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

[Jacques Grove]

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)]

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

[Muhammad Irfan (muhammad-irfan)]

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...

[Muhammad Irfan (muhammad-irfan)]

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

[Muhammad Irfan (muhammad-irfan)]

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

[Shahriyar Rzayev (rzayev-sehriyar)]

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