Bug #89148 The timestamp of the GITD events in the GR relay log look wrong.
Submitted: 8 Jan 22:23 Modified: 12 Feb 7:38
Reporter: Jean-François Gagné Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Group Replication Severity:S4 (Feature request)
Version:5.7.20 and 8.0.3 OS:Any
Assigned to: CPU Architecture:Any
Triage: Needs Triage: D5 (Feature request)

[8 Jan 22:23] Jean-François Gagné
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.
[12 Feb 7:38] Umesh Shastry
Hello Jean,

Thank you for the report and feature request!

Thanks,
Umesh