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:

# ./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.

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