1 Demonstrations of ext4dist, the Linux eBPF/bcc version. 2 3 4 ext4dist traces ext4 reads, writes, opens, and fsyncs, and summarizes their 5 latency as a power-of-2 histogram. For example: 6 7 # ./ext4dist 8 Tracing ext4 operation latency... Hit Ctrl-C to end. 9 ^C 10 11 operation = '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 28 operation = '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 36 operation = '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 44 This output shows a bi-modal distribution for read latency, with a faster 45 mode of less than 7 microseconds, and a slower mode of between 256 and 1023 46 microseconds. The count column shows how many events fell into that latency 47 range. It's likely that the faster mode was a hit from the in-memory file 48 system cache, and the slower mode is a read from a storage device (disk). 49 50 This "latency" is measured from when the operation was issued from the VFS 51 interface to the file system, to when it completed. This spans everything: 52 block device I/O (disk I/O), file system CPU cycles, file system locks, run 53 queue latency, etc. This is a better measure of the latency suffered by 54 applications reading from the file system than measuring this down at the 55 block device interface. 56 57 Note that this only traces the common file system operations previously 58 listed: other file system operations (eg, inode operations including 59 getattr()) are not traced. 60 61 62 An optional interval and a count can be provided, as well as -m to show the 63 distributions in milliseconds. For example: 64 65 # ./ext4dist -m 1 5 66 Tracing ext4 operation latency... Hit Ctrl-C to end. 67 68 10:19:00: 69 70 operation = '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 80 operation = 'write' 81 msecs : count distribution 82 0 -> 1 : 20 |****************************************| 83 84 operation = 'open' 85 msecs : count distribution 86 0 -> 1 : 346 |****************************************| 87 88 10:19:01: 89 90 operation = '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 101 operation = 'write' 102 msecs : count distribution 103 0 -> 1 : 20 |****************************************| 104 105 operation = 'open' 106 msecs : count distribution 107 0 -> 1 : 336 |****************************************| 108 109 10:19:02: 110 111 operation = '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 120 operation = 'write' 121 msecs : count distribution 122 0 -> 1 : 19 |****************************************| 123 2 -> 3 : 1 |** | 124 125 operation = 'open' 126 msecs : count distribution 127 0 -> 1 : 390 |****************************************| 128 129 10:19:03: 130 131 operation = '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 141 operation = 'write' 142 msecs : count distribution 143 0 -> 1 : 20 |****************************************| 144 145 operation = 'open' 146 msecs : count distribution 147 0 -> 1 : 417 |****************************************| 148 149 10:19:04: 150 151 operation = '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 161 operation = 'write' 162 msecs : count distribution 163 0 -> 1 : 20 |****************************************| 164 165 operation = 'open' 166 msecs : count distribution 167 0 -> 1 : 427 |****************************************| 168 169 This shows a mixed read/write workload. 170 171 172 USAGE message: 173 174 # ./ext4dist -h 175 usage: ext4dist [-h] [-T] [-m] [-p PID] [interval] [count] 176 177 Summarize ext4 operation latency 178 179 positional arguments: 180 interval output interval, in seconds 181 count number of outputs 182 183 optional 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 189 examples: 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
