EVOLUTION-MANAGER

Edit File: fslatency-nd_example.txt

Examples of fslatency-nd.stp, the Linux SystemTap version. fslatency-nd.stp dynamically traces two common file system functions: do_sync_read() and do_sync_write(). Many, but not all, file systems and workloads use these functions. Tracing their time provides one view of suffered file system latency. # ./fslatency-nd.stp Tracing FS sync reads and writes... Hit Ctrl-C to end. ^C FS latency (ns): FS call: do_sync_read() value |-------------------------------------------------- count 256 | 0 512 | 0 1024 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 4858 2048 |@@@@ 400 4096 | 3 8192 | 7 16384 | 14 32768 | 6 65536 | 3 131072 | 9 262144 | 40 524288 |@ 164 1048576 | 87 2097152 | 10 4194304 | 5 8388608 | 2 16777216 | 5 33554432 | 16 67108864 | 2 134217728 | 0 268435456 | 1 536870912 | 0 1073741824 | 0 FS call: do_sync_write() value |-------------------------------------------------- count 2048 | 0 4096 | 0 8192 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 5335 16384 |@@ 260 32768 | 32 65536 | 2 131072 | 2 262144 | 0 524288 | 0 1048576 | 0 2097152 | 0 4194304 | 1 8388608 | 0 16777216 | 0 In the above output, do_sync_read() has multiple modes. The largest, around 1 to 4 microseconds, likely corresponds to page cache hits, and spans over 5000 reads. Next is a much smaller mode around 0.5 ms, which is likely a disk read. Then a small mode around 32 ms, which would likely be disk I/O that queued. Unlike biolatency-nd.stp, fslatency-nd.stp includes cache hits. Here is a clear bimodal distribution from a random read workload: # ./fslatency-nd.stp Tracing FS sync reads and writes... Hit Ctrl-C to end. ^C FS latency (ns): FS call: do_sync_read() value |-------------------------------------------------- count 128 | 0 256 | 0 512 | 2 1024 |@ 6 2048 |@@@@@@@@@@@ 46 4096 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 134 8192 |@@@@@ 20 16384 | 2 32768 | 1 65536 | 0 131072 | 0 262144 | 1 524288 |@@ 9 1048576 | 0 2097152 |@@@@@@@@@@@@@@ 57 4194304 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 200 8388608 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 169 16777216 |@@@ 13 33554432 | 3 67108864 | 0 134217728 | 0 The first, around 4 us, is likely page cache hits. The second, around 4-8 ms, is likely page cache misses (disk reads). fslatency-nd.ntp takes an optional interval and count as arguments. Eg, to show latency every second: # ./fslatency-nd.stp 1 Tracing FS sync reads and writes... Output every 1 secs. Fri Feb 6 21:58:48 2015 FS latency (ns): FS call: do_sync_read() value |-------------------------------------------------- count 512 | 0 1024 | 0 2048 |@@@@@ 11 4096 |@@@@@@@@@@@@@ 27 8192 |@ 3 16384 | 0 32768 | 0 65536 | 0 131072 | 0 262144 | 1 524288 | 1 1048576 | 0 2097152 |@@@@ 9 4194304 |@@@@@@@@@@@@@@@@@@@@@@ 44 8388608 |@@@@@@@@@@@@@@@@@@@@@@@@@@ 52 16777216 |@@ 4 33554432 | 1 67108864 | 0 134217728 | 0 Fri Feb 6 21:58:49 2015 FS latency (ns): FS call: do_sync_read() value |-------------------------------------------------- count 512 | 0 1024 | 0 2048 |@@@@@@@@@ 9 4096 |@@@@@@@@@@@@@@@@@@@@@@@@@ 25 8192 |@@@@ 4 16384 | 0 32768 | 0 65536 | 0 131072 | 0 262144 |@ 1 524288 |@ 1 1048576 |@@ 2 2097152 |@@@@@@@@@@@@@@ 14 4194304 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 49 8388608 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 46 16777216 |@@@@@ 5 33554432 |@@ 2 67108864 | 0 134217728 | 0 Fri Feb 6 21:58:50 2015 FS latency (ns): FS call: do_sync_read() value |-------------------------------------------------- count 512 | 0 1024 | 0 2048 |@@ 5 4096 |@@@@@@@@@@@@@@@@@@@ 38 8192 |@@ 4 16384 | 0 32768 | 0 65536 | 0 131072 | 0 262144 |@ 2 524288 | 1 1048576 | 0 2097152 |@@@@@@@@@@ 21 4194304 |@@@@@@@@@@@@@@@@@@@@@ 43 8388608 |@@@@@@@@@@@@@@@@@@@@@@@@@@ 53 16777216 |@ 2 33554432 |@ 2 67108864 | 0 134217728 | 0 Fri Feb 6 21:58:51 2015 FS latency (ns): FS call: do_sync_read() value |-------------------------------------------------- count 512 | 0 1024 | 0 2048 |@@@@@@@@ 17 4096 |@@@@@@@@@@@@@@@@@@@@@@@@ 49 8192 |@ 2 16384 | 0 32768 | 0 65536 | 0 131072 | 0 262144 |@ 3 524288 | 0 1048576 | 1 2097152 |@@@@@@@@@@@@ 24 4194304 |@@@@@@@@@@@@@@@@@@@@@@@@ 48 8388608 |@@@@@@@@@@@@@@@@@@@@@@@@@@ 52 16777216 |@ 3 33554432 | 0 67108864 | 0 Fri Feb 6 21:58:52 2015 FS latency (ns): FS call: do_sync_read() value |-------------------------------------------------- count 512 | 0 1024 | 0 2048 |@@@@@@@@@@@@@ 13 4096 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 34 8192 |@@@@@ 5 16384 | 0 32768 | 0 65536 | 0 131072 | 0 262144 |@ 1 524288 |@@@@@@ 6 1048576 | 0 2097152 |@@@@@@@@@@@@@ 13 4194304 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 38 8388608 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 46 16777216 |@@@@@@@@@@@ 11 33554432 | 0 67108864 | 0 Fri Feb 6 21:58:53 2015 FS latency (ns): FS call: do_sync_read() value |-------------------------------------------------- count 512 | 0 1024 | 0 2048 |@@@@@@@ 15 4096 |@@@@@@@@@@@@@@@@@@@@ 41 8192 |@@@ 7 16384 | 0 32768 | 0 65536 | 0 131072 | 0 262144 |@ 2 524288 |@ 2 1048576 | 0 2097152 |@@@@@@@@@@ 21 4194304 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 59 8388608 |@@@@@@@@@@@@@@@@@@@@@ 42 16777216 |@@ 5 33554432 | 0 67108864 | 0