Systems Performance 2nd Ed.



BPF Performance Tools book

Recent posts:
Blog index
About
RSS

File System Latency: part 4

24 May 2011

I originally posted this at http://dtrace.org/blogs/brendan/2011/05/24/file-system-latency-part-4.

This is part 4 on file system latency, a series on storage I/O performance from the application perspective (see part 1, part 2 and part 3). In the previous post I showed how to trace file system latency from within MySQL using the pid provider. In this post I'll show how similar data can be retrieved using the DTrace syscall and fbt providers. These allow us to trace at the system call layer, and deeper in the kernel at both the Virtual File System (VFS) interface and the specific file system itself.

Syscall Tracing

By tracing at the system call layer, the file system can be traced system-wide - examining all applications simultaneously (no "-p PID"). DTrace has the "syscall" provider for tracing system calls:

                        +---------------+ 
                        |  Application  | 
                        |    mysqld     | 
                        +---------------+ 
                         reads ^ | writes 
                               | |                  user-land
      HERE -->  ---------system calls---------------------------
                               | |                  kernel
               +--------------------------------+
               |  File System  | |              |
               |               | V              |
               |/\/\/\/\/\/\/\/\/\/\/\/\/\/\/\/\|
[...]

Another advantage is that the syscalls are well understood and documented in the man pages. They are also much less likely to change than the mysql functions traced earlier (I would say - will never change - until I saw the exec() family of syscalls change slightly during the Solaris 10 releases).

syscall-read-zfs.d

To demonstrate syscall tracing, this DTrace script shows the latency of read()s to ZFS by application name:

# ./syscall-read-zfs.d 
dtrace: script './syscall-read-zfs.d' matched 2 probes
^C
  httpd                                               (ns):                                             
           value  ------------- Distribution ------------- count    
             512 |                                         0        
            1024 |@@@@@@                                   1072     
            2048 |@@@@@@@                                  1276     
            4096 |@@@@@                                    890      
            8192 |@@@@@@@@@@@@@@@@@@@@                     3520     
           16384 |@                                        152      
           32768 |                                         10       
           65536 |                                         2        
          131072 |                                         0        

  mysqld                                              (ns):                                             
           value  ------------- Distribution ------------- count    
             512 |                                         0        
            1024 |@@@                                      1268     
            2048 |@@@@@@@@@@@@@@@@@                        7710     
            4096 |@@@@@@@@@@@@@                            5773     
            8192 |@@@@@                                    2231     
           16384 |@                                        446      
           32768 |                                         186      
           65536 |                                         26       
          131072 |                                         7        
          262144 |                                         0   

As seen previously with mysqld_pid_fslatency.d, file system reads are extremely fast - most likely returning out of DRAM. The slowest seen above reached only the 131 to 262 microsecond range (less than 0.3 ms).

Tracing syscalls has been made dramatically easier with the introduction of the fds[] array, which allows file descriptor numbers to be converted into descriptive details, such as the file system type. The array is indexed by file descriptor number, which for the read() syscall is the first argument: read(fd, buf, size). Here the fi_fs (file system) member is checked on line 4, to only match reads to ZFS:

     1  #!/usr/sbin/dtrace -s
     2  
     3  syscall::read:entry
     4  /fds[arg0].fi_fs == "zfs"/
     5  {
     6      self->start = timestamp;
     7  }
     8  
     9  syscall::read:return
    10  /self->start/
    11  {
    12      @[execname, "(ns):"] = quantize(timestamp - self->start);
    13      self->start = 0;
    14  }

This script can be modified to include other syscall types, and other file systems. See fsrwtime.d from the DTrace book for a version that matches more syscall types, and prints latency by file system, operation and mount point.

Syscall analysis with DTrace is easy and effective.

When doing amazing things by tracing the internals of an application, it can be easy to forget that syscall tracing may be good enough - and a lot simpler. For this reason we put it early in the Strategy section of the File System chapter of the DTrace book.

Drawbacks of the syscall approach are:

  • Can't currently execute in a Solaris zone or Joyent SmartMachine (only because the fds[] array isn't currently available; the syscall provider does work in those environments).
  • No query context. Expressing file system latency as a portion of query latency (as was done with mysqld_pid_fslatency_slowlog.d) isn't possible. (Unless this is inferred from syscall activity, such as via socket related syscalls; it might be possible - I haven't tried yet.)

Stack Fishing

Another use of the syscall provider is to investigate how applications are using the file system - the calling stack trace. This approach is how I initially found the above functions from the mysql source: my_read(), my_write(), etc, which took me to the right place to start reading the code. You can also try this approach if the mysqld_pid_fslatency.d script from part 3 fails:

# ./mysqld_pid_fslatency.d -p 16060
dtrace: failed to compile script ./mysqld_pid_fslatency.d: line 23: probe description 
pid16060::os_file_read:entry does not match any probes

First, make sure that the PID really is mysqld. Then, you can use "stack fishing" to find out what is being called instead of os_file_read() (in that case).

This one-liner demonstrates the approach, frequency counting the syscall type and user stack frames for the given process calling into the ZFS file system:

# dtrace -x ustackframes=100 -n 'syscall::*read:entry,
    syscall::*write:entry /pid == $target && fds[arg0].fi_fs == "zfs"/ { 
    @[probefunc, ustack()] = count(); }' -p 29952
dtrace: description 'syscall::*read:entry,syscall::*write:entry ' matched 4 probes
^C

  pread                                             
              libc.so.1`__pread+0xa
              mysqld`os_file_pread+0x8e
              mysqld`os_file_read+0x3b
              mysqld`fil_io+0x2b0
              mysqld`buf_read_page_low+0x14e
              mysqld`buf_read_page+0x81
              mysqld`buf_page_get_gen+0x143
              mysqld`fsp_reserve_free_extents+0x6d
              mysqld`btr_cur_pessimistic_delete+0x96
              mysqld`row_purge_remove_sec_if_poss_low+0x31c
              mysqld`row_purge_step+0x8e1
              mysqld`que_run_threads+0x7c6
              mysqld`trx_purge+0x3cb
              mysqld`srv_master_thread+0x99d
              libc.so.1`_thrp_setup+0x8d
              libc.so.1`_lwp_start
                1

[...output truncated...]
  pwrite                                            
              libc.so.1`__pwrite+0xa
              mysqld`os_file_write+0x97
              mysqld`fil_io+0x2b0
              mysqld`log_group_write_buf+0x34f
              mysqld`log_write_up_to+0x566
              mysqld`trx_commit_off_kernel+0x72f
              mysqld`trx_commit_for_mysql+0x9f
              mysqld`_Z15innobase_commitP3THDb+0x116
              mysqld`_Z19ha_commit_one_phaseP3THDb+0x95
              mysqld`_Z15ha_commit_transP3THDb+0x136
              mysqld`_Z9end_transP3THD25enum_mysql_completiontype+0x191
              mysqld`_Z21mysql_execute_commandP3THD+0x2172
              mysqld`_Z11mysql_parseP3THDPKcjPS2_+0x116
              mysqld`_Z16dispatch_command19enum_server_commandP3THDPcj+0xfc1
              mysqld`_Z10do_commandP3THD+0xb8
              mysqld`handle_one_connection+0x7f7
              libc.so.1`_thrp_setup+0x8d
              libc.so.1`_lwp_start
              904
  write                                             
              libc.so.1`__write+0xa
              mysqld`my_write+0x3e
              mysqld`my_b_flush_io_cache+0xdd
              mysqld`_ZN9MYSQL_LOG14flush_and_syncEv+0x2a
              mysqld`_ZN9MYSQL_LOG5writeEP3THDP11st_io_cacheP9Log_event+0x209
              mysqld`_Z16binlog_end_transP3THDP11st_io_cacheP9Log_event+0x25
              mysqld`_ZN9MYSQL_LOG7log_xidEP3THDy+0x51
              mysqld`_Z15ha_commit_transP3THDb+0x24a
              mysqld`_Z9end_transP3THD25enum_mysql_completiontype+0x191
              mysqld`_Z21mysql_execute_commandP3THD+0x2172
              mysqld`_Z11mysql_parseP3THDPKcjPS2_+0x116
              mysqld`_Z16dispatch_command19enum_server_commandP3THDPcj+0xfc1
              mysqld`_Z10do_commandP3THD+0xb8
              mysqld`handle_one_connection+0x7f7
              libc.so.1`_thrp_setup+0x8d
              libc.so.1`_lwp_start
              923
  read                                              
              libc.so.1`__read+0xa
              mysqld`my_read+0x4a
              mysqld`_my_b_read+0x17d
              mysqld`_ZN9Log_event14read_log_eventEP11st_io_cacheP6StringP14_pthread_mutex+0xf4
              mysqld`_Z17mysql_binlog_sendP3THDPcyt+0x5dc
              mysqld`_Z16dispatch_command19enum_server_commandP3THDPcj+0xc09
              mysqld`_Z10do_commandP3THD+0xb8
              mysqld`handle_one_connection+0x7f7
              libc.so.1`_thrp_setup+0x8d
              libc.so.1`_lwp_start
             1496
  read                                              
              libc.so.1`__read+0xa
              mysqld`my_read+0x4a
              mysqld`_my_b_read+0x17d
              mysqld`_ZN9Log_event14read_log_eventEP11st_io_cacheP6StringP14_pthread_mutex+0xf4
              mysqld`_Z17mysql_binlog_sendP3THDPcyt+0x35e
              mysqld`_Z16dispatch_command19enum_server_commandP3THDPcj+0xc09
              mysqld`_Z10do_commandP3THD+0xb8
              mysqld`handle_one_connection+0x7f7
              libc.so.1`_thrp_setup+0x8d
              libc.so.1`_lwp_start
             2939

The DTrace scripts shown earlier take the file system functions (as seen in the above stack traces) and measure latency. There are a lot more functions that DTrace can also inspect (any of the lines above), along with the function entry arguments and return values.

Stack traces show functions that can be individually traced with DTrace.

Note that this one-liner includes all file system I/O, not just those during a query. The very first stack trace looks like it is as asynchronous database thread (srv_master_thread() -> trx_purge()), whereas all the rest look like they are indeed during a query (handle_one_connection() -> do_command()). The numbers at the bottom of the stack shows the number of times that entire stack trace was responsible for the syscall being called, during tracing (I let it run for several seconds).

VFS Tracing

Apart from the application itself and system calls, DTrace can also drill down into the kernel. The first location of interest is the Virtual File System abstraction layer, which is an interface that file systems are called from. Such a common interface is good fodder for DTracing. There isn't a vfs provider for DTrace (at least, one that exposes the latency of events), and so to do this we can currently use the fbt provider to trace kernel internals.

Introducing VFS into our I/O stack:

                              +---------------+ 
                              |  Application  | 
                              |    mysqld     | 
                              +---------------+ 
                               reads ^ | writes 
                                     | |        
                                     | |                  user-land
                  -------------system calls---------------------------
                                     | |                  kernel
                            +-------------------+   
      HERE -->              |        VFS        |               
                +-----------|                   |------------+
                | File      +-------------------+            |
                | Systems       / /         \ \              |
                |              / /           \ \             |
                |     +------------+  +------------+         |
                |     |  ZFS  | |  |  |  UFS  | |  |         |
                |     |       | |  |  |       | |  |  ...    |
                |     |       | V  |  |       | V  |         |
                |     |/\/\/\/\/\/\|  |/\/\/\/\/\/\|         |
[...]

Advantages of tracing at the VFS level include:

  • All file system types can be traced from one place.
  • The VFS interface functions are more "stable" than other parts of the kernel.
  • Kernel context is available, including more information than fds[] makes available.

You can find examples of VFS tracing in Chapter 5 of the DTrace book, which can be downloaded as a sample chapter (PDF). Here is an example, solvfssnoop.d, which traces all VFS I/O on Solaris:

# ./solvfssnoop.d -n 'tick-10ms { exit(0); }'
TIME(ms)      UID    PID PROCESS   CALL        KB  PATH
18844835237   104  29952 mysqld    fop_read    0   <null>
18844835237   104  29952 mysqld    fop_write   0   <null>
18844835238     0  22703 sshd      fop_read    16  /devices/pseudo/clone@0:ptm
18844835237   104  29008 mysqld    fop_write   16  /z01/opt/mysql5-64/data/xxxxx/xxxxx.ibd
18844835237   104  29008 mysqld    fop_write   32  /z01/opt/mysql5-64/data/xxxxx/xxxxx.ibd
18844835237   104  29008 mysqld    fop_write   48  /z01/opt/mysql5-64/data/xxxxx/xxxxx.ibd
18844835237   104  29008 mysqld    fop_write   16  /z01/opt/mysql5-64/data/xxxxx/xxxxx.ibd
18844835237   104  29008 mysqld    fop_write   16  /z01/opt/mysql5-64/data/xxxxx/xxxxx.ibd
18844835237   104  29008 mysqld    fop_write   32  /z01/opt/mysql5-64/data/xxxxx/xxxxx.ibd

I've had to redact the filename info (replaced portions with "xxxxx"), but you should still get the picture. This has all the useful details except for the latency, which can be added to the script by tracing the "return" probe as well as the "entry" probes, and comparing timestamps (similar to how the syscalls were traced earlier).

Since VFS I/O can be very frequent (thousands of I/O per second), when I invoked the script above I added an action to exit after 10 milliseconds. The script also accepts a process name as an argument, eg, "mysqld" to only trace VFS I/O from mysqld processes.

VFS Latency

To demonstrate fetching latency info, here is VFS read()s on Solaris traced via fop_read():

# dtrace -n 'fbt::fop_read:entry { self->start = timestamp; }
    fbt::fop_read:return /self->start/ { @[execname, "ns"] = 
    quantize(timestamp - self->start); self->start = 0; }'
dtrace: description 'fbt::fop_read:entry ' matched 2 probes
^C
[...]

  mysqld                                              ns                                                
           value  ------------- Distribution ------------- count    
             512 |                                         0        
            1024 |@@                                       725      
            2048 |@@@@@@@@@@@@@@@@                         5928     
            4096 |@@@@@@@@@                                3319     
            8192 |@@                                       708      
           16384 |                                         80       
           32768 |                                         17       
           65536 |                                         130      
          131072 |@                                        532      
          262144 |@                                        492      
          524288 |@                                        489      
         1048576 |@@                                       862      
         2097152 |@@@                                      955      
         4194304 |@@                                       602      
         8388608 |@                                        271      
        16777216 |                                         102      
        33554432 |                                         27       
        67108864 |                                         14       
       134217728 |                                         2        
       268435456 |                                         0   

Yikes! Wasn't this system running with a 99.9% cache hit rate earlier? The second group in the distribution shows VFS reads between 1 and 8 ms, sounding a lot like disk I/O cache misses. They aren't - and this is a disadvantage of tracing at VFS - it's including other things that use the VFS interface that aren't really file systems, including socket I/O.

Filtering just for ZFS:

# dtrace -n 'fbt::fop_read:entry /args[0]->v_op->vnop_name == "zfs"/ {
    self->start = timestamp; } fbt::fop_read:return /self->start/ {
    @[execname, "ns"] = quantize(timestamp - self->start); self->start = 0; }'
dtrace: description 'fbt::fop_read:entry ' matched 2 probes
^C
[...]

  mysqld                                              ns                                                
           value  ------------- Distribution ------------- count    
             512 |                                         0        
            1024 |@@@@@@@                                  931      
            2048 |@@@@@@@@                                 1149     
            4096 |@@@@@@@                                  992      
            8192 |@@@@@@@@@@@@@@@@                         2266     
           16384 |@@                                       320      
           32768 |                                         20       
           65536 |                                         2        
          131072 |                                         0      

That's better.

Drawbacks of VFS tracing:

  • It can include other kernel components that use VFS, such as sockets.
  • Application context not available.
  • It is not possible to do this from a Solaris zones or Joyent SmartMachine environment, via direct use of the fbt provider. The fbt provider allows inspection of kernel internals, which has the potential to share privileged data between zones, and so is unlikely to ever be available from within a zone. (But indirect use via a secure means may be possible - more on this in part 5).
  • The fbt provider is considered an "unstable" interface, since it exposes thousands of raw kernel functions. Any scripts written to use it may stop working on kernel updates, should the kernel engineer rename or modify functions you are tracing.

File System Tracing

The second location in the kernel to consider is the File System itself: ZFS, UFS, etc. This will expose file system specific characteristics, and can be the origin of many file system latency issues. DTrace can examine these using the fbt provider.

File systems in the I/O stack:

                              +---------------+ 
                              |  Application  | 
                              |    mysqld     | 
                              +---------------+ 
                               reads ^ | writes 
                                     | |        
                                     | |                  user-land
                  -------------system calls---------------------------
                                     | |                  kernel
                            +-------------------+   
                            |        VFS        |               
                +-----------|                   |------------+
                | File      +-------------------+            |
                | Systems       / /         \ \              |
                |              / /           \ \             |
                |     +------------+  +------------+         |
      HERE -->  |     |  ZFS  | |  |  |  UFS  | |  |         |
                |     |       | |  |  |       | |  |  ...    |
                |     |       | V  |  |       | V  |         |
                |     |/\/\/\/\/\/\|  |/\/\/\/\/\/\|         |
[...]

Advantages for tracing at the file system:

  • File system specific behaviour can be examined.
  • Kernel context is available, including more information than fds[] makes available.

After the VFS scripts, there are examples of file system tracing scripts in Chapter 5 of the DTrace book. One of my favourites is zfsslower.d, which takes a millisecond argument and shows any I/O that was slower than that time:

# ./zfsslower.d 10 
TIME                 PROCESS     D   KB   ms FILE
2011 May 17 01:23:12 mysqld      R   16   19 /z01/opt/mysql5-64/data/xxxxx/xxxxx.ibd
2011 May 17 01:23:13 mysqld      W   16   10 /z01/var/mysql/xxxxx/xxxxx.ibd
2011 May 17 01:23:33 mysqld      W   16   11 /z01/var/mysql/xxxxx/xxxxx.ibd
2011 May 17 01:23:33 mysqld      W   16   10 /z01/var/mysql/xxxxx/xxxxx.ibd
2011 May 17 01:23:51 httpd       R   56   14 /z01/home/xxxxx/xxxxx/xxxxx/xxxxx/xxxxx
^C

Again, I've redacted the filename info (replaced portions with "xxxxx"), but the output should still make sense. This is tracing the POSIX requests of the ZFS file system, via functions including zfs_read() and zfs_write(), and showing details including latency for any longer than the specified time.

Drawbacks of File System tracing:

  • Application context not available.
  • It is not possible to do this from a Solaris zones or Joyent SmartMachine environment, via direct use of the fbt provider. The fbt provider allows inspection of kernel internals, which has the potential to share privileged data between zones, and so is unlikely to ever be available from within a zone. (But indirect use via a secure means may be possible - more on this in part 5).
  • The fbt provider is considered an "unstable" interface, since it exposes thousands of raw kernel functions. Any scripts written to use it may stop working on kernel updates, should the kernel engineer rename or modify functions you are tracing.
  • File Systems get complex.

ZFS

The zfsslower.d script mentioned above only traces requests to ZFS. DTrace can continue drilling and expose all of the internals of ZFS, pinpointing file system induced latency. This could be the subject of a separate series of blog posts, including:

  • Lock contention latency
  • ZIO pipeline latency
  • Compression latency
  • Allocation latency
  • vdev queue latency
  • and lots more...

You may be able to skip this part if the latency can be traced at a lower level than the file system - ie, originating from the disk subsystem and being passed up the stack. Which can be a practical approach - digging into file system internals can be very time consuming, and isn't necessary for every issue.

Lower Level

By tracing down to the disk device, you can identify exactly where the latency is originating. The full kernel stack would include (showing Solaris ZFS in this example):

            -------------------system calls---------------------------
                                     | |                  kernel
                            +-------------------+   
                +-----------|        VFS        |------------+
                | File      +-------------------+            |
                | Systems            | |                     |
                |         +-----------------------+          |
                |         |  ZFS     | |          |          |
                |         |      +---------+      |          |
                |         |      |   ZIO   |      |          |
                |         |      +---------+      |          |
                |         |      |  vdevs  |      |          |
                |         +------+---------+------+          |
                |                    | |                     |
                +--------------------------------------------+
                                     | |            
                              +----------------+    
                              |  block device  |    
                              +----------------+    
                                     | |            
                                +------------+    
                                |    SCSI    |    
                                +------------+    
                                     | |            
                                +------------+    
                                |    SAS     |    
                                +------------+    
                                     | |            
                                     V |            
                                .-----------.      
                                `-----------'       
                                |   disk    |       
                                `-----------'      

Latency at each of these layers can be traced: VFS, ZFS (including ZIO pipeline and vdevs), block device (sd), SCSI and SAS. If the latency is originating from any of these locations, you can identify it by comparing between the layers.

To show what this can look like, here is an experimental script that shows latency from multiple layers at the same time - for comparison:

# ./zfsstacklatency.d
dtrace: script './zfsstacklatency.d' matched 25 probes
^C
CPU     ID                    FUNCTION:NAME
 15      2                             :END 
  zfs_read                                            time (ns)                                         
           value  ------------- Distribution ------------- count    
             512 |                                         0        
            1024 |@@@@                                     424      
            2048 |@@@@@@@@                                 768      
            4096 |@@@@                                     375      
            8192 |@@@@@@@@@@@@@@@@                         1548     
           16384 |@@@@@@@@                                 763      
           32768 |                                         35       
           65536 |                                         4        
          131072 |                                         12       
          262144 |                                         1        
          524288 |                                         0        

  zfs_write                                           time (ns)                                         
           value  ------------- Distribution ------------- count    
            2048 |                                         0        
            4096 |@@@                                      718      
            8192 |@@@@@@@@@@@@@@@@@@@                      5152     
           16384 |@@@@@@@@@@@@@@@                          4085     
           32768 |@@@                                      731      
           65536 |@                                        137      
          131072 |                                         23       
          262144 |                                         3        
          524288 |                                         0        


  zio_wait                                            time (ns)                                         
           value  ------------- Distribution ------------- count    
             512 |                                         0        
            1024 |@@@@@@@@@@@@@                            6188     
            2048 |@@@@@@@@@@@@@@@@@@@@@@@                  11459    
            4096 |@@@@                                     2026     
            8192 |                                         60       
           16384 |                                         37       
           32768 |                                         8        
           65536 |                                         2        
          131072 |                                         0        
          262144 |                                         0        
          524288 |                                         1        
         1048576 |                                         0        
         2097152 |                                         0        
         4194304 |                                         0        
         8388608 |                                         0        
        16777216 |                                         0        
        33554432 |                                         0        
        67108864 |                                         0        
       134217728 |                                         0        
       268435456 |                                         1        
       536870912 |                                         0        


  zio_vdev_io_done                                    time (ns)                                         
           value  ------------- Distribution ------------- count    
            2048 |                                         0        
            4096 |@                                        8        
            8192 |@@@@                                     56       
           16384 |@                                        17       
           32768 |@                                        13       
           65536 |                                         2        
          131072 |@@                                       24       
          262144 |@@                                       23       
          524288 |@@@                                      44       
         1048576 |@@@                                      38       
         2097152 |                                         1        
         4194304 |                                         4        
         8388608 |                                         4        
        16777216 |                                         4        
        33554432 |@@@                                      43       
        67108864 |@@@@@@@@@@@@@@@@@@@@@                    315      
       134217728 |                                         0        
       268435456 |                                         2        
       536870912 |                                         0        


  vdev_disk_io_done                                   time (ns)                                         
           value  ------------- Distribution ------------- count    
           65536 |                                         0        
          131072 |@                                        12       
          262144 |@@                                       26       
          524288 |@@@@                                     47       
         1048576 |@@@                                      40       
         2097152 |                                         1        
         4194304 |                                         4        
         8388608 |                                         4        
        16777216 |                                         4        
        33554432 |@@@                                      43       
        67108864 |@@@@@@@@@@@@@@@@@@@@@@@@@                315      
       134217728 |                                         0        
       268435456 |                                         2        
       536870912 |                                         0        


  io:::start                                          time (ns)                                         
           value  ------------- Distribution ------------- count    
           32768 |                                         0        
           65536 |                                         3        
          131072 |@@                                       19       
          262144 |@@                                       21       
          524288 |@@@@                                     45       
         1048576 |@@@                                      38       
         2097152 |                                         0        
         4194304 |                                         4        
         8388608 |                                         4        
        16777216 |                                         4        
        33554432 |@@@                                      43       
        67108864 |@@@@@@@@@@@@@@@@@@@@@@@@@                315      
       134217728 |                                         0        
       268435456 |                                         2        
       536870912 |                                         0        


  scsi                                                time (ns)                                         
           value  ------------- Distribution ------------- count    
           16384 |                                         0        
           32768 |                                         2        
           65536 |                                         3        
          131072 |@                                        18       
          262144 |@@                                       20       
          524288 |@@@@                                     46       
         1048576 |@@@                                      37       
         2097152 |                                         0        
         4194304 |                                         4        
         8388608 |                                         4        
        16777216 |                                         4        
        33554432 |@@@                                      43       
        67108864 |@@@@@@@@@@@@@@@@@@@@@@@@@                315      
       134217728 |                                         0        
       268435456 |                                         2        
       536870912 |                                         0        


  mega_sas                                            time (ns)                                         
           value  ------------- Distribution ------------- count    
           16384 |                                         0        
           32768 |                                         2        
           65536 |                                         5        
          131072 |@@                                       20       
          262144 |@                                        16       
          524288 |@@@@                                     50       
         1048576 |@@@                                      33       
         2097152 |                                         0        
         4194304 |                                         4        
         8388608 |                                         4        
        16777216 |                                         4        
        33554432 |@@@                                      43       
        67108864 |@@@@@@@@@@@@@@@@@@@@@@@@@                315      
       134217728 |                                         0        
       268435456 |                                         2        
       536870912 |                                         0        

mega_sas is the SAS disk device driver - which shows the true latency of the disk I/O (about as deep as the operating system can go). The first distribution printed was for zfs_read() latency, which is the read requests to ZFS.

It's hugely valuable to be able to pluck this sort of latency data out from different layers of the operating system stack, to narrow down the source of the latency. Comparing all I/O in this way can also identify the origin of outliers (few I/O with high latency) quickly, which may be hit-or-miss if single I/O were picked and traced as they executed through the kernel.

Latency at different levels of the OS stack can be examined and compared to identify the origin.

The spike of slow disk I/O seen in the mega_sas distribution (315 I/O with a latency between 67 and 134 ms), which is likely due to queueing on the disk, propagates up the stack to a point and then vanishes. That latency is not visible in the zfs_read() and zfs_write() interfaces, meaning, no application was affected by that latency (at least via read/write). The spike corresponded to a ZFS TXG flush - which is asynchronous to the application, and queues a bunch of I/O to the disks. If that spike were to propagate all the way up into zfs_read()/zfs_write(), then this output would have identified the origin - the disks.

zfsstacklatency.d

I wrote zfsstacklatency.d as a demonstration only script, to show what is technically possible. The script breaks a rule I learned the hard way: keep it simple. zfsstacklatency.d is not simple, it traces at multiple stack layers using the unstable fbt provider and is over 100 lines long. This makes it brittle and not likely to run on different kernel builds other than the system I'm on (there is little point including it here, since it almost certainly won't run for you). To trace at these layers, it can be more relibale to run small scripts that trace individual layers separately, and to maintain those invidiual scripts if and when they break on newer kernel versions. Chapter 4 of the DTrace book does this via scripts such as scsilatency.d, satalatency.d, mptlatency.d, etc.

Comparing File System Latency

By examining latency at different levels of the I/O stack, its origin can be identified. DTrace provides the ability to trace latency from the application right down to the disk device driver - leaving no stone unturned. This can be especially useful for the cases where latency is not caused by the disks, but by other issues in the kernel.

In the next and final post in this series, I'll show other useful presentations of file system latency as a metric.