1Demonstrations of ext4dist, the Linux eBPF/bcc version. 2 3 4ext4dist traces ext4 reads, writes, opens, and fsyncs, and summarizes their 5latency as a power-of-2 histogram. For example: 6 7# ./ext4dist 8Tracing ext4 operation latency... Hit Ctrl-C to end. 9^C 10 11operation = 'read' 12 usecs : count distribution 13 0 -> 1 : 1210 |****************************************| 14 2 -> 3 : 126 |**** | 15 4 -> 7 : 376 |************ | 16 8 -> 15 : 86 |** | 17 16 -> 31 : 9 | | 18 32 -> 63 : 47 |* | 19 64 -> 127 : 6 | | 20 128 -> 255 : 24 | | 21 256 -> 511 : 137 |**** | 22 512 -> 1023 : 66 |** | 23 1024 -> 2047 : 13 | | 24 2048 -> 4095 : 7 | | 25 4096 -> 8191 : 13 | | 26 8192 -> 16383 : 3 | | 27 28operation = 'write' 29 usecs : count distribution 30 0 -> 1 : 0 | | 31 2 -> 3 : 0 | | 32 4 -> 7 : 0 | | 33 8 -> 15 : 75 |****************************************| 34 16 -> 31 : 5 |** | 35 36operation = 'open' 37 usecs : count distribution 38 0 -> 1 : 1278 |****************************************| 39 2 -> 3 : 40 |* | 40 4 -> 7 : 4 | | 41 8 -> 15 : 1 | | 42 16 -> 31 : 1 | | 43 44This output shows a bi-modal distribution for read latency, with a faster 45mode of less than 7 microseconds, and a slower mode of between 256 and 1023 46microseconds. The count column shows how many events fell into that latency 47range. It's likely that the faster mode was a hit from the in-memory file 48system cache, and the slower mode is a read from a storage device (disk). 49 50This "latency" is measured from when the operation was issued from the VFS 51interface to the file system, to when it completed. This spans everything: 52block device I/O (disk I/O), file system CPU cycles, file system locks, run 53queue latency, etc. This is a better measure of the latency suffered by 54applications reading from the file system than measuring this down at the 55block device interface. 56 57Note that this only traces the common file system operations previously 58listed: other file system operations (eg, inode operations including 59getattr()) are not traced. 60 61 62An optional interval and a count can be provided, as well as -m to show the 63distributions in milliseconds. For example: 64 65# ./ext4dist -m 1 5 66Tracing ext4 operation latency... Hit Ctrl-C to end. 67 6810:19:00: 69 70operation = 'read' 71 msecs : count distribution 72 0 -> 1 : 576 |****************************************| 73 2 -> 3 : 5 | | 74 4 -> 7 : 6 | | 75 8 -> 15 : 13 | | 76 16 -> 31 : 17 |* | 77 32 -> 63 : 5 | | 78 64 -> 127 : 1 | | 79 80operation = 'write' 81 msecs : count distribution 82 0 -> 1 : 20 |****************************************| 83 84operation = 'open' 85 msecs : count distribution 86 0 -> 1 : 346 |****************************************| 87 8810:19:01: 89 90operation = 'read' 91 msecs : count distribution 92 0 -> 1 : 584 |****************************************| 93 2 -> 3 : 10 | | 94 4 -> 7 : 11 | | 95 8 -> 15 : 16 |* | 96 16 -> 31 : 6 | | 97 32 -> 63 : 4 | | 98 64 -> 127 : 2 | | 99 128 -> 255 : 1 | | 100 101operation = 'write' 102 msecs : count distribution 103 0 -> 1 : 20 |****************************************| 104 105operation = 'open' 106 msecs : count distribution 107 0 -> 1 : 336 |****************************************| 108 10910:19:02: 110 111operation = 'read' 112 msecs : count distribution 113 0 -> 1 : 678 |****************************************| 114 2 -> 3 : 7 | | 115 4 -> 7 : 9 | | 116 8 -> 15 : 25 |* | 117 16 -> 31 : 10 | | 118 32 -> 63 : 3 | | 119 120operation = 'write' 121 msecs : count distribution 122 0 -> 1 : 19 |****************************************| 123 2 -> 3 : 1 |** | 124 125operation = 'open' 126 msecs : count distribution 127 0 -> 1 : 390 |****************************************| 128 12910:19:03: 130 131operation = 'read' 132 msecs : count distribution 133 0 -> 1 : 567 |****************************************| 134 2 -> 3 : 7 | | 135 4 -> 7 : 9 | | 136 8 -> 15 : 20 |* | 137 16 -> 31 : 15 |* | 138 32 -> 63 : 5 | | 139 64 -> 127 : 2 | | 140 141operation = 'write' 142 msecs : count distribution 143 0 -> 1 : 20 |****************************************| 144 145operation = 'open' 146 msecs : count distribution 147 0 -> 1 : 417 |****************************************| 148 14910:19:04: 150 151operation = 'read' 152 msecs : count distribution 153 0 -> 1 : 762 |****************************************| 154 2 -> 3 : 9 | | 155 4 -> 7 : 9 | | 156 8 -> 15 : 11 | | 157 16 -> 31 : 20 |* | 158 32 -> 63 : 4 | | 159 64 -> 127 : 1 | | 160 161operation = 'write' 162 msecs : count distribution 163 0 -> 1 : 20 |****************************************| 164 165operation = 'open' 166 msecs : count distribution 167 0 -> 1 : 427 |****************************************| 168 169This shows a mixed read/write workload. 170 171 172USAGE message: 173 174# ./ext4dist -h 175usage: ext4dist [-h] [-T] [-m] [-p PID] [interval] [count] 176 177Summarize ext4 operation latency 178 179positional arguments: 180 interval output interval, in seconds 181 count number of outputs 182 183optional arguments: 184 -h, --help show this help message and exit 185 -T, --notimestamp don't include timestamp on interval output 186 -m, --milliseconds output in milliseconds 187 -p PID, --pid PID trace this PID only 188 189examples: 190 ./ext4dist # show operation latency as a histogram 191 ./ext4dist -p 181 # trace PID 181 only 192 ./ext4dist 1 10 # print 1 second summaries, 10 times 193 ./ext4dist -m 5 # 5s summaries, milliseconds 194