1Demonstrations of xfsdist, the Linux eBPF/bcc version. 2 3 4xfsdist traces XFS reads, writes, opens, and fsyncs, and summarizes their 5latency as a power-of-2 histogram. For example: 6 7# ./xfsdist 8Tracing XFS operation latency... Hit Ctrl-C to end. 9^C 10 11operation = '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 27operation = 'open' 28 usecs : count distribution 29 0 -> 1 : 0 | | 30 2 -> 3 : 3 |****************************************| 31 32This output shows a bi-modal distribution for read latency, with a faster 33mode of 20,686 reads that took between 8 and 15 microseconds, and a slower 34mode of over 10,000 reads that took between 64 and 1023 microseconds. It's 35likely that the faster mode was a hit from the in-memory file system cache, 36and the slower mode is a read from a storage device (disk). 37 38This "latency" is measured from when the operation was issued from the VFS 39interface to the file system, to when it completed. This spans everything: 40block device I/O (disk I/O), file system CPU cycles, file system locks, run 41queue latency, etc. This is a better measure of the latency suffered by 42applications reading from the file system than measuring this down at the 43block device interface. 44 45Note that this only traces the common file system operations previously 46listed: other file system operations (eg, inode operations including 47getattr()) are not traced. 48 49 50An optional interval and a count can be provided, as well as -m to show the 51distributions in milliseconds. For example: 52 53# ./xfsdist -m 1 5 54Tracing XFS operation latency... Hit Ctrl-C to end. 55 5610:14:15: 57 58operation = '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 66operation = 'write' 67 msecs : count distribution 68 0 -> 1 : 685 |****************************************| 69 7010:14:16: 71 72operation = '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 81operation = 'write' 82 msecs : count distribution 83 0 -> 1 : 536 |****************************************| 84 8510:14:17: 86 87operation = '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 96operation = 'write' 97 msecs : count distribution 98 0 -> 1 : 639 |****************************************| 99 10010:14:18: 101 102operation = '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 111operation = 'write' 112 msecs : count distribution 113 0 -> 1 : 556 |****************************************| 114 11510:14:19: 116 117operation = '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 126operation = 'write' 127 msecs : count distribution 128 0 -> 1 : 613 |****************************************| 129 130This shows a mixed read/write workload, where the slower read mode was around 13110 ms. 132 133 134USAGE message: 135 136# ./xfsdist -h 137usage: xfsdist [-h] [-T] [-m] [-p PID] [interval] [count] 138 139Summarize XFS operation latency 140 141positional arguments: 142 interval output interval, in seconds 143 count number of outputs 144 145optional 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 151examples: 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