Bug #74550 Server side prepared statements leads to potential off-by-second timestamp on sl
Submitted: 24 Oct 2014 13:30 Modified: 14 Apr 2015 16:52
Reporter: Muhammad Irfan Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Prepared statements Severity:S2 (Serious)
Version:5.6.21 OS:Linux
Assigned to: CPU Architecture:Any

[24 Oct 2014 13:30] Muhammad Irfan
Description:
When using server-side prepared statements (Test 1), the fractional part of the timestamp was dropped before getting to the binary log. When not using server-side prepared statements (Test 2), 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').

How to repeat:
MASTER:
CentOS release 6.5 (Final)

mysql-community-libs-5.6.21-2.el6.x86_64
mysql-community-common-5.6.21-2.el6.x86_64
mysql-community-client-5.6.21-2.el6.x86_64
mysql-community-server-5.6.21-2.el6.x86_64

mysql> SHOW GLOBAL VARIABLES LIKE '%version%';
+-------------------------+------------------------------+
| Variable_name           | Value                        |
+-------------------------+------------------------------+
| innodb_version          | 5.6.21                       |
| protocol_version        | 10                           |
| slave_type_conversions  |                              |
| version                 | 5.6.21-log                   |
| version_comment         | MySQL Community Server (GPL) |
| version_compile_machine | x86_64                       |
| version_compile_os      | Linux                        |
+-------------------------+------------------------------+

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

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

mysql> SHOW GLOBAL VARIABLES LIKE 'binlog_format';
+---------------+-----------+
| Variable_name | Value     |
+---------------+-----------+
| binlog_format | STATEMENT |
+---------------+-----------+

mysql-connector-java-5.1.33

SLAVE:
CentOS release 6.5 (Final)

mysql-community-libs-5.6.21-2.el6.x86_64
mysql-community-libs-compat-5.6.21-2.el6.x86_64
mysql-community-server-5.6.21-2.el6.x86_64
mysql-community-common-5.6.21-2.el6.x86_64
mysql-community-client-5.6.21-2.el6.x86_64

mysql> SHOW GLOBAL VARIABLES LIKE '%version%';
+-------------------------+------------------------------+
| Variable_name           | Value                        |
+-------------------------+------------------------------+
| innodb_version          | 5.6.21                       |
| protocol_version        | 10                           |
| slave_type_conversions  |                              |
| version                 | 5.6.21-log                   |
| version_comment         | MySQL Community Server (GPL) |
| version_compile_machine | x86_64                       |
| version_compile_os      | Linux                        |
+-------------------------+------------------------------+

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

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

mysql> SHOW GLOBAL VARIABLES LIKE 'binlog_format';
+---------------+-----------+
| Variable_name | Value     |
+---------------+-----------+
| binlog_format | STATEMENT |
+---------------+-----------+

Test1, With Prepared Statements:
=================================

Run the following code using mysql-connector-java 5.1.32 or mysql-connector-java 5.1.33 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:

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

BEGIN
/*!*/;
# at 207
#141024 12:08:22 server id 1  end_log_pos 349 CRC32 0xe102ace4  Query   thread_id=5     exec_time=0     error_code=0
use `test`/*!*/;
SET TIMESTAMP=1414152502/*!*/;
INSERT INTO t1 (created_time) values ('2011-03-23 12:28:53')
/*!*/;
# at 349
#141024 12:08:22 server id 1  end_log_pos 380 CRC32 0xa2d3ca97  Xid = 27
COMMIT/*!*/;

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

BEGIN
/*!*/;
# at 476
#141024 12:08:22 server id 1  end_log_pos 618 CRC32 0xffe0caa9  Query   thread_id=5     exec_time=0     error_code=0
SET TIMESTAMP=1414152502/*!*/;
INSERT INTO t1 (created_time) values ('2011-03-23 12:28:53')
/*!*/;
# at 618
#141024 12:08:22 server id 1  end_log_pos 649 CRC32 0x7daecef7  Xid = 44
COMMIT/*!*/;

Test2, Witout Prepared Statements:
===================================

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:

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 12:11:43 server id 1  end_log_pos 467 CRC32 0x6ebb5e92  Query   thread_id=10    exec_time=0     error_code=0
SET TIMESTAMP=1414152703/*!*/;
BEGIN
/*!*/;
# at 467
#141024 12:11:43 server id 1  end_log_pos 613 CRC32 0x15d83262  Query   thread_id=10    exec_time=0     error_code=0
SET TIMESTAMP=1414152703/*!*/;
INSERT INTO t1 (created_time) values ('2011-03-23 12:28:53.501')
/*!*/;
# at 613
#141024 12:11:43 server id 1  end_log_pos 644 CRC32 0x4c4b2125  Xid = 74
COMMIT/*!*/;

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

# at 649
#141024 12:11:43 server id 1  end_log_pos 736 CRC32 0x40432d32  Query   thread_id=10    exec_time=0     error_code=0
SET TIMESTAMP=1414152703/*!*/;
BEGIN
/*!*/;
# at 736
#141024 12:11:43 server id 1  end_log_pos 882 CRC32 0x8a89dc85  Query   thread_id=10    exec_time=0     error_code=0
SET TIMESTAMP=1414152703/*!*/;
INSERT INTO t1 (created_time) values ('2011-03-23 12:28:53.501')
/*!*/;
# at 882
#141024 12:11:43 server id 1  end_log_pos 913 CRC32 0xdf9c3b31  Xid = 58
COMMIT/*!*/;

NOTE: This works correctly when setting binlog_format = ROW but not with binlog_format = STATEMENT
[27 Oct 2014 7:21] MySQL Verification Team
Hello Muhammad Irfan,

Thank you for the bug report and test case.

Thanks,
Umesh
[27 Oct 2014 7:22] MySQL Verification Team
// 5.6.21

//Master

mysql> create table t1(created_time datetime);
Query OK, 0 rows affected (0.03 sec)

mysql> show create table t1\G
*************************** 1. row ***************************
       Table: t1
Create Table: CREATE TABLE `t1` (
  `created_time` datetime DEFAULT NULL
) ENGINE=InnoDB DEFAULT CHARSET=latin1
1 row in set (0.00 sec)

[ushastry@common]~/bugs/mysql-5.6.21: vi Test.java
[ushastry@common]~/bugs/mysql-5.6.21: javac Test.java
[ushastry@common]~/bugs/mysql-5.6.21: java -classpath '.:/home/umshastr/bugs/mysql-connector-java-5.1.33/mysql-connector-java-5.1.33-bin.jar' Test

mysql> select * from t1;
+---------------------+
| created_time        |
+---------------------+
| 2011-03-23 13:28:54 |
+---------------------+
1 row in set (0.00 sec)

# at 925
#141025 15:35:25 server id 1  end_log_pos 1004 CRC32 0xdf29ac2f         Query   thread_id=10    exec_time=0     error_code=0
SET TIMESTAMP=1414244125/*!*/;
SET @@session.sql_mode=1075838976/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
BEGIN
/*!*/;
# at 1004
#141025 15:35:25 server id 1  end_log_pos 1138 CRC32 0x0dd172e4         Query   thread_id=10    exec_time=0     error_code=0
SET TIMESTAMP=1414244125/*!*/;
INSERT INTO t1 (created_time) values ('2011-03-23 13:28:53')
/*!*/;
# at 1138
#141025 15:35:25 server id 1  end_log_pos 1169 CRC32 0x2bbbe15a         Xid = 54
COMMIT/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

// Slave

mysql> select * from t1;
+---------------------+
| created_time        |
+---------------------+
| 2011-03-23 13:28:53 |
+---------------------+
1 row in set (0.00 sec)

# at 396
#141025 15:35:25 server id 1  end_log_pos 1004 CRC32 0xdf29ac2f         Query   thread_id=10    exec_time=0     error_code=0
SET TIMESTAMP=1414244125/*!*/;
SET @@session.sql_mode=1075838976/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
BEGIN
/*!*/;
# at 475
#141025 15:35:25 server id 1  end_log_pos 1138 CRC32 0x0dd172e4         Query   thread_id=10    exec_time=0     error_code=0
SET TIMESTAMP=1414244125/*!*/;
INSERT INTO t1 (created_time) values ('2011-03-23 13:28:53')
/*!*/;
# at 609
#141025 15:35:25 server id 1  end_log_pos 1169 CRC32 0x2bbbe15a         Xid = 54
COMMIT/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

// Witout Prepared Statements:

/ Master

mysql> select * from t1;
+---------------------+
| created_time        |
+---------------------+
| 2011-03-23 13:28:54 |
| 2011-03-23 13:28:54 |
+---------------------+
2 rows in set (0.00 sec)

# at 1169
#141025 15:45:30 server id 1  end_log_pos 1248 CRC32 0x6fb46400         Query   thread_id=11    exec_time=0     error_code=0
SET TIMESTAMP=1414244730/*!*/;
BEGIN
/*!*/;
# at 1248
#141025 15:45:30 server id 1  end_log_pos 1386 CRC32 0x27d413ce         Query   thread_id=11    exec_time=0     error_code=0
SET TIMESTAMP=1414244730/*!*/;
INSERT INTO t1 (created_time) values ('2011-03-23 13:28:53.501')
/*!*/;
# at 1386
#141025 15:45:30 server id 1  end_log_pos 1417 CRC32 0x6f91c9a6         Xid = 64
COMMIT/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

/ Slave

mysql> select * from t1;
+---------------------+
| created_time        |
+---------------------+
| 2011-03-23 13:28:53 |
| 2011-03-23 13:28:54 |
+---------------------+
2 rows in set (0.01 sec)

# at 640
#141025 15:45:30 server id 1  end_log_pos 1248 CRC32 0x6fb46400         Query   thread_id=11    exec_time=0     error_code=0
SET TIMESTAMP=1414244730/*!*/;
BEGIN
/*!*/;
# at 719
#141025 15:45:30 server id 1  end_log_pos 1386 CRC32 0x27d413ce         Query   thread_id=11    exec_time=0     error_code=0
SET TIMESTAMP=1414244730/*!*/;
INSERT INTO t1 (created_time) values ('2011-03-23 13:28:53.501')
/*!*/;
# at 857
#141025 15:45:30 server id 1  end_log_pos 1417 CRC32 0x6f91c9a6         Xid = 64
COMMIT/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
[27 Oct 2014 7:28] MySQL Verification Team
Also, see http://bugs.mysql.com/bug.php?id=68760
[14 Apr 2015 16:52] Paul DuBois
Noted in 5.8.0 changelog.

imestamps for server-side prepared statements could be written to
the binary log up to a second behind timestamps for the corresponding
nonprepared statements.
[24 Aug 2017 13:14] Andrey Tarashevskiy
Any possibilities that this issue might be fixed in 5.6 branch?
We experience inconvenience from that bug, because we are trying to use our db slave instance as a read-only data provider, but we can not do that due to that bug.

We can see that master log to binary log timestamps with fractional part, but not all the time, about 30% or statements logged with fractional part.
[2 Oct 2018 7:41] MySQL Verification Team
BUG 25187670 - BACKPORT BUG#19894382 TO 5.6 AND 5.7

Noted in 5.6.36, 5.7.18 changelogs.

Timestamps for server-side prepared statements could be written to
the binary log up to a second behind timestamps for the corresponding
nonprepared statements, leading to time value differences between
master and slave servers.