| 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: | |
| Category: | MySQL Server: Prepared statements | Severity: | S2 (Serious) |
| Version: | 5.6.21 | OS: | Linux |
| Assigned to: | CPU Architecture: | Any | |
[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.
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