Server side prepared statements leads to potential off-by-second timestamp on slaves

Bug #1381966 reported by Jacques Grove on 2014-10-16
14
This bug affects 3 people
Affects Status Importance Assigned to Milestone
MySQL Server
Unknown
Unknown
Percona Server moved to https://jira.percona.com/projects/PS
Status tracked in 5.7
5.5
Invalid
Undecided
Unassigned
5.6
Triaged
Medium
Unassigned
5.7
Triaged
Medium
Unassigned
8.0
Fix Committed
Medium
Unassigned

Bug Description

I have Percona Server 5.6.21 installed on RHEL6, the following packages:

Percona-Server-client-56-5.6.21-rel69.0.el6.x86_64
Percona-Server-server-56-5.6.21-rel69.0.el6.x86_64
Percona-Server-shared-56-5.6.21-rel69.0.el6.x86_64

I have the following table:

> show create table test.t1\G
*************************** 1. row ***************************
       Table: t1
Create Table: CREATE TABLE `t1` (
  `created_time` timestamp NULL DEFAULT NULL
) ENGINE=InnoDB DEFAULT CHARSET=utf8

Testcase:

 > truncate test.t1;
Query OK, 0 rows affected (0.02 sec)

Run the following code using mysql-connector-java 5.1.32 from MySQL. Note the use of server-side prepared statements:

import java.sql.Connection;
import java.sql.Timestamp;
import java.sql.DriverManager;
import java.sql.PreparedStatement;

class Test {
   public static void main(String[] args) {
        Connection conn;
        try {
            Class.forName("com.mysql.jdbc.Driver").newInstance();
            String url = "jdbc:mysql://127.0.0.1:3306/test?useServerPrepStmts=true";
            conn = DriverManager.getConnection(url, "test", "test");
            PreparedStatement stmt = conn.prepareStatement("INSERT INTO t1 (created_time) values (?)");
            stmt.setTimestamp(1, new Timestamp(1300883333501L));
            stmt.execute();
        } catch (Exception e) {
            System.out.println("Exception: "+e);
            e.printStackTrace();
        }
    }
}

Note the result in the table:

> select * from test.t1\G
*************************** 1. row ***************************
created_time: 2011-03-23 12:28:54

Now, run the same code, but without server-side prepared statements in the driver options:

import java.sql.Connection;
import java.sql.Timestamp;
import java.sql.DriverManager;
import java.sql.PreparedStatement;

class Test {
   public static void main(String[] args) {
        Connection conn;
        try {
            Class.forName("com.mysql.jdbc.Driver").newInstance();
            String url = "jdbc:mysql://127.0.0.1:3306/test";
            conn = DriverManager.getConnection(url, "test", "test");
            PreparedStatement stmt = conn.prepareStatement("INSERT INTO t1 (created_time) values (?)");
            stmt.setTimestamp(1, new Timestamp(1300883333501L));
            stmt.execute();
        } catch (Exception e) {
            System.out.println("Exception: "+e);
            e.printStackTrace();
        }
    }
}

Inspect the database again; result is as expected:

> select * from test.t1\G
*************************** 1. row ***************************
created_time: 2011-03-23 12:28:54
*************************** 2. row ***************************
created_time: 2011-03-23 12:28:54

However, now examine the binary/replication log on the server (binlog_format=STATEMENT):

#141016 9:16:23 server id 9993 end_log_pos 7065 CRC32 0x08aa0438 Query thread_id=81 exec_time=0 error_code=0
SET TIMESTAMP=1413450983/*!*/;
INSERT INTO t1 (created_time) values ('2011-03-23 12:28:53')
/*!*/;
# at 7065
#141016 9:16:23 server id 9993 end_log_pos 7096 CRC32 0x11ceda38 Xid = 1268
COMMIT/*!*/;
# at 7096
#141016 9:18:13 server id 9993 end_log_pos 7183 CRC32 0xad39e8c8 Query thread_id=83 exec_time=0 error_code=0
SET TIMESTAMP=1413451093/*!*/;
BEGIN
/*!*/;
# at 7183
#141016 9:18:13 server id 9993 end_log_pos 7329 CRC32 0x039bbb0b Query thread_id=83 exec_time=0 error_code=0
SET TIMESTAMP=1413451093/*!*/;
INSERT INTO t1 (created_time) values ('2011-03-23 12:28:53.501')
/*!*/;
# at 7329
#141016 9:18:13 server id 9993 end_log_pos 7360 CRC32 0x6c565aeb Xid = 1282
COMMIT/*!*/;

Note that the for the first test, while using server-side prepared statements, the fractional part of the timestamp was dropped before getting to the binary log. When not using server-side prepared statements (2nd test), the fractional part of the timestamp is preserved into the binary log. From the timestamps in the table, you can see the problem. With server-side prepared statements the master will end up with the correctly rounded timestamp ('2011-03-23 12:28:54'), but any slave will end up with the truncated timestamp, which in this case is 1 second behind ('2011-03-23 12:28:53').

The workaround of not using server-side prepared statements is not an option. In our case we have alleviated the issue by rounding the timestamp in the code to the nearest second, but this should really "just work".

I have not looked deeper into whether this is a JDBC driver or a server issue.

Jacques Grove (aquarapid) wrote :

Verified that this also happens with the newest mysql-connector-java (5.1.33)

summary: - Server side prepared statements leads to timestamp precision loss on
- slaves
+ Server side prepared statements leads to potential off-by-second
+ timestamp on slaves
Changed in percona-server:
assignee: nobody → Muhammad Irfan (muhammad-irfan)
Muhammad Irfan (muhammad-irfan) wrote :
Download full text (3.8 KiB)

I am able to reproduce this problem. Below is complete test case.

MASTER:
CentOS release 6.5 (Final)

Percona-Server-client-56-5.6.21-rel69.0.el6.x86_64
Percona-Server-server-56-5.6.21-rel69.0.el6.x86_64
Percona-Server-shared-56-5.6.21-rel69.0.el6.x86_64

mysql-connector-java-5.1.33

+------------------+--------+
| Variable_name | Value |
+------------------+--------+
| system_time_zone | UTC |
| time_zone | SYSTEM |
+------------------+--------+
mysql> SELECT NOW();
+---------------------+
| NOW() |
+---------------------+
| 2014-10-24 10:38:51 |
+---------------------+
1 row in set (0.00 sec)

SLAVE:
CentOS release 6.5 (Final)

Percona-Server-client-56-5.6.21-rel69.0.el6.x86_64
Percona-Server-server-56-5.6.21-rel69.0.el6.x86_64
Percona-Server-shared-56-5.6.21-rel69.0.el6.x86_64

+------------------+--------+
| Variable_name | Value |
+------------------+--------+
| system_time_zone | UTC |
| time_zone | SYSTEM |
+------------------+--------+

mysql> SELECT NOW();
+---------------------+
| NOW() |
+---------------------+
| 2014-10-24 10:38:58 |
+---------------------+
1 row in set (0.00 sec)

Test1: Prepared Statements:
======================

MASTER:
mysql> SELECT * FROM t1;
+---------------------+
| created_time |
+---------------------+
| 2011-03-23 12:28:54 |
+---------------------+
1 row in set (0.00 sec)

# at 207
#141024 10:29:22 server id 1 end_log_pos 349 CRC32 0xf7ff4942 Query thread_id=38 exec_time=0 error_code=0
use `test`/*!*/;
SET TIMESTAMP=1414146562/*!*/;
INSERT INTO t1 (created_time) values ('2011-03-23 12:28:53')
/*!*/;
# at 349
#141024 10:29:22 server id 1 end_log_pos 380 CRC32 0xcae46060 Xid = 255
COMMIT/*!*/;

SLAVE:
mysql> SELECT * FROM t1;
+---------------------+
| created_time |
+---------------------+
| 2011-03-23 12:28:53 |
+---------------------+
1 row in set (0.00 sec)

# at 207
#141024 10:29:22 server id 1 end_log_pos 349 CRC32 0xf7ff4942 Query thread_id=38 exec_time=0 error_code=0
use `test`/*!*/;
SET TIMESTAMP=1414146562/*!*/;
INSERT INTO t1 (created_time) values ('2011-03-23 12:28:53')
/*!*/;
# at 349
#141024 10:29:22 server id 1 end_log_pos 380 CRC32 0xfbac923d Xid = 82
COMMIT/*!*/;

Test2, Without Prepared Statements:
=============================
MASTER:
mysql> SELECT * FROM t1;
+---------------------+
| created_time |
+---------------------+
| 2011-03-23 12:28:54 |
| 2011-03-23 12:28:54 |
+---------------------+
2 rows in set (0.00 sec)

# at 380
#141024 10:31:32 server id 1 end_log_pos 467 CRC32 0x24840528 Query thread_id=40 exec_time=0 error_code=0
SET TIMESTAMP=1414146692/*!*/;
BEGIN
/*!*/;
# at 467
#141024 10:31:32 server id 1 end_log_pos 613 CRC32 0xa37c7990 Query thread_id=40 exec_time=0 error_code=0
SET TIMESTAMP=1414146692/*!*/;
INSERT INTO t1 (created_time) values ('2011-03-23 12:28:53.501')
/*!*/;
# at 613
#141024 10:31:32 server id 1 end_log_pos 644 CRC32 0x143d5b10 Xid = 269
COMMIT/*!*/;

SLAVE:
mysql> SELECT * FROM t1;
+---------------------+
| created_time |
+---------------------+
| 2011-03-23 12:28:53 |
| 2011-03-23 12:28:54 |
+---------------------+
2 row...

Read more...

Muhammad Irfan (muhammad-irfan) wrote :

This occurs with binlog_format STATEMENT while works correctly when using binlog format ROW

Changed in percona-server:
status: New → Confirmed
assignee: Muhammad Irfan (muhammad-irfan) → nobody
tags: added: upstream
Muhammad Irfan (muhammad-irfan) wrote :

I was not able to reproduce the same on PS 5.5.

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-1549

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.