1 Demonstrations of xfsdist, the Linux eBPF/bcc version. 2 3 4 xfsdist traces XFS reads, writes, opens, and fsyncs, and summarizes their 5 latency as a power-of-2 histogram. For example: 6 7 # ./xfsdist 8 Tracing XFS operation latency... Hit Ctrl-C to end. 9 ^C 10 11 operation = 'read' 12 usecs : count distribution 13 0 -> 1 : 0 | | 14 2 -> 3 : 362 | | 15 4 -> 7 : 807 |* | 16 8 -> 15 : 20686 |****************************************| 17 16 -> 31 : 512 | | 18 32 -> 63 : 4 | | 19 64 -> 127 : 2744 |***** | 20 128 -> 255 : 7127 |************* | 21 256 -> 511 : 2483 |**** | 22 512 -> 1023 : 1281 |** | 23 1024 -> 2047 : 39 | | 24 2048 -> 4095 : 5 | | 25 4096 -> 8191 : 1 | | 26 27 operation = 'open' 28 usecs : count distribution 29 0 -> 1 : 0 | | 30 2 -> 3 : 3 |****************************************| 31 32 This output shows a bi-modal distribution for read latency, with a faster 33 mode of 20,686 reads that took between 8 and 15 microseconds, and a slower 34 mode of over 10,000 reads that took between 64 and 1023 microseconds. It's 35 likely that the faster mode was a hit from the in-memory file system cache, 36 and the slower mode is a read from a storage device (disk). 37 38 This "latency" is measured from when the operation was issued from the VFS 39 interface to the file system, to when it completed. This spans everything: 40 block device I/O (disk I/O), file system CPU cycles, file system locks, run 41 queue latency, etc. This is a better measure of the latency suffered by 42 applications reading from the file system than measuring this down at the 43 block device interface. 44 45 Note that this only traces the common file system operations previously 46 listed: other file system operations (eg, inode operations including 47 getattr()) are not traced. 48 49 50 An optional interval and a count can be provided, as well as -m to show the 51 distributions in milliseconds. For example: 52 53 # ./xfsdist -m 1 5 54 Tracing XFS operation latency... Hit Ctrl-C to end. 55 56 10:14:15: 57 58 operation = 'read' 59 msecs : count distribution 60 0 -> 1 : 1366 |****************************************| 61 2 -> 3 : 86 |** | 62 4 -> 7 : 95 |** | 63 8 -> 15 : 132 |*** | 64 16 -> 31 : 72 |** | 65 66 operation = 'write' 67 msecs : count distribution 68 0 -> 1 : 685 |****************************************| 69 70 10:14:16: 71 72 operation = 'read' 73 msecs : count distribution 74 0 -> 1 : 984 |****************************************| 75 2 -> 3 : 66 |** | 76 4 -> 7 : 67 |** | 77 8 -> 15 : 104 |**** | 78 16 -> 31 : 70 |** | 79 32 -> 63 : 12 | | 80 81 operation = 'write' 82 msecs : count distribution 83 0 -> 1 : 536 |****************************************| 84 85 10:14:17: 86 87 operation = 'read' 88 msecs : count distribution 89 0 -> 1 : 1262 |****************************************| 90 2 -> 3 : 75 |** | 91 4 -> 7 : 80 |** | 92 8 -> 15 : 119 |*** | 93 16 -> 31 : 75 |** | 94 32 -> 63 : 3 | | 95 96 operation = 'write' 97 msecs : count distribution 98 0 -> 1 : 639 |****************************************| 99 100 10:14:18: 101 102 operation = 'read' 103 msecs : count distribution 104 0 -> 1 : 1070 |****************************************| 105 2 -> 3 : 58 |** | 106 4 -> 7 : 74 |** | 107 8 -> 15 : 140 |***** | 108 16 -> 31 : 60 |** | 109 32 -> 63 : 5 | | 110 111 operation = 'write' 112 msecs : count distribution 113 0 -> 1 : 556 |****************************************| 114 115 10:14:19: 116 117 operation = 'read' 118 msecs : count distribution 119 0 -> 1 : 1176 |****************************************| 120 2 -> 3 : 53 |* | 121 4 -> 7 : 94 |*** | 122 8 -> 15 : 112 |*** | 123 16 -> 31 : 77 |** | 124 32 -> 63 : 3 | | 125 126 operation = 'write' 127 msecs : count distribution 128 0 -> 1 : 613 |****************************************| 129 130 This shows a mixed read/write workload, where the slower read mode was around 131 10 ms. 132 133 134 USAGE message: 135 136 # ./xfsdist -h 137 usage: xfsdist [-h] [-T] [-m] [-p PID] [interval] [count] 138 139 Summarize XFS operation latency 140 141 positional arguments: 142 interval output interval, in seconds 143 count number of outputs 144 145 optional arguments: 146 -h, --help show this help message and exit 147 -T, --notimestamp don't include timestamp on interval output 148 -m, --milliseconds output in milliseconds 149 -p PID, --pid PID trace this PID only 150 151 examples: 152 ./xfsdist # show operation latency as a histogram 153 ./xfsdist -p 181 # trace PID 181 only 154 ./xfsdist 1 10 # print 1 second summaries, 10 times 155 ./xfsdist -m 5 # 5s summaries, milliseconds 156
