| Bug #70813 | No fractional seconds in the insert statement in binary log | ||
|---|---|---|---|
| Submitted: | 4 Nov 2013 20:15 | Modified: | 26 Nov 2013 18:07 |
| Reporter: | Roy Chen | Email Updates: | |
| Status: | Not a Bug | Impact on me: | |
| Category: | MySQL Server | Severity: | S3 (Non-critical) |
| Version: | 5.6.10 | OS: | Linux (Centos 6.4) |
| Assigned to: | CPU Architecture: | Any | |
| Tags: | binary log, jdbc connector, replication | ||
[14 Nov 2013 19:03]
Sveta Smirnova
Thank you for the report. But version 5.6.10 is old. Please try with current version 5.6.14 and if issue still exists, do following test: 1. Turn general log ON 2. Run problematic query 3. Send us general query log content. I want to check if this is server or application issue.
[21 Nov 2013 19:30]
Roy Chen
Hi,
I updated mysql to 5.6.14. It still doesn't work.
Here is a chunk from general log:
131121 10:53:58 10 Prepare INSERT INTO im_statitem (time, nodeid, statid, subkeyid, value) VALUES (?, ?, ?, ?, ?)
10 Prepare UPDATE im_lateststatitem SET time = (?), value = ?, inserttime = now() WHERE nodeid = ? AND statid = ? AND subkeyid = ?
10 Prepare DELETE FROM im_lateststatitem WHERE nodeid = ? AND statid = ? AND subkeyid = ? LIMIT ?
10 Prepare INSERT INTO im_lateststatitem (time, nodeid, statid, subkeyid, value, inserttime) VALUES (?, ?, ?, ?, ?, now())
10 Query select @@session.tx_read_only
10 Execute UPDATE im_lateststatitem SET time = ('2013-11-21 10:53:58'), value = 0.307, inserttime = now() WHERE nodeid = 0 AND statid = 2 AND subkeyid = 1
10 Query select @@session.tx_read_only
10 Execute INSERT INTO im_statitem (time, nodeid, statid, subkeyid, value) VALUES ('2013-11-21 10:53:58', 0, 2, 1, 0.307)
10 Query select @@session.tx_read_only
10 Execute UPDATE im_lateststatitem SET time = ('2013-11-21 10:53:58'), value = 242, inserttime = now() WHERE nodeid = 0 AND statid = 2 AND subkeyid = 2
10 Query select @@session.tx_read_only
10 Execute INSERT INTO im_statitem (time, nodeid, statid, subkeyid, value) VALUES ('2013-11-21 10:53:58', 0, 2, 2, 242)
10 Query select @@session.tx_read_only
10 Execute UPDATE im_lateststatitem SET time = ('2013-11-21 10:53:58'), value = 0.2, inserttime = now() WHERE nodeid = 0 AND statid = 2 AND subkeyid = 3
10 Query select @@session.tx_read_only
10 Execute INSERT INTO im_statitem (time, nodeid, statid, subkeyid, value) VALUES ('2013-11-21 10:53:58', 0, 2, 3, 0.2)
10 Query select @@session.tx_read_only
10 Execute UPDATE im_lateststatitem SET time = ('2013-11-21 10:53:58'), value = 0, inserttime = now() WHERE nodeid = 0 AND statid = 2 AND subkeyid = 4
10 Query select @@session.tx_read_only
10 Execute UPDATE im_lateststatitem SET time = ('2013-11-21 10:53:58'), value = 0, inserttime = now() WHERE nodeid = 0 AND statid = 2 AND subkeyid = 5
10 Query select @@session.tx_read_only
10 Execute UPDATE im_lateststatitem SET time = ('2013-11-21 10:53:58'), value = 0, inserttime = now() WHERE nodeid = 0 AND statid = 2 AND subkeyid = 6
10 Query select @@session.tx_read_only
10 Execute UPDATE im_lateststatitem SET time = ('2013-11-21 10:53:58'), value = 0, inserttime = now() WHERE nodeid = 0 AND statid = 2 AND subkeyid = 7
10 Query select @@session.tx_read_only
10 Execute UPDATE im_lateststatitem SET time = ('2013-11-21 10:53:58'), value = 35, inserttime = now() WHERE nodeid = 0 AND statid = 2 AND subkeyid = 8
10 Query select @@session.tx_read_only
10 Execute INSERT INTO im_statitem (time, nodeid, statid, subkeyid, value) VALUES ('2013-11-21 10:53:58', 0, 2, 8, 35)
10 Query select @@session.tx_read_only
10 Execute UPDATE im_lateststatitem SET time = ('2013-11-21 10:53:58'), value = 0.009, inserttime = now() WHERE nodeid = 0 AND statid = 2 AND subkeyid = 9
10 Query select @@session.tx_read_only
10 Execute INSERT INTO im_statitem (time, nodeid, statid, subkeyid, value) VALUES ('2013-11-21 10:53:58', 0, 2, 9, 0.009)
10 Close stmt
10 Close stmt
10 Close stmt
10 Close stmt
Here is the chunk from binary log output:
# at 193905
#131121 10:53:57 server id 1 end_log_pos 194001 CRC32 0xaf5003aa Query thread_id=10 exec_time=0 error_code=0
SET TIMESTAMP=1385060037/*!*/;
COMMIT
/*!*/;
# at 194096
#131121 10:53:58 server id 1 end_log_pos 194329 CRC32 0x93a7eac7 Query thread_id=10 exec_time=0 error_code=0
SET TIMESTAMP=1385060038/*!*/;
UPDATE im_lateststatitem SET time = ('2013-11-21 10:53:58'), value = 0.307, inserttime = now() WHERE nodeid = 0 AND statid = 2 AND subkeyid = 1
/*!*/;
# at 194512
#131121 10:53:58 server id 1 end_log_pos 194704 CRC32 0x5bed11b3 Query thread_id=10 exec_time=0 error_code=0
SET TIMESTAMP=1385060038/*!*/;
INSERT INTO im_statitem (time, nodeid, statid, subkeyid, value) VALUES ('2013-11-21 10:53:58', 0, 2, 1, 0.307)
/*!*/;
# at 194704
#131121 10:53:58 server id 1 end_log_pos 194792 CRC32 0xc82c0331 Query thread_id=10 exec_time=0 error_code=0
SET TIMESTAMP=1385060038/*!*/;
COMMIT
/*!*/;
# at 194792
#131121 10:53:58 server id 1 end_log_pos 194887 CRC32 0x375fecbf Query thread_id=10 exec_time=0 error_code=0
SET TIMESTAMP=1385060038/*!*/;
BEGIN
/*!*/;
# at 194887
#131121 10:53:58 server id 1 end_log_pos 195118 CRC32 0x38dc9bbc Query thread_id=10 exec_time=0 error_code=0
SET TIMESTAMP=1385060038/*!*/;
UPDATE im_lateststatitem SET time = ('2013-11-21 10:53:58'), value = 242, inserttime = now() WHERE nodeid = 0 AND statid = 2 AND subkeyid = 2
/*!*/;
# at 195214
#131121 10:53:58 server id 1 end_log_pos 195301 CRC32 0xefeb8adf Query thread_id=10 exec_time=0 error_code=0
SET TIMESTAMP=1385060038/*!*/;
BEGIN
/*!*/;
# at 195301
#131121 10:53:58 server id 1 end_log_pos 195491 CRC32 0xd714a16d Query thread_id=10 exec_time=0 error_code=0
SET TIMESTAMP=1385060038/*!*/;
INSERT INTO im_statitem (time, nodeid, statid, subkeyid, value) VALUES ('2013-11-21 10:53:58', 0, 2, 2, 242)
/*!*/;
# at 195674
#131121 10:53:58 server id 1 end_log_pos 195905 CRC32 0x894a34d4 Query thread_id=10 exec_time=0 error_code=0
SET TIMESTAMP=1385060038/*!*/;
UPDATE im_lateststatitem SET time = ('2013-11-21 10:53:58'), value = 0.2, inserttime = now() WHERE nodeid = 0 AND statid = 2 AND subkeyid = 3
/*!*/;
# at 196088
#131121 10:53:58 server id 1 end_log_pos 196278 CRC32 0xcd9486d9 Query thread_id=10 exec_time=0 error_code=0
SET TIMESTAMP=1385060038/*!*/;
INSERT INTO im_statitem (time, nodeid, statid, subkeyid, value) VALUES ('2013-11-21 10:53:58', 0, 2, 3, 0.2)
/*!*/;
If I do a query on the MySQL database table, I get:
mysql> select * from im_statitem where time>"2013-11-21 10:53:58" and time <="2013-11-21 10:53:59";
+----------------------------+--------+--------+----------+-------+
| time | nodeid | statid | subkeyid | value |
+----------------------------+--------+--------+----------+-------+
| 2013-11-21 10:53:58.497000 | 0 | 2 | 1 | 0.307 |
| 2013-11-21 10:53:58.497000 | 0 | 2 | 2 | 242 |
| 2013-11-21 10:53:58.497000 | 0 | 2 | 3 | 0.2 |
| 2013-11-21 10:53:58.497000 | 0 | 2 | 8 | 35 |
| 2013-11-21 10:53:58.497000 | 0 | 2 | 9 | 0.009 |
+----------------------------+--------+--------+----------+-------+
5 rows in set (0.00 sec)
[21 Nov 2013 19:37]
Sveta Smirnova
Thank you for the feedback.
Please look into your general query log:
INSERT INTO im_statitem (time, nodeid, statid, subkeyid, value) VALUES ('2013-11-21 10:53:58', 0, 2, 2, 242)
UPDATE im_lateststatitem SET time = ('2013-11-21 10:53:58'), value = 0.2, inserttime = now() WHERE nodeid = 0 AND statid = 2 AND subkeyid = 3
Queries have no fractional seconds. Binary log also uses statement format:
INSERT INTO im_statitem (time, nodeid, statid, subkeyid, value) VALUES ('2013-11-21 10:53:58', 0, 2, 2, 242)
UPDATE im_lateststatitem SET time = ('2013-11-21 10:53:58'), value = 0.2, inserttime = now() WHERE nodeid = 0 AND statid = 2 AND subkeyid = 3
Queries are identical to those which are in general query log. I don't see bug here.
If you need your slave to be 100% same as master consider switching to row-based replication format.
[21 Nov 2013 22:05]
Roy Chen
But why the database table has microseconds values in it?
[21 Nov 2013 22:34]
Roy Chen
My point is, the application call statement.executeUpdate API. It is able to insert a row with fractional seconds in the time column. Why the general log / binary log cannot show the same value with the same precision? I still think this is a bug.
[25 Nov 2013 23:42]
Roy Chen
Re-open the bug because of my last comment
[26 Nov 2013 18:07]
Sveta Smirnova
Thank you for the feedback.
> But why the database table has microseconds values in it?
Because you specified default value for the time column as "0000-00-00 00:00:00.000000"
See:
mysql> INSERT INTO item (time, nid, sid, subid, value) VALUES ('2013-11-21 10:53:58', 0, 2, 2, 242);
Query OK, 1 row affected (0.01 sec)
mysql> select * from item;
+----------------------------+-----+-----+-------+-------+
| time | nid | sid | subid | value |
+----------------------------+-----+-----+-------+-------+
| 2013-11-21 10:53:58.000000 | 0 | 2 | 2 | 242 |
+----------------------------+-----+-----+-------+-------+
1 row in set (0.00 sec)
mysql> show binlog events;
+-------------------+-----+-------------+-----------+-------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Log_name | Pos | Event_type | Server_id | End_log_pos | Info |
+-------------------+-----+-------------+-----------+-------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| master-bin.000001 | 4 | Format_desc | 1 | 120 | Server ver: 5.6.16-log, Binlog ver: 4 |
| master-bin.000001 | 120 | Query | 1 | 473 | use `test`; CREATE TABLE `item`( `time` datetime(6) NOT NULL DEFAULT '0000-00-00 00:00:00.000000', `nid` mediumint(9) NOT NULL DEFAULT 0, `sid` mediumint(9) NOT NULL DEFAULT 0, `subid` mediumint(9) NOT NULL DEFAULT 0, `value` double NOT NULL DEFAULT 0, KEY(`time`), KEY(`nid`), KEY(`sid`) ) |
...
And binlog events for the query which specifies fractional seconds:
mysql> INSERT INTO item (time, nid, sid, subid, value) VALUES ('2013-11-21 10:53:58.000497', 0, 2, 2, 242);
Query OK, 1 row affected (0.01 sec)
mysql> show binlog events;
+-------------------+------+-------------+-----------+-------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Log_name | Pos | Event_type | Server_id | End_log_pos | Info |
+-------------------+------+-------------+-----------+-------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
...
| master-bin.000001 | 798 | Query | 1 | 877 | BEGIN |
| master-bin.000001 | 877 | Query | 1 | 1050 | use `test`; INSERT INTO item (time, nid, sid, subid, value) VALUES ('2013-11-21 10:53:58.000497', 0, 2, 2, 242)
As you see binary log works fine and this is not a bug.
> [21 Nov 22:34] Roy Chen
>
> My point is, the application call statement.executeUpdate API. It is able to > insert a row with fractional seconds in the time column. Why the general log > / binary log cannot show the same value with the same precision? I still
> think this is a bug.
If general query log does not contain a query which specifies fractional seconds, it was added by default. You can have inserted fractional seconds in the binary log, however: simply use binary log format row.
[26 Nov 2013 18:11]
Sveta Smirnova
Ups, example of binary log without fractional seconds:
|
| master-bin.000001 | 552 | Query | 1 | 718 | use `test`; INSERT INTO item (time, nid, sid, subid, value) VALUES ('2013-11-21 10:53:58', 0, 2, 2, 242)
(And with fractional:
| master-bin.000001 | 877 | Query | 1 | 1050 | use `test`; INSERT INTO item (time, nid, sid, subid, value) VALUES ('2013-11-21 10:53:58.000497', 0, 2, 2, 242)
)
Description: Hi, I was trying to synchronize two database manually. The source database is on MySQL, version 5.6.10. The table schema looks like this: mysql> describe item; +----------+--------------+------+-----+----------------------------+-------+ | Field | Type | Null | Key | Default | Extra | +----------+--------------+------+-----+----------------------------+-------+ | time | datetime(6) | NO | MUL | 0000-00-00 00:00:00.000000 | | | nid | mediumint(9) | NO | MUL | 0 | | | sid | mediumint(9) | NO | MUL | 0 | | | subid | mediumint(9) | NO | | 0 | | | value | double | NO | | 0 | | +----------+--------------+------+-----+----------------------------+-------+ 5 rows in set (0.01 sec) The data of the table was inserted using Java. The code looks like this: PreparedStatement insertStmt = conn.prepareStatement("INSERT INTO item (time, nid, sid, subid, value) VALUES (?, ?, ?, ?, ?)"); insertStmt.setTimestamp(1, new Timestamp(Math.min(now, object.getTimestamp()))); insertStmt.setInt(2, si.getNId()); insertStmt.setInt(3, si.getSId()); insertStmt.setInt(4, si.getSubId()); insertStmt.setDouble(5, object.getValue().doubleValue()); insertStmt.executeUpdate(); insertStmt.close(); In order to manually sync two database, I turned on the binary log on the source database. The binary log is set to Statement format. I extract the binary log using the "mysqlbinlog" command. When I read the binary log, I got the following insert statement: INSERT INTO item (time, nid, sid, subid, value) VALUES ('2013-10-31 16:57:39', 0, 2, 1, 0.108) But if I query the source database table, I get: mysql> select * from item where time > '2013-10-31 16:57:39' and time < '2013-10-31 16:57:40'; +----------------------------+--------+--------+----------+-------+ | time | nid | sid | subid | value | +----------------------------+--------+--------+----------+-------+ | 2013-10-31 16:57:39.035000 | 0 | 2 | 1 | 0.108 | +----------------------------+--------+--------+----------+-------+ 1 row in set (0.01 sec) So the problem here is, from the binary log, I lost fractional seconds in the time column. I wonder is there any way I can get fractional seconds in the binary log? Thank you in advance for your help. How to repeat: prepare a MySQL table with one column of type datetime. Enable binary log in Statement format Using java to insert an statement: PreparedStatement stmt = conn.prepareStatement("....."); stmt.setTimestamp(1, new Timestamp(<now>)); stmt.executeUpdate. In the database table, you should see the timestamp with fractional seconds. And in the binary log, the insert statement should have fractional seconds as well.