On iostat, disk latency; iohist onward!

Just a little heads-up and a bit of MySQL-related technical content for all of you still out there following along…

At Proven Scaling, we take on MySQL performance problems pretty regularly, I’m often in need of good tools to characterize current performance and find any issues. In the database world, you’re really looking for a few things of interest related to I/O: throughput in bytes, requests, and latency. The typical tool to get this information on Linux is iostat. You would normally run it like iostat -dx 1 sda and its output would be something like this, repeating every 1 second:


Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s rkB/s wkB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 8.00 0.00 4.00 0.00 96.00 0.00 48.00 24.00 0.06 15.75 15.75 6.30

Most of the output of iostat is interesting and reasonable for its intended purpose, which is as a general purpose way to monitor I/O. The really interesting things for most database servers (especially those in trouble) are:

  • avgrq-sz — Average request size, in kilobytes.
  • avgqu-sz — Average I/O queue length, in requests.
  • await — Average waiting time (in queue and scheduler) before servicing a request, in milliseconds.
  • svctm — Average total service time for I/O requests, in milliseconds. This includes await, so should always be higher than await. This is the most interesting number for any write-heavy transactional database server, as it translates directly to transaction commit time.
  • %util — Approximate percent utilization for the device.

There are one major problem with using iostat to monitor MySQL/InnoDB servers: svctm and await combine reads and writes. With a reasonably configured InnoDB, on a server with RAID with a battery-backed write cache (BBWC), reads and writes will have very different behaviour. In general, with a non-filled cache, writes should complete (to the BBWC) in just about zero milliseconds. Reads should take approximately the theoretical average time possible on the underlying disk subsystem.

I’ve often times found myself scratching my head looking at a non-sensical svctm due to reads and writes being combined together. One day I was perplexed enough to do something about it: I opened up the code for iostat to see how it worked. It turns out that the core of what it does is quite simple (so much so, I wonder why it’s C instead of Perl) — it opens /proc/diskstats, and /proc/stat and does some magic to the contents.

What I really wanted is a histogram of the reads and writes (separately, please!) for the given device. I hacked up a quick script to do that, and noticed how incredibly useful it is. I recently had to extend it to address other customer needs, so I worked on it a bit more and now it looks pretty good. Here’s an example from a test machine (so not that realistic for a MySQL server):

util:   1.27% r_ios:     0  w_ios:     1  aveq:     0,
ms : r_svctm                     : w_svctm
 0 :                             :
 1 :                             :
 2 :                             :
 3 : x                           :
 4 : x                           :
 5 : xxx                         :
 6 : xxxx                        :
 7 :                             :
 8 : x                           : x
 9 : x                           : xx
10 : x                           : xxxxx
11 :                             : xxxxxxxxxxxxxxx
12 :                             : xxxxxxxxxxxxxxxxxxxxxxxxx
13 : xx                          : xxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
14 :                             : xxxxxxxxxxxxxxxxxxxxx
15 : xx                          : xxxxxxxxxxx
16 : x                           : xxxxx
17 : x                           : xxxxxx
18 :                             : xxxx
19 : x                           : xx
20 :                             : x
21 :                             : x
22 :                             : x
23 :                             : x
24 :                             : x
25 :                             :
26 :                             :
27 :                             :
28 : x                           :
29 :                             :
30 :                             :
++ : 0                           : 250

It uses Curses now to avoid redrawing the entire screen, and I’ve got a ton of ideas on how to improve it. I have a few more must-haves before I release it formally to the world, but I wonder what more features people would want from it. It is Linux-only for the foreseeable future.

What do you think?



Google
 
Search the Web Search only jcole.us

15 Responses to “On iostat, disk latency; iohist onward!”

  1. vadim mysqlperformanceblog.com Says:

    Great stuff!

    I would like to see the same info in old text format. It is easier to copy-paste.

  2. Colin Charles Says:

    Agreed with vadim. Text format output should be supported as well. And this is great stuff, kudos!

  3. Kevin Burton Says:

    Hm…….. I think you’re on to something… yeah… iostat is simple.

    This would sort of be a TOP for IO……… hm…… I think the concept should be extended a bit but I generally like the idea…… w00t.

  4. Sean Says:

    I think that would be great… I’ve been fighting with some I/O problems on an NFS server and I’d love that tool.

    Other features would be a time series display (ie just like iostat is now, but with reads and writes separated and in graph form) and some form of logging. I’ve just started looking at I/O scheduler tuning and have been trying to figure out a way to measure how effective a given setting is.

    thanks,

    Sean

  5. Jeremy Cole Says:

    Vadim, Colin:

    By “text format” do you mean raw numbers instead of a graph?

    Sounds easy enough. :)

  6. Francois Saint-Jacques Says:

    Raw numbers! You can combine them with nagios/rrd/munin…

  7. Farhan Mashraqi Says:

    I got your IM this morning. Thank you for writing this.

    More insight into IO = Less time scratching head

    Since the iostat on Solaris 10 has some different options, I will run all the commands you mentioned on Solaris to see how the same info can be extracted from Solaris iostat.

    BTW, the writing comes at an ideal time because I am working on some DTrace stuff to track IO. The concepts you mentioned are very helpful.

    Thanks again,

    Frank
    PS: Man, I was seeing chatting w/ Pascal and got to see pics from the Proven Scaling’s annual trip. It made me realize how much I missed it :)

  8. Farhan Mashraqi Says:

    s/seeing chatting/chatting/
    :)

  9. Pythian Group Blog » Log Buffer #44: a Carnival of the Vanities for DBAs Says:

    [...] Jeremy Cole shows how to get a visual take on MySQL and I/O statistics on Linux. (Something Pythian’s Alex Gorbachev looked at in an older article on basic IO Monitoring on Linux). [...]

  10. Colin Charles Says:

    @Jeremy: yeah, raw numbers for sure. Should be an easy implementation, because its easier to manipulate numbers than it is to manipulate a graph

  11. Blake Golliher Says:

    Any update on when / if you will release this?

  12. Dean Thompson Says:

    So — any chance you would release this tool? Pretty please, with sugar on top?

  13. Jeremy Zawodny Says:

    I can haz download?!

  14. Yuri Says:

    The MAN says
    From MAN

    await The average time (in milliseconds) for I/O requests
    issued to the device to be served. This includes the time
    spent by the requests in queue and the time spent servic-
    ing them.

    svctm
    The average service time (in milliseconds) for I/O
    requests that were issued to the device.

    You seem to have it backwards. Your svctm includes await. Is that the conclusion you drew from looking into iostat code or just a typo? My awaits are almost always higher than svctm

  15. Measuring & Optimizing I/O Performance - igvita.com Says:

    [...] popular tool amongst the database crowd, so not surprisingly you’ll find a lot of great discussions documenting the use. Depending on your application you will need to focus on different metrics, but as a gentle [...]

Leave a Reply