Uncovering the ib_logfiles mtime Mystery

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.

After some time examining the code, I tracked this specifically to the log_group_checkpoint function in log0log.c (the link is for Percona server, but this also applies to plain MySQL)

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

Summary

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.