Bug #102971 slave-db losts original commit time of master_db
Submitted: 15 Mar 7:06 Modified: 20 Apr 10:04
Reporter: Brian Yue (OCA) Email Updates:
Status: Verified Impact on me:
None 
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)

[15 Mar 7:06] Brian Yue
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.
[1 Apr 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 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 10:04] MySQL Verification Team
Observed this finally. Thank you!

regards,
Umesh