1Demonstrations of btrfsdist, the Linux eBPF/bcc version. 2 3 4btrfsdist traces btrfs reads, writes, opens, and fsyncs, and summarizes their 5latency as a power-of-2 histogram. For example: 6 7# ./btrfsdist 8Tracing btrfs operation latency... Hit Ctrl-C to end. 9^C 10 11operation = 'read' 12 usecs : count distribution 13 0 -> 1 : 15 | | 14 2 -> 3 : 1308 |******* | 15 4 -> 7 : 198 |* | 16 8 -> 15 : 0 | | 17 16 -> 31 : 11 | | 18 32 -> 63 : 361 |* | 19 64 -> 127 : 55 | | 20 128 -> 255 : 104 | | 21 256 -> 511 : 7312 |****************************************| 22 512 -> 1023 : 387 |** | 23 1024 -> 2047 : 10 | | 24 2048 -> 4095 : 4 | | 25 26operation = 'write' 27 usecs : count distribution 28 0 -> 1 : 0 | | 29 2 -> 3 : 0 | | 30 4 -> 7 : 0 | | 31 8 -> 15 : 4 |****************************************| 32 33operation = 'open' 34 usecs : count distribution 35 0 -> 1 : 1 |********** | 36 2 -> 3 : 4 |****************************************| 37 38This output shows a bi-modal distribution for read latency, with a faster 39mode of 1,308 reads that took between 2 and 3 microseconds, and a slower 40mode of over 7,312 reads that took between 256 and 511 microseconds. It's 41likely that the faster mode was a hit from the in-memory file system cache, 42and the slower mode is a read from a storage device (disk). 43 44This "latency" is measured from when the operation was issued from the VFS 45interface to the file system, to when it completed. This spans everything: 46block device I/O (disk I/O), file system CPU cycles, file system locks, run 47queue latency, etc. This is a better measure of the latency suffered by 48applications reading from the file system than measuring this down at the 49block device interface. 50 51Note that this only traces the common file system operations previously 52listed: other file system operations (eg, inode operations including 53getattr()) are not traced. 54 55 56An optional interval and a count can be provided, as well as -m to show the 57distributions in milliseconds. For example, two second summaries, five times: 58 59# ./btrfsdist 2 5 60Tracing btrfs operation latency... Hit Ctrl-C to end. 61 6203:40:49: 63 64operation = 'read' 65 usecs : count distribution 66 0 -> 1 : 15 | | 67 2 -> 3 : 833 |******** | 68 4 -> 7 : 127 |* | 69 8 -> 15 : 0 | | 70 16 -> 31 : 8 | | 71 32 -> 63 : 907 |******** | 72 64 -> 127 : 91 | | 73 128 -> 255 : 246 |** | 74 256 -> 511 : 4164 |****************************************| 75 512 -> 1023 : 193 |* | 76 1024 -> 2047 : 4 | | 77 2048 -> 4095 : 6 | | 78 4096 -> 8191 : 2 | | 79 8003:40:51: 81 82operation = 'read' 83 usecs : count distribution 84 0 -> 1 : 25 | | 85 2 -> 3 : 1491 |*************** | 86 4 -> 7 : 218 |** | 87 8 -> 15 : 0 | | 88 16 -> 31 : 16 | | 89 32 -> 63 : 1527 |*************** | 90 64 -> 127 : 319 |*** | 91 128 -> 255 : 429 |**** | 92 256 -> 511 : 3841 |****************************************| 93 512 -> 1023 : 232 |** | 94 1024 -> 2047 : 3 | | 95 2048 -> 4095 : 6 | | 96 4096 -> 8191 : 1 | | 97 8192 -> 16383 : 1 | | 98 9903:40:53: 100 101operation = 'read' 102 usecs : count distribution 103 0 -> 1 : 27 | | 104 2 -> 3 : 2999 |********************************* | 105 4 -> 7 : 407 |**** | 106 8 -> 15 : 0 | | 107 16 -> 31 : 46 | | 108 32 -> 63 : 3538 |****************************************| 109 64 -> 127 : 595 |****** | 110 128 -> 255 : 621 |******* | 111 256 -> 511 : 3532 |*************************************** | 112 512 -> 1023 : 212 |** | 113 1024 -> 2047 : 1 | | 114 2048 -> 4095 : 0 | | 115 4096 -> 8191 : 0 | | 116 8192 -> 16383 : 0 | | 117 16384 -> 32767 : 1 | | 118 11903:40:55: 120 121operation = 'read' 122 usecs : count distribution 123 0 -> 1 : 221 | | 124 2 -> 3 : 12580 |****************************************| 125 4 -> 7 : 1366 |**** | 126 8 -> 15 : 0 | | 127 16 -> 31 : 289 | | 128 32 -> 63 : 10782 |********************************** | 129 64 -> 127 : 1232 |*** | 130 128 -> 255 : 807 |** | 131 256 -> 511 : 2299 |******* | 132 512 -> 1023 : 135 | | 133 1024 -> 2047 : 5 | | 134 2048 -> 4095 : 2 | | 135 13603:40:57: 137 138operation = 'read' 139 usecs : count distribution 140 0 -> 1 : 73951 |************************* | 141 2 -> 3 : 117639 |****************************************| 142 4 -> 7 : 7943 |** | 143 8 -> 15 : 1841 | | 144 16 -> 31 : 1143 | | 145 32 -> 63 : 5006 |* | 146 64 -> 127 : 483 | | 147 128 -> 255 : 242 | | 148 256 -> 511 : 253 | | 149 512 -> 1023 : 84 | | 150 1024 -> 2047 : 23 | | 151 152This shows a read workload that begins bimodal, and eventually the second 153mode disappears. The reason for this is that the workload cached during 154tracing. Note that the rate also increased, with over 200k reads for the 155final two second sample. 156 157 158USAGE message: 159 160# ./btrfsdist -h 161usage: btrfsdist [-h] [-T] [-m] [-p PID] [interval] [count] 162 163Summarize btrfs operation latency 164 165positional arguments: 166 interval output interval, in seconds 167 count number of outputs 168 169optional arguments: 170 -h, --help show this help message and exit 171 -T, --notimestamp don't include timestamp on interval output 172 -m, --milliseconds output in milliseconds 173 -p PID, --pid PID trace this PID only 174 175examples: 176 ./btrfsdist # show operation latency as a histogram 177 ./btrfsdist -p 181 # trace PID 181 only 178 ./btrfsdist 1 10 # print 1 second summaries, 10 times 179 ./btrfsdist -m 5 # 5s summaries, milliseconds 180