Brandon Nesterenko via developers <developers@lists.mariadb.org> writes:
2. Why the condition on thd->user_time.val? What is the situation where we are not replicating an event, but user_time is set and we do not want to put the current time in the XID_EVENT?
When SET TIMESTAMP is set, the XID_EVENT should use the user value, rather than the current time (as all other events of the transaction will use the SET TIMESTAMP value).
Hm, ok. I don't 100% recall what SET TIMESTAMP is used for, but I guess that makes sense.
3. This handles an XID end event, which is for InnoDB transactions. But MyISAM/Aria use a different end event, a COMMIT query, and there are are few other cases as well. Don't you want consistently to have the end of the query as the time in all end events? Then this code should probably instead be in binlog_flush_cache() or perhaps write_transaction_to_binlog()?
Hmm, but I think that would break your point of (4) where there are Query_log_events without end events. So if we tag their `when` to be at binlog time, then when we calculate the end of the Query_log_event on the slave, it would be when + exec_time, which could put us significantly past the real end time of the event. So I think the XID and Query_log events should be treated differently.
Aha, so what I missed is that the end_event will have exec_time set to the duration of the prior query in the event group. So it looks like this, where the last event is a COMMIT end_event with exec_time=2: #240725 11:13:19 server id 1 end_log_pos 927 CRC32 0x2ba8f136 GTID 0-1-4 #240725 11:13:19 server id 1 end_log_pos 0 CRC32 0x327ace12 Query thread_id=8 exec_time=2 error_code=0 xid=0 #240725 11:13:19 server id 1 end_log_pos 1102 CRC32 0x4e855e67 Query thread_id=8 exec_time=2 error_code=0 xid=0 Whereas for an autocommit with XID_log_event as end_event, there is no exec_time: #240725 11:13:21 server id 1 end_log_pos 1144 CRC32 0xc8677301 GTID 0-1-5 trans #240725 11:13:21 server id 1 end_log_pos 0 CRC32 0x54ccf6ee Query thread_id=8 exec_time=2 error_code=0 xid=0 #240725 11:13:21 server id 1 end_log_pos 1277 CRC32 0x51a85907 Xid = 136 So this is the case being fixed here, set the Xid=136 event to have timestamp equal to the (when + exec_time) of the prior query. So I guess an alternative would be to have the "COMMIT" end_event have exec_time=0 and timestamp set to the time of commit, just like the Xid_log_event? Anyway, then this sounds ok. For a multi-statement transaction, the GTID event has the time of the end of the transaction, not the start: #240725 11:13:29 server id 1 end_log_pos 1970 CRC32 0x6dbb2f78 GTID 0-1-9 trans #240725 11:13:26 server id 1 end_log_pos 0 CRC32 0xdd94a6da Query thread_id=8 exec_time=1 error_code=0 xid=0 #240725 11:13:27 server id 1 end_log_pos 0 CRC32 0xc3c9da02 Query thread_id=8 exec_time=1 error_code=0 xid=0 #240725 11:13:28 server id 1 end_log_pos 0 CRC32 0x778bdcb3 Query thread_id=8 exec_time=1 error_code=0 xid=0 #240725 11:13:29 server id 1 end_log_pos 2307 CRC32 0x5750cba9 Xid = 147 This is inconsistent with an autocommit transaction where the the GTID has timestamp of transaction start. Does this need to be fixed as well? Or doesn't it matter, because the master_last_event_time will just be set ahead slightly earlier by the IO thread, and the SQL threads only use the end_event to update the slave_last_event_time? Is that correctly understood?
4. Even given (3), there are still cases (eg. DDL) where there is no end event, and thus there is no event containing the time for the end of the operation on the master. Won't this cause some inconsistency in how the slave determines and displays its timings with this patch? If not, why not?
And to elaborate on the response of (3) for consistency, the Query_log_event's `when` uses thd->start_time, even for the end event. So the end Query_log_event for say a MyISAM/Aria transaction will be consistent with the single Query_log_event of an event without an explicit ending transaction.
Right, but this is because the time used for slave_last_event_time is set to the (when + exec_time) which is effectively the end time of the event. And the "COMMIT" query end event happens to get the when/exec_time values from the prior query execution, so it ends up consistent in the end. Right? The thing that confused me here was missing that the exec_time gets set for the end_event here and thus effectively gives the correct end time.
+ /* Remove 2 first fields and all fields above and including field 55 */ + used_fields&= ~((1ULL << 0) | (1ULL << 1)); + used_fields&= ((1ULL << 56)-1);
Should there be some constant used for the magic numbers 55/56? And/or an assertion that this value is correct?
That'd make sense, sure.
Also, is the intention here that we will from here on never add more fields to legacy SHOW SLAVE STATUS? If so, there should probably be a comment about this; also see the test case mysql-test/suite/rpl/t/rpl_show_slave_status.test which has comments that might need updating.
Not that I know of, why wouldn't we want to keep them in-sync?
Agree, it seems fine to me to continue to keep them in sync. My comment was referring to the fixed 55/56 constants in the code, which suggested to me that those were not expected to change any more. But with some constant and/or assert for that it should be fine, probably. - Kristian.