Thursday May 28, 2009

Inniostat - InnoDB IO Statistics

I wrote a small DTrace script to understand InnoDB IO statistics. This script shows statistics about different kinds of Innodb IO requests and how many of them result in actual IO. Sample output is shown below
#./inniostat -h
Usage: inniostat [-h] [-d] [-p pid] [interval]
                 -h : Print this message
                 -p : MySQL PID
                 -d : Dump dtrace script being used

# ./inniostat
 __physical__  ___Innodb___ ____read____     ______write______
   r/s    w/s    r/s    w/s   data    pre    log dblbuf dflush     Time
    24    121     24     50     24      0     50      0      0 16:00:57
    26    130     26     51     26      0     51      0      0 16:00:58
    18    134     18     54     18      0     54      0      0 16:00:59
    25    129     25     51     25      0     51      0      0 16:01:00
    29    116     46     47     17     29     47      0      0 16:01:01
    10    140     10    132     10      0     52      0     80 16:01:02
    29    129     35     53     14     21     53      0      0 16:01:03

r/s Physical (Actual) writes per sec
w/s Physical (Actual) writes per sec
r/s Reads issued by Innodb per sec
w/s Writes issued by Innodb per sec
data Regular Reads issued by Innodb to the datafiles per sec
pre Prefetch Reads issued by Innodb to the datafiles per sec
log Log writes issued by Innodb per sec
dblbuf Double buffer writes per sec
dflush Writes due to flushing of Innodb buffers to disk.

For the above example you can see that writes to the Innodb double buffer (dblbuf) is zero. This is because I had turned it off explicitly. You will also notice that there are more physical writes than what Innodb is requesting. This can be due to a variety of factors (other engines are doing writes, other applications are doing writes, recordsize mismatch between filesystem and mysql, filesystem logging, etc.). You will also notice a few prefetch requests are being issued.

Another example

Consider the sample output below (contributed by Dimitri)

 __physical__  ___Innodb___ ____read____    ______write______
   r/s    w/s    r/s    w/s   data    pre    log dblbuf dflush     Time
     0   1681      0   5259      0      0   2780      0   2479 14:58:13
     0    224      0   6111      0      0   6111      0      0 14:58:18
     0    761      0   4300      0      0   3368      0    932 14:58:23
     0    503      0   4232      0      0   3546      0    686 14:58:28
     0    904      0   4024      0      0   2923      0   1101 14:58:33
     0   1231      0   4046      0      0   2470      0   1575 14:58:38
     0    502      0   4192      0      0   3640      0    552 14:58:43
     0    928      0   4669      0      0   3331      0   1338 14:58:48
You can quickly notice that this is a cached workload (r/s is zero). There is a significant difference between log writes issued by Innodb and physical writes. This is because this particular setup had innodb_flush_log_at_trx_commit set to 2 (i.e flush log writes every second). If want to flush the log after every commit, you need a disk[s] that can handle around 3000 writes per second. You will also notice a lot of Innodb buffers being flushed (dflush). This maybe because modified buffers in the Innodb buffer pool are being flushed, and/or due to caching in the filesystem instead of in the InnoDB buffer pool.

But I can get some these statistics via "show status"

Some (but not all) of these statistics are available via "show status" command. Be sure to understand what they are measuring before using them. Few of them can be little puzzling. For ex, Innodb_buffer_pool_read_ahead_seq variable counts the number of times a sequential read ahead was triggered. It does not tell you, how many pages were fetched as a result of the read ahead. Similarly, Innodb_log_write_requests tells you how many times a write happened to the log, but its is not really useful as this is incremented when someone writes to the in-memory log block, it does not tell you when the log was written to disk.


Innodb issues reads to either the data files or log files (during recovery). This script does not differentiate between them. Writes are either to the data files, log files, or double write buffer. If you view the source of the script (or use the -d option), you will see that I am interposing on the fil_io function and interpreting its arguments to differentiate IO types. I am using the io:::start probe to figure out the physical IO. Note that this script tracks Innodb IO requests. The actual IO may be carried out by a Innodb background thread some time later. This script also makes assumptions regarding several Innodb constants and hence may not be accurate for future versions.


You can download it here. Since it uses DTrace, it only works on Solaris, MacOS and FreeBSD. Please feel free to use it and let me know of any feedback/comments.

Thursday Nov 01, 2007

Visualizing callgraphs via dtrace and ruby

The allfrom.d dscript can be used to display all function entry/exits caused by a function call. When call graphs are deep, or long, a visual representation is very helpful to understand the flow as well as how much time each function consumed. The output displayed is inspired by Roch's CallStackAnalyzer which was in turn inspired by the work on vftrace by Jan Boerhout.

I wrote a simple ruby script to post process the allfrom.d output and generate a SVG image. The advantage of using SVG is that you can use javascript to provide added functionality. For example, you can hover your mouse over any block to see the name of the function and its elapsed time. Similarly, you could add support for Zoom and Pan

Unfortunately, I am having problems with serving svg files with the right mime type. So I have included a png image below. You can save the svg files somewhere on your computer and view them using Firefox.

A sample for the connect(3socket) is shown below. The input file used to generate it is available here. The width of each box indicates how long the function took. Y axis indicates call depth.

If you are interested, you can also check out

To use the scripts to generate your own call stacks, download the following two [ 1, 2] ruby source files. For example, to generate the above callgraph, you can use

dtrace -s allfromkernel.d acccept > accept.log
ruby function_call_graph.rb accept.log > accept.svg

Note that the script does not work reliably for asynchronous function calls, or cases where the thread changes CPU. If there is sufficient interest, I might be tempted to add those in :-)



« August 2016