| Bug #89148 | The timestamp of the GITD events in the GR relay log look wrong. | ||
|---|---|---|---|
| Submitted: | 8 Jan 2018 22:23 | Modified: | 12 Feb 2018 7:38 |
| Reporter: | Jean-François Gagné | Email Updates: | |
| Status: | Verified | Impact on me: | |
| Category: | MySQL Server: Group Replication | Severity: | S4 (Feature request) |
| Version: | 5.7.20 and 8.0.3 | OS: | Any |
| Assigned to: | CPU Architecture: | Any | |
[12 Feb 2018 7:38]
MySQL Verification Team
Hello Jean, Thank you for the report and feature request! Thanks, Umesh
[4 Jun 2019 1:23]
Fengchun Hua
certification_handler.cc handle_transaction_id
/*
Remote transaction.
*/
if (seq_number > 0)
{
if (!tcle->is_gtid_specified())
{
// Create new GTID event.
Gtid gtid= { group_sidno, seq_number };
Gtid_specification gtid_specification= { GTID_GROUP, gtid };
Gtid_log_event *gle_generated= new Gtid_log_event(gle->server_id,
gle->is_using_trans_cache(),
gle->last_committed,
gle->sequence_number,
gle->may_have_sbr_stmts,
gtid_specification);
/*slave create a new gle, and this event will use slave's applier thread
time, but this time will never changed after mgr started. So change it to
use master's gle time*/
gle_generated->header()->when= gle->header()->when;
pevent->reset_pipeline_event();
pevent->set_LogEvent(gle_generated);
[4 Jun 2019 1:24]
Fengchun Hua
see fix above. I think this way can fix this bug.
Description: Hi, It looks to me that there is something wrong with the timestamps of the GTID event of Group Replication. I would expect the timestamps to be corresponding to when the event was committed (or certified) but I am getting timestamps which looks like when Group Replication was started. Here is an extract of the relay logs of Group Replication: # mysqlbinlog my_relaylog-group_replication_applier.N | grep -e last_ | sed -e 's/server id.*last/[...] last/' -e 's/.rbr_only.*/ [...]/' #180106 19:31:36 [...] last_committed=0 sequence_number=0 [...] #180106 19:31:36 [...] last_committed=1 sequence_number=2 [...] -- CREATE DB #180106 19:31:36 [...] last_committed=2 sequence_number=3 [...] -- CREATE TB #180106 19:31:36 [...] last_committed=3 sequence_number=4 [...] -- INSERT a #180106 19:31:36 [...] last_committed=3 sequence_number=5 [...] -- INSERT b #180106 19:31:36 [...] last_committed=3 sequence_number=6 [...] -- INSERT c And the corresponding binary logs: # mysqlbinlog my_binlog.M | grep -e last_ | sed -e 's/server id.*last/[...] last/' -e 's/.rbr_only.*/ [...]/' #180106 19:31:59 [...] last_committed=0 sequence_number=1 [...] -- CREATE DB #180106 19:32:02 [...] last_committed=1 sequence_number=2 [...] -- CREATE TB #180106 19:32:05 [...] last_committed=2 sequence_number=3 [...] -- INSERT a #180106 19:32:08 [...] last_committed=3 sequence_number=4 [...] -- INSERT b #180106 19:32:11 [...] last_committed=4 sequence_number=5 [...] -- INSERT c Note: those extracts are from the following blog post: https://jfg-mysql.blogspot.com/2018/01/write-set-in-mysql-5-7-group-replication.html All the timestamps of the relay log events are 19:31:36 (I guess this match when Group Replication was started) and the binary log timestamps look like a match for the moment the transactions were run. We can see the same in the relay log extract of Bug#89147 (notice both GTID events having 19:40:07 and the next event having 19:42:13 and 19:42:20 respectively): # at 13288 #180106 19:40:07 [...] end_log_pos 61 GTID last_committed=55 sequence_number=57 [...] SET @@SESSION.GTID_NEXT= 'UUID:171'/*!*/; # at 13349 #180106 19:42:13 server id 198208002 end_log_pos 69 Query thread_id=2488 exec_time=0 error_code=0 [...] # at 14722 #180106 19:40:07 [...] end_log_pos 61 GTID last_committed=61 sequence_number=63 [...] SET @@SESSION.GTID_NEXT= 'UUID:177'/*!*/; # at 14783 #180106 19:42:20 [...] end_log_pos 69 Query thread_id=2517 exec_time=0 error_code=0 [...] Many thanks for looking into that, JFG How to repeat: See description.