I've had a search through previous questions but can't find an exact match to my question:
At what point during a query transaction is the binary log timestamp set and then written to the binary log?
Context: I have been working with a DB which is using master/slave replication. Quite often the slave will fall behind the master server and I am certain is it simply due to there being a lot of transactions in the binary log that share the same timestamp. When I say a lot I am talking about over 150 timestamps belonging to over 9000 entries in a 1 hour log (plus the rest that returned under 9000 entries). This was found using:
mysqlbinlog bin-log.0001 | grep 'TIMESTAMP' | uniq -c | awk '{if ($1>9000){print $0}} ' | sed -e 's/\/\*\!\*\/;//g' | gawk -F '=' '{cmd="date -d @"$2; cmd | getline d; print $1"="$2"\t("d")"; close(d)}'
So I'm basically trying to workout if the number of transactions sharing a timestamp is a reflection of workload on the master server, and whether these numbers are unusual.
When graphing the Second_behind_master it shows linear growth and then a sudden drop off which seems to suggest the same thing.
MySQL version is 5.6.33.
There are a number possible reasons for 'slave lag' which would be hard to answer in detail here. The binary log timestamp is written at the start of the transaction.
There is a useful post that walks through how to identify the cause of your symptoms here: https://www.percona.com/blog/2014/05/02/how-to-identify-and-cure-mysql-replication-slave-lag/ For example, it explains how the Seconds_Behind_Master parameter can be misleading, because it only measures the difference between the timestamps of the relay log most recently executed, versus the relay log entry most recently downloaded by the IO_THREAD.
You'll find many other resources on the site that might help you. This includes the Percona Toolkit, mentioned in the blog post which, like ALL Percona software is entirely free of charge, and open source.
Disclosure: I work for Percona.