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:

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:

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:

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:

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:

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:

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.

Print Friendly
Posted on May 24, 2011 at 5:57 pm by Brendan Gregg · Permalink
In: Performance · Tagged with: , , , ,

2 Responses

Subscribe to comments via RSS

  1. Written by links for 2011-05-27 « Dan Creswell’s Linkblog
    on May 27, 2011 at 5:05 am
    Permalink

    [...] Brendan's blog » File System Latency: part 4 (tags: filesystem performance solaris dtrace latency) [...]

  2. [...] might find Brendan Gregg’s recent blog series on filesystem latency useful. He shows a couple of scripts for investigating filesystem usage with the syscall provider [...]

Subscribe to comments via RSS