Demonstrations of ext4dist, the Linux eBPF/bcc version.


ext4dist traces ext4 reads, writes, opens, and fsyncs, and summarizes their
latency as a power-of-2 histogram. For example:

Note: only synchronous O_DIRECT writes are measured. Buffered/asynchronous
writes (eg, via libaio) complete after this tool's return probe fires, so
their real completion time isn't captured; including them would show
misleadingly low latency.

# ./ext4dist
Tracing ext4 operation latency... Hit Ctrl-C to end.
^C

operation = 'read'
     usecs               : count     distribution
         0 -> 1          : 1210     |****************************************|
         2 -> 3          : 126      |****                                    |
         4 -> 7          : 376      |************                            |
         8 -> 15         : 86       |**                                      |
        16 -> 31         : 9        |                                        |
        32 -> 63         : 47       |*                                       |
        64 -> 127        : 6        |                                        |
       128 -> 255        : 24       |                                        |
       256 -> 511        : 137      |****                                    |
       512 -> 1023       : 66       |**                                      |
      1024 -> 2047       : 13       |                                        |
      2048 -> 4095       : 7        |                                        |
      4096 -> 8191       : 13       |                                        |
      8192 -> 16383      : 3        |                                        |

operation = 'write'
     usecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 75       |****************************************|
        16 -> 31         : 5        |**                                      |

operation = 'open'
     usecs               : count     distribution
         0 -> 1          : 1278     |****************************************|
         2 -> 3          : 40       |*                                       |
         4 -> 7          : 4        |                                        |
         8 -> 15         : 1        |                                        |
        16 -> 31         : 1        |                                        |

This output shows a bi-modal distribution for read latency, with a faster
mode of less than 7 microseconds, and a slower mode of between 256 and 1023
microseconds. The count column shows how many events fell into that latency
range. It's likely that the faster mode was a hit from the in-memory file
system cache, and the slower mode is a read from a storage device (disk).

This "latency" is measured from when the operation was issued from the VFS
interface to the file system, to when it completed. This spans everything:
block device I/O (disk I/O), file system CPU cycles, file system locks, run
queue latency, etc. This is a better measure of the latency suffered by
applications reading from the file system than measuring this down at the
block device interface. For writes, this only holds for synchronous O_DIRECT
requests, per the note above.

Note that this only traces the common file system operations previously
listed: other file system operations (eg, inode operations including
getattr()) are not traced.


An optional interval and a count can be provided, as well as -m to show the
distributions in milliseconds. For example:

# ./ext4dist -m 1 5
Tracing ext4 operation latency... Hit Ctrl-C to end.

10:19:00:

operation = 'read'
     msecs               : count     distribution
         0 -> 1          : 576      |****************************************|
         2 -> 3          : 5        |                                        |
         4 -> 7          : 6        |                                        |
         8 -> 15         : 13       |                                        |
        16 -> 31         : 17       |*                                       |
        32 -> 63         : 5        |                                        |
        64 -> 127        : 1        |                                        |

operation = 'write'
     msecs               : count     distribution
         0 -> 1          : 20       |****************************************|

operation = 'open'
     msecs               : count     distribution
         0 -> 1          : 346      |****************************************|

10:19:01:

operation = 'read'
     msecs               : count     distribution
         0 -> 1          : 584      |****************************************|
         2 -> 3          : 10       |                                        |
         4 -> 7          : 11       |                                        |
         8 -> 15         : 16       |*                                       |
        16 -> 31         : 6        |                                        |
        32 -> 63         : 4        |                                        |
        64 -> 127        : 2        |                                        |
       128 -> 255        : 1        |                                        |

operation = 'write'
     msecs               : count     distribution
         0 -> 1          : 20       |****************************************|

operation = 'open'
     msecs               : count     distribution
         0 -> 1          : 336      |****************************************|

10:19:02:

operation = 'read'
     msecs               : count     distribution
         0 -> 1          : 678      |****************************************|
         2 -> 3          : 7        |                                        |
         4 -> 7          : 9        |                                        |
         8 -> 15         : 25       |*                                       |
        16 -> 31         : 10       |                                        |
        32 -> 63         : 3        |                                        |

operation = 'write'
     msecs               : count     distribution
         0 -> 1          : 19       |****************************************|
         2 -> 3          : 1        |**                                      |

operation = 'open'
     msecs               : count     distribution
         0 -> 1          : 390      |****************************************|

10:19:03:

operation = 'read'
     msecs               : count     distribution
         0 -> 1          : 567      |****************************************|
         2 -> 3          : 7        |                                        |
         4 -> 7          : 9        |                                        |
         8 -> 15         : 20       |*                                       |
        16 -> 31         : 15       |*                                       |
        32 -> 63         : 5        |                                        |
        64 -> 127        : 2        |                                        |

operation = 'write'
     msecs               : count     distribution
         0 -> 1          : 20       |****************************************|

operation = 'open'
     msecs               : count     distribution
         0 -> 1          : 417      |****************************************|

10:19:04:

operation = 'read'
     msecs               : count     distribution
         0 -> 1          : 762      |****************************************|
         2 -> 3          : 9        |                                        |
         4 -> 7          : 9        |                                        |
         8 -> 15         : 11       |                                        |
        16 -> 31         : 20       |*                                       |
        32 -> 63         : 4        |                                        |
        64 -> 127        : 1        |                                        |

operation = 'write'
     msecs               : count     distribution
         0 -> 1          : 20       |****************************************|

operation = 'open'
     msecs               : count     distribution
         0 -> 1          : 427      |****************************************|

This shows a mixed read/write workload.


USAGE message:

# ./ext4dist -h
usage: ext4dist [-h] [-T] [-m] [-p PID] [interval] [count]

Summarize ext4 operation latency

positional arguments:
  interval            output interval, in seconds
  count               number of outputs

optional arguments:
  -h, --help          show this help message and exit
  -T, --notimestamp   don't include timestamp on interval output
  -m, --milliseconds  output in milliseconds
  -p PID, --pid PID   trace this PID only

examples:
    ./ext4dist            # show operation latency as a histogram
    ./ext4dist -p 181     # trace PID 181 only
    ./ext4dist 1 10       # print 1 second summaries, 10 times
    ./ext4dist -m 5       # 5s summaries, milliseconds
