Analyzing the distribution of InnoDB log file writes

July 17, 2010

Author

Baron Schwartz

MySQL

Percona Software

Share this Post:

I recently did a quick analysis of the distribution of writes to InnoDB’s log files. On a high-traffic commodity MySQL server running Percona XtraDB for a gaming workload (mostly inserts to the “moves” table), I used strace to gather statistics about how the log file writes are distributed in terms of write size. InnoDB writes to the log files in multiples of 512 bytes. Mark Callaghan explained this and some of its performance implications here. How many big writes does InnoDB do, and how many small writes?

First, I found out the file descriptor numbers of the log files:

<pre><br># lsof -p $(pidof mysqld) | grep ib_log<br>mysqld  29772 mysql    8uW  REG                8,2   268435456   7143989 /var/lib/mysql/ib_logfile0<br>mysqld  29772 mysql    9uW  REG                8,2   268435456   7143993 /var/lib/mysql/ib_logfile1<br>

1	<pre><br># lsof -p $(pidof mysqld) \| grep ib_log<br>mysqld 29772 mysql 8uW REG 8,2 268435456 7143989 /var/lib/mysql/ib_logfile0<br>mysqld 29772 mysql 9uW REG 8,2 268435456 7143993 /var/lib/mysql/ib_logfile1<br>

The file descriptors are 8 and 9. We’ll need to capture writes to both of those; InnoDB round-robins through them. The following grabs the write sizes out of 100k calls to pwrite() and aggregates them:

<pre><br># strace -f -p $(pidof mysqld) -e pwrite -s1 -xx 2&gt;&amp;1 <br>   | grep 'pwrite([89],' |head -n 100000 <br>   | awk '{writes[$5]++}END{for(w in writes){print w, " ", writes[w]}}'<br>

1	<pre><br># strace -f -p $(pidof mysqld) -e pwrite -s1 -xx 2>&1 <br> \| grep 'pwrite([89],' \|head -n 100000 <br> \| awk '{writes[$5]++}END{for(w in writes){print w, " ", writes[w]}}'<br>

I could have done it better with a little more shell scripting, but the output from this was enough for me to massage into a decent format with another step or two! Here is the final result:

<pre><br>bytes	count<br>512	44067<br>1024	30740<br>1536	15221<br>2048	7094<br>2560	1810<br>3072	570<br>3584	219<br>4096	112<br>4608	39<br>5120	23<br>5632	16<br>6144	15<br>6656	5<br>7168	3<br>7680	8<br>8192	2<br>8704	2<br>9216	1<br>9728	2<br>10240	1<br>10752	2<br>11264	1<br>11776	1<br>14848	1<br>15360	1<br>15872	2<br>16384	4<br>16896	4<br>17408	2<br>17920	2<br>18432	2<br>18944	8<br>19456	7<br>19968	4<br>20480	4<br>21504	1<br>22016	2<br>24064	1<br>40960	1<br>

1

<pre> bytes count 512 44067 1024 30740 1536 15221 2048 7094 2560 1810 3072 570 3584 219 4096 112 4608 39 5120 23 5632 16 6144 15 6656 5 7168 3 7680 8 8192 2 8704 2 9216 1 9728 2 10240 1 10752 2 11264 1 11776 1 14848 1 15360 1 15872 2 16384 4 16896 4 17408 2 17920 2 18432 2 18944 8 19456 7 19968 4 20480 4 21504 1 22016 2 24064 1 40960 1

So, in sum, we see that about 3/4ths of InnoDB log file writes on this workload are 512 or 1024 bytes. (It might vary for other workloads.) Now, what does this actually mean? There are a lot of interesting and complex things to think about here and research further:

Most writes are less than 4k, but the operating system page size is 4k. If the page isn’t in the OS buffer cache, then the write will cause a read-around write — the page will have to be read, modified, and then written again, instead of just written. Vadim did some benchmarks earlier showing that the log files need to be in the OS cache for best performance (sorry, can’t find the link right now). This makes intuitive sense given that the writes are smaller than 4k.

This server has innodb_flush_log_at_trx_commit set to 2. This means each transaction does a log file write, the same as for a setting of 1. If it’s set to 0, the distribution may be quite different — the writes might accumulate and become much larger.

What happens if the log buffer is actually smaller than a transaction? That’s another topic for research. I don’t know off the top of my head.

Is the distribution meaningful for determining the necessary log buffer size? The largest write above is just under 40k, which might seem to indicate that only 64k or so of log buffer would be large enough — but is it really? We’d need to benchmark and see. Peter and I were just talking, trying to remember some complex behavior of how space in the buffer is reserved for writes. We could not quite recall what that is, but there is some subtlety. This needs more research. It’s possible that even if the largest write is quite small, a small log buffer size wouldn’t be good and could cause additional lock contention. (There is a single mutex around the log buffer.) We probably need to benchmark to learn more about this.

In the end, the distribution is a simple observation to make, but the InnoDB redo log system is intricate. It’s not something to guess about, but rather something to measure and study more deeply. Perhaps we can follow this up with some more benchmarks or observations under different InnoDB settings and different workloads. Or then again, maybe Yasufumi will read this post when he returns from vacation and already know all the answers by heart!