The ib_logfiles mtime mystery
I have seen it stated many times that MySQL redo log files or ib_logfiles, are used in a circular fashion – even the manual says so. However during one of my observations, I saw the following behaviour in MySQL 5.6:
$ ls -latrh ib_log* -rw-r----- 1 mysql mysql 2.0G May 24 13:01 ib_logfile1 -rw-r----- 1 mysql mysql 2.0G May 24 13:24 ib_logfile0
This looks ok, ib_logfile0 is the one being written to. After waiting some time for the log to switch files, I expected to see something like:
$ ls -latrh ib_log* -rw-r----- 1 mysql mysql 2.0G May 24 13:24 ib_logfile0 -rw-r----- 1 mysql mysql 2.0G May 24 13:35 ib_logfile1
However I never saw that. What I actually saw was something like this:
$ ls -latrh ib_log* -rw-r----- 1 mysql mysql 2.0G May 24 13:35 ib_logfile0 -rw-r----- 1 mysql mysql 2.0G May 24 13:35 ib_logfile1
Both files being written to at the same time.
Digging a little more
First of all, I checked the mtimes in full format:
$ ls -latrh --full-time ib_log* -rw-r----- 1 mysql mysql 2.0G 2016-05-24 18:08:14.264116666 +0000 ib_logfile0 -rw-r----- 1 mysql mysql 2.0G 2016-05-24 18:08:18.764219555 +0000 ib_logfile1
After running a few online searches, I couldn’t find anything that explained why both log files were being written to at roughly the same time, so I decide to have a look at the source code.
The following comment on log0log.h provided the following explanation:
“We write alternately to the checkpoint fields when we make new checkpoints; this field is only defined in the first log file of a log group”
So ib_logfile0 contains the log checkpoint information in the log group header. A checkpoint in this context is the LSN of the oldest modification in the buffer pool, so it corresponds to an actual position in the log files (See log_calc_where_lsn_is function).
The log checkpoint information is stored in two locations which are used alternatively (the reason for this I have yet to figure out) and correspond to pages 1 and 3 of the first log file. This is exposed as ‘Last checkpoint at’ in innodb status:
mysql> show engine innodb status\G --- LOG --- Log sequence number 73636504193043 Log flushed up to 73636500884764 Pages flushed up to 73635409614578 Last checkpoint at 73635393067723 Max checkpoint age 5217674159 Checkpoint age target 5054621842 Modified age 1094578465 Checkpoint age 1111125320
The first log file will always have the checkpoint info written to it, so that is why even if ib_logfile1 is the “active” logfile, you will still see writes to ib_logfile0.