1 Demonstrations of btrfsdist, the Linux eBPF/bcc version. 2 3 4 btrfsdist traces btrfs reads, writes, opens, and fsyncs, and summarizes their 5 latency as a power-of-2 histogram. For example: 6 7 # ./btrfsdist 8 Tracing btrfs operation latency... Hit Ctrl-C to end. 9 ^C 10 11 operation = '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 26 operation = 'write' 27 usecs : count distribution 28 0 -> 1 : 0 | | 29 2 -> 3 : 0 | | 30 4 -> 7 : 0 | | 31 8 -> 15 : 4 |****************************************| 32 33 operation = 'open' 34 usecs : count distribution 35 0 -> 1 : 1 |********** | 36 2 -> 3 : 4 |****************************************| 37 38 This output shows a bi-modal distribution for read latency, with a faster 39 mode of 1,308 reads that took between 2 and 3 microseconds, and a slower 40 mode of over 7,312 reads that took between 256 and 511 microseconds. It's 41 likely that the faster mode was a hit from the in-memory file system cache, 42 and the slower mode is a read from a storage device (disk). 43 44 This "latency" is measured from when the operation was issued from the VFS 45 interface to the file system, to when it completed. This spans everything: 46 block device I/O (disk I/O), file system CPU cycles, file system locks, run 47 queue latency, etc. This is a better measure of the latency suffered by 48 applications reading from the file system than measuring this down at the 49 block device interface. 50 51 Note that this only traces the common file system operations previously 52 listed: other file system operations (eg, inode operations including 53 getattr()) are not traced. 54 55 56 An optional interval and a count can be provided, as well as -m to show the 57 distributions in milliseconds. For example, two second summaries, five times: 58 59 # ./btrfsdist 2 5 60 Tracing btrfs operation latency... Hit Ctrl-C to end. 61 62 03:40:49: 63 64 operation = '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 80 03:40:51: 81 82 operation = '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 99 03:40:53: 100 101 operation = '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 119 03:40:55: 120 121 operation = '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 136 03:40:57: 137 138 operation = '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 152 This shows a read workload that begins bimodal, and eventually the second 153 mode disappears. The reason for this is that the workload cached during 154 tracing. Note that the rate also increased, with over 200k reads for the 155 final two second sample. 156 157 158 USAGE message: 159 160 # ./btrfsdist -h 161 usage: btrfsdist [-h] [-T] [-m] [-p PID] [interval] [count] 162 163 Summarize btrfs operation latency 164 165 positional arguments: 166 interval output interval, in seconds 167 count number of outputs 168 169 optional 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 175 examples: 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
