| Bug #102971 | slave-db losts original commit time of master_db | ||
|---|---|---|---|
| Submitted: | 15 Mar 2021 7:06 | Modified: | 20 Apr 2021 10:04 |
| Reporter: | Brian Yue (OCA) | Email Updates: | |
| Status: | Verified | Impact on me: | |
| Category: | MySQL Server: Replication | Severity: | S3 (Non-critical) |
| Version: | MySQL8.0.22, 8.0.23 | OS: | Any (rhel-7.4) |
| Assigned to: | CPU Architecture: | Any (intel x86-64) | |
[1 Apr 2021 7:34]
MySQL Verification Team
Hello Brian Yue, Thank you for the report and feedback. Are there time difference in source and replica instances? I tried to follow your steps but not seeing any difference as reported. Please let me know, lso could you please share configuration file from both source and replica(if not on default)? Thank you. regards, Umesh
[1 Apr 2021 14:02]
Brian Yue
Hello Umesh, Here is some related configurations of mysqld, I wish it's helpful: [general] instance_num=1 [mysqld] # generic configuration options sql_mode = STRICT_TRANS_TABLES sync_binlog=1 binlog_expire_logs_seconds=259200 open_files_limit = 65535 transaction-isolation = REPEATABLE-READ lower_case_table_names = 1 performance_schema = ON max_binlog_size = 10485760 binlog_format=ROW slave_parallel_workers = 32 slave-parallel-type = LOGICAL_CLOCK slave_preserve_commit_order = 1 relay_log_recovery = 0 mysqlx=0 default_authentication_plugin=mysql_native_password log-bin=../binlog/mysql-bin relay-log=../relaylog/relay-bin secure-file-priv= gtid_mode = on enforce_gtid_consistency=on default-time-zone='+8:00' log_timestamps=SYSTEM master-info-repository=TABLE relay-log-info-repository=TABLE character_set_server = utf8mb4 collation_server = utf8mb4_bin
[20 Apr 2021 10:04]
MySQL Verification Team
Observed this finally. Thank you! regards, Umesh
[6 Jun 2022 8:44]
Sven Sandberg
Posted by developer: If I understand right, the problem can be phrased as follows: - There are three kinds of timestamp: per-event time, per-transaction original_commit_timestamp, per-transaction immediate_commit_timestamp. - There is no observed problem with original_commit_timestamp or immediate_commit_timestamp. - The observation is that the per-event time for XID_event in a replica binary log is always equal to that of the previous event in the same binary log. - This differs from row events and query_log_events, since the per-event time for them is preserved from the source. - This is perceived as a problem, and the suggestion is to instead make it equal to the per-event time for the corresponding XID_event in the primary. The suggested change is reasonable, as it would make the timestamps more understandable. But it would be good to understand the damage from this defect, since: - AFAIU, it has always worked like the current behavior, so there is no regression. - The per-event timestamp is a bit obsolete, since it has very low precision (second) and does not work well with timezone differences. - For measuring lag it is recommended to use the per-transaction timestamps. In what way does the current behavior cause problems for the application?
Description: hello, I found that for a transaction commit time (XID_event and GTID_event) is not correct, because it's not same with either commit-time of master-db or current time, but same with the last relayed write-rows event. As a result, we can't get any information of commit-time in binlog of slave db. How to repeat: Firstly, we configure binlog_format as `ROW`, binlog_row_image as `FULL` and log_slave_updates as ON, then we setup 2 mysql instance with replication relationship. Then we execute these statements in master-db: mysql> create database q1; Query OK, 1 row affected (0.01 sec) mysql> use q1 Database changed mysql> create table t1 (id int); Query OK, 0 rows affected (0.02 sec) mysql> begin; Query OK, 0 rows affected (0.00 sec) mysql> insert into t1 values (1); Query OK, 1 row affected (0.03 sec) # wait for several seconds mysql> insert into t1 values (2); Query OK, 1 row affected (0.01 sec) # wait for several seconds mysql> commit; Query OK, 0 rows affected (0.00 sec) After slave-db has relayed these changes, we check binlog of both master-db and slave-db. ============================================[master-db]============================================== #210315 14:50:29 server id 1 end_log_pos 609 CRC32 0xf32cabaf GTID last_committed=2 sequence_number=3 rbr_only=yes original_committed_timestamp=1615791029229811 immediate_commit_timestamp=1615791029229811 transaction_length=360 /*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/; # original_commit_timestamp=1615791029229811 (2021-03-15 14:50:29.229811 CST) # immediate_commit_timestamp=1615791029229811 (2021-03-15 14:50:29.229811 CST) /*!80001 SET @@session.original_commit_timestamp=1615791029229811*//*!*/; /*!80014 SET @@session.original_server_version=80022*//*!*/; /*!80014 SET @@session.immediate_server_version=80022*//*!*/; SET @@SESSION.GTID_NEXT= '5392b7b6-12dc-11eb-97f7-801844e6dd8c:3'/*!*/; # at 609 #210315 14:50:15 server id 1 end_log_pos 687 CRC32 0xb3c38190 Query thread_id=8 exec_time=0 error_code=0 SET TIMESTAMP=1615791015/*!*/; BEGIN /*!*/; # at 687 #210315 14:50:15 server id 1 end_log_pos 733 CRC32 0x8649d77f Table_map: `q1`.`t1` mapped to number 103 # at 733 #210315 14:50:15 server id 1 end_log_pos 773 CRC32 0xcf2de342 Write_rows: table id 103 flags: STMT_END_F BINLOG ' pwNPYBMBAAAALgAAAN0CAAAAAGcAAAAAAAEAAnExAAJ0MQABAwABAQEAf9dJhg== pwNPYB4BAAAAKAAAAAUDAAAAAGcAAAAAAAEAAgAB/wABAAAAQuMtzw== '/*!*/; ### INSERT INTO `q1`.`t1` ### SET ### @1=1 /* INT meta=0 nullable=1 is_null=0 */ # at 773 #210315 14:50:22 server id 1 end_log_pos 819 CRC32 0x5dd0d032 Table_map: `q1`.`t1` mapped to number 103 # at 819 #210315 14:50:22 server id 1 end_log_pos 859 CRC32 0xd1838737 Write_rows: table id 103 flags: STMT_END_F BINLOG ' rgNPYBMBAAAALgAAADMDAAAAAGcAAAAAAAEAAnExAAJ0MQABAwABAQEAMtDQXQ== rgNPYB4BAAAAKAAAAFsDAAAAAGcAAAAAAAEAAgAB/wACAAAAN4eD0Q== '/*!*/; ### INSERT INTO `q1`.`t1` ### SET ### @1=2 /* INT meta=0 nullable=1 is_null=0 */ # at 859 #210315 14:50:29 server id 1 end_log_pos 890 CRC32 0x70f2a063 Xid = 27 COMMIT/*!*/; ============================================[slave-db]=============================================== # at 584 #210315 14:50:22 server id 1 end_log_pos 670 CRC32 0x1234795c GTID last_committed=2 sequence_number=3 rbr_only=yes original_committed_timestamp=1615791029229811 immediate_commit_timestamp=1615790853727077 transaction_length=362 /*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/; # original_commit_timestamp=1615791029229811 (2021-03-15 14:50:29.229811 CST) # immediate_commit_timestamp=1615790853727077 (2021-03-15 14:47:33.727077 CST) /*!80001 SET @@session.original_commit_timestamp=1615791029229811*//*!*/; /*!80014 SET @@session.original_server_version=80022*//*!*/; /*!80014 SET @@session.immediate_server_version=80022*//*!*/; SET @@SESSION.GTID_NEXT= '5392b7b6-12dc-11eb-97f7-801844e6dd8c:3'/*!*/; # at 670 #210315 14:50:15 server id 1 end_log_pos 743 CRC32 0x1f7289db Query thread_id=8 exec_time=4294967134 error_code=0 SET TIMESTAMP=1615791015/*!*/; SET @@session.sql_mode=524288/*!*/; BEGIN /*!*/; # at 743 #210315 14:50:15 server id 1 end_log_pos 789 CRC32 0x5cae5417 Table_map: `q1`.`t1` mapped to number 81 # at 789 #210315 14:50:15 server id 1 end_log_pos 829 CRC32 0x52c5363f Write_rows: table id 81 flags: STMT_END_F BINLOG ' pwNPYBMBAAAALgAAABUDAAAAAFEAAAAAAAEAAnExAAJ0MQABAwABAQEAF1SuXA== pwNPYB4BAAAAKAAAAD0DAAAAAFEAAAAAAAEAAgAB/wABAAAAPzbFUg== '/*!*/; ### INSERT INTO `q1`.`t1` ### SET ### @1=1 /* INT meta=0 nullable=1 is_null=0 */ # at 829 #210315 14:50:22 server id 1 end_log_pos 875 CRC32 0xed285eec Table_map: `q1`.`t1` mapped to number 81 # at 875 #210315 14:50:22 server id 1 end_log_pos 915 CRC32 0x41a2f3ce Write_rows: table id 81 flags: STMT_END_F BINLOG ' rgNPYBMBAAAALgAAAGsDAAAAAFEAAAAAAAEAAnExAAJ0MQABAwABAQEA7F4o7Q== rgNPYB4BAAAAKAAAAJMDAAAAAFEAAAAAAAEAAgAB/wACAAAAzvOiQQ== '/*!*/; ### INSERT INTO `q1`.`t1` ### SET ### @1=2 /* INT meta=0 nullable=1 is_null=0 */ # at 915 #210315 14:50:22 server id 1 end_log_pos 946 CRC32 0x8517d23e Xid = 7 COMMIT/*!*/; /********************************************** Problems ***************************************************/ Analyzing the binlog file of master-db above, we can see that: ## om master-db, we executed the 1st insert stament at '14:50:15', and 1nd insert at '14:50:22', and commit the transaction at '14:50:29' Analyzing binlog of slave-db, we can see that: ## Execute time of the 2 insert statements are the same with master-db ('14:50:15' and '14:50:22') ## Execute time of XID_event and GTID_event is '14:50:22' ## While slave-db relayed this transaction. current time is `14:47:33` (time of 2 hosts differ): # original_commit_timestamp=1615791029229811 (2021-03-15 14:50:29.229811 CST) # immediate_commit_timestamp=1615790853727077 (2021-03-15 14:47:33.727077 CST) So, commit time of slave-db while replaying events didn't instructs any useful information, which is not same with either commit-time of master-db (14:50:29) or current-time (14:47:33). And I think use commit-time of master-db instead will be a better choice.