| Demonstrations of ext4slower, the Linux eBPF/bcc version. |
| |
| |
| ext4slower shows ext4 reads, writes, opens, and fsyncs, slower than a threshold. |
| For example: |
| |
| # ./ext4slower |
| Tracing ext4 operations slower than 10 ms |
| TIME COMM PID T BYTES OFF_KB LAT(ms) FILENAME |
| 06:35:01 cron 16464 R 1249 0 16.05 common-auth |
| 06:35:01 cron 16463 R 1249 0 16.04 common-auth |
| 06:35:01 cron 16465 R 1249 0 16.03 common-auth |
| 06:35:01 cron 16465 R 4096 0 10.62 login.defs |
| 06:35:01 cron 16464 R 4096 0 10.61 login.defs |
| 06:35:01 cron 16463 R 4096 0 10.63 login.defs |
| 06:35:01 cron 16465 R 2972 0 18.52 pam_env.conf |
| 06:35:01 cron 16464 R 2972 0 18.51 pam_env.conf |
| 06:35:01 cron 16463 R 2972 0 18.49 pam_env.conf |
| 06:35:01 dumpsystemstat 16473 R 128 0 12.58 date |
| 06:35:01 debian-sa1 16474 R 283 0 12.66 sysstat |
| 06:35:01 debian-sa1 16474 R 128 0 10.39 sa1 |
| 06:35:01 dumpsystemstat 16491 R 128 0 13.22 ifconfig |
| 06:35:01 DumpThreads 16534 R 128 0 12.78 cut |
| 06:35:01 cron 16545 R 128 0 14.76 sendmail |
| 06:35:01 sendmail 16545 R 274 0 10.88 dynamicmaps.cf |
| 06:35:02 postdrop 16546 R 118 0 32.94 Universal |
| 06:35:02 pickup 9574 R 118 0 21.02 localtime |
| [...] |
| |
| This shows various system tasks reading from ext4. The high latency here is |
| due to disk I/O, as I had just evicted the file system cache for this example. |
| |
| This "latency" is measured from when the operation was issued from the VFS |
| interface to the file system, to when it completed. This spans everything: |
| block device I/O (disk I/O), file system CPU cycles, file system locks, run |
| queue latency, etc. This is a better measure of the latency suffered by |
| applications reading from the file system than measuring this down at the |
| block device interface. |
| |
| Note that this only traces the common file system operations previously |
| listed: other file system operations (eg, inode operations including |
| getattr()) are not traced. |
| |
| |
| The threshold can be provided as an argument. Eg, I/O slower than 1 ms: |
| |
| # ./ext4slower 1 |
| Tracing ext4 operations slower than 1 ms |
| TIME COMM PID T BYTES OFF_KB LAT(ms) FILENAME |
| 06:49:17 bash 3616 R 128 0 7.75 cksum |
| 06:49:17 cksum 3616 R 39552 0 1.34 [ |
| 06:49:17 cksum 3616 R 96 0 5.36 2to3-2.7 |
| 06:49:17 cksum 3616 R 96 0 14.94 2to3-3.4 |
| 06:49:17 cksum 3616 R 10320 0 6.82 411toppm |
| 06:49:17 cksum 3616 R 65536 0 4.01 a2p |
| 06:49:17 cksum 3616 R 55400 0 8.77 ab |
| 06:49:17 cksum 3616 R 36792 0 16.34 aclocal-1.14 |
| 06:49:17 cksum 3616 R 15008 0 19.31 acpi_listen |
| 06:49:17 cksum 3616 R 6123 0 17.23 add-apt-repository |
| 06:49:17 cksum 3616 R 6280 0 18.40 addpart |
| 06:49:17 cksum 3616 R 27696 0 2.16 addr2line |
| 06:49:17 cksum 3616 R 58080 0 10.11 ag |
| 06:49:17 cksum 3616 R 906 0 6.30 ec2-meta-data |
| 06:49:17 cksum 3616 R 6320 0 10.00 animate.im6 |
| 06:49:17 cksum 3616 R 5680 0 18.69 anytopnm |
| 06:49:17 cksum 3616 R 2671 0 20.27 apport-bug |
| 06:49:17 cksum 3616 R 12566 0 16.72 apport-cli |
| 06:49:17 cksum 3616 R 1622 0 7.95 apport-unpack |
| 06:49:17 cksum 3616 R 10440 0 2.37 appres |
| 06:49:17 cksum 3616 R 48112 0 5.42 whatis |
| 06:49:17 cksum 3616 R 14832 0 6.24 apt |
| 06:49:17 cksum 3616 R 65536 0 24.74 apt-cache |
| 06:49:17 cksum 3616 R 27264 0 1.68 apt-cdrom |
| 06:49:17 cksum 3616 R 23224 0 5.31 apt-extracttemplates |
| 06:49:17 cksum 3616 R 65536 0 8.08 apt-ftparchive |
| 06:49:17 cksum 3616 R 65536 128 2.92 apt-ftparchive |
| 06:49:17 cksum 3616 R 65536 0 9.58 aptitude-curses |
| 06:49:17 cksum 3616 R 65536 128 44.25 aptitude-curses |
| 06:49:17 cksum 3616 R 65536 384 1.69 aptitude-curses |
| [...] |
| |
| This time a cksum(1) command can be seen reading various files (from /usr/bin). |
| |
| |
| A threshold of 0 will trace all operations. Warning: the output will be |
| verbose, as it will include all file system cache hits. |
| |
| # ./ext4slower 0 |
| Tracing ext4 operations |
| TIME COMM PID T BYTES OFF_KB LAT(ms) FILENAME |
| 06:58:05 supervise 1884 O 0 0 0.00 status.new |
| 06:58:05 supervise 1884 W 18 0 0.02 status.new |
| 06:58:05 supervise 1884 O 0 0 0.00 status.new |
| 06:58:05 supervise 1884 W 18 0 0.01 status.new |
| 06:58:05 supervise 15817 O 0 0 0.00 run |
| 06:58:05 supervise 15817 R 92 0 0.00 run |
| 06:58:05 supervise 15817 O 0 0 0.00 bash |
| 06:58:05 supervise 15817 R 128 0 0.00 bash |
| 06:58:05 supervise 15817 R 504 0 0.00 bash |
| 06:58:05 supervise 15817 R 28 0 0.00 bash |
| 06:58:05 supervise 15817 O 0 0 0.00 ld-2.19.so |
| 06:58:05 supervise 15817 R 64 0 0.00 ld-2.19.so |
| 06:58:05 supervise 15817 R 392 0 0.00 ld-2.19.so |
| 06:58:05 run 15817 O 0 0 0.00 ld.so.cache |
| 06:58:05 run 15817 O 0 0 0.00 libtinfo.so.5.9 |
| 06:58:05 run 15817 R 832 0 0.00 libtinfo.so.5.9 |
| 06:58:05 run 15817 O 0 0 0.00 libdl-2.19.so |
| 06:58:05 run 15817 R 832 0 0.00 libdl-2.19.so |
| 06:58:05 run 15817 O 0 0 0.00 libc-2.19.so |
| 06:58:05 run 15817 R 832 0 0.00 libc-2.19.so |
| 06:58:05 supervise 1876 O 0 0 0.00 status.new |
| 06:58:05 supervise 1876 W 18 0 0.01 status.new |
| 06:58:05 supervise 1895 O 0 0 0.00 status.new |
| 06:58:05 supervise 1895 W 18 0 0.02 status.new |
| 06:58:05 supervise 1876 O 0 0 0.00 status.new |
| 06:58:05 supervise 1876 W 18 0 0.01 status.new |
| 06:58:05 supervise 1872 O 0 0 0.00 status.new |
| 06:58:05 supervise 1872 W 18 0 0.02 status.new |
| 06:58:05 supervise 1895 O 0 0 0.00 status.new |
| 06:58:05 supervise 1895 W 18 0 0.01 status.new |
| 06:58:05 supervise 15818 R 92 0 0.00 run |
| 06:58:05 supervise 15818 O 0 0 0.00 bash |
| 06:58:05 supervise 15818 R 128 0 0.00 bash |
| 06:58:05 supervise 15818 R 504 0 0.00 bash |
| 06:58:05 supervise 15818 R 28 0 0.00 bash |
| 06:58:05 supervise 15818 O 0 0 0.00 ld-2.19.so |
| 06:58:05 supervise 15818 R 64 0 0.00 ld-2.19.so |
| 06:58:05 supervise 15818 R 392 0 0.00 ld-2.19.so |
| 06:58:05 supervise 15818 O 0 0 0.00 run |
| 06:58:05 supervise 1888 O 0 0 0.00 status.new |
| 06:58:05 supervise 1888 W 18 0 0.01 status.new |
| 06:58:05 supervise 1888 O 0 0 0.00 status.new |
| 06:58:05 supervise 1888 W 18 0 0.02 status.new |
| 06:58:05 supervise 15822 R 119 0 0.00 run |
| 06:58:05 supervise 15822 O 0 0 0.00 bash |
| 06:58:05 supervise 15822 R 128 0 0.00 bash |
| 06:58:05 supervise 15822 R 504 0 0.00 bash |
| 06:58:05 supervise 15822 R 28 0 0.00 bash |
| 06:58:05 supervise 15822 O 0 0 0.00 ld-2.19.so |
| 06:58:05 supervise 15822 R 64 0 0.00 ld-2.19.so |
| 06:58:05 supervise 15822 R 392 0 0.00 ld-2.19.so |
| 06:58:05 supervise 1892 O 0 0 0.00 status.new |
| 06:58:05 supervise 1892 W 18 0 0.02 status.new |
| 06:58:05 supervise 1892 O 0 0 0.00 status.new |
| 06:58:05 supervise 1892 W 18 0 0.02 status.new |
| 06:58:05 supervise 15820 O 0 0 0.00 run |
| [...] |
| |
| The output now includes open operations ("O"), and writes ("W"). |
| |
| |
| A -j option will print just the fields (parsable output, csv): |
| |
| # ./ext4slower -j 1 |
| ENDTIME_us,TASK,PID,TYPE,BYTES,OFFSET_b,LATENCY_us,FILE |
| 127200712278,bash,17225,R,128,0,14329,cksum |
| 127200722986,cksum,17225,R,3274,0,8368,command-not-found |
| 127200735581,cksum,17225,R,65536,0,10903,libbfd-2.24-system.so |
| 127200738482,cksum,17225,R,65536,131072,2419,libbfd-2.24-system.so |
| 127200749226,cksum,17225,R,65536,655360,8995,libbfd-2.24-system.so |
| 127200776273,cksum,17225,R,55080,0,25297,libbind9.so.90.0.9 |
| 127200784688,cksum,17225,R,65536,0,7873,libblas.so.3.0 |
| 127200787551,cksum,17225,R,65536,131072,2386,libblas.so.3.0 |
| 127200795524,cksum,17225,R,18624,0,4947,libcpupower.so.3.13.0-49 |
| 127200802073,cksum,17225,R,65536,0,6410,libcwidget.so.3.0.0 |
| 127200808718,cksum,17225,R,65536,131072,6181,libcwidget.so.3.0.0 |
| 127200829518,cksum,17225,R,65536,0,14213,libdns.so.100.2.2 |
| 127200832916,cksum,17225,R,65536,131072,2911,libdns.so.100.2.2 |
| 127200841044,cksum,17225,R,65536,655360,6376,libdns.so.100.2.2 |
| 127200853646,cksum,17225,R,956,0,1022,libdumbnet.la |
| 127200857814,cksum,17225,R,61096,0,4111,libdumbnet.so.1.0.1 |
| 127200869655,cksum,17225,R,65536,0,11252,libgettextlib-0.18.3.so |
| 127200872985,cksum,17225,R,65536,131072,2882,libgettextlib-0.18.3.so |
| 127200883063,cksum,17225,R,65536,0,9661,libgettextsrc-0.18.3.so |
| 127200884767,cksum,17225,R,65536,131072,1251,libgettextsrc-0.18.3.so |
| 127200904830,cksum,17225,R,65536,0,19571,libgirepository-1.0.so.1.0.0 |
| 127200906354,cksum,17225,R,65536,131072,1080,libgirepository-1.0.so.1.0.0 |
| 127200936047,cksum,17225,R,65536,0,28674,libGraphicsMagick.a |
| 127200939091,cksum,17225,R,65536,131072,2576,libGraphicsMagick.a |
| 127200947295,cksum,17225,R,65536,655360,6463,libGraphicsMagick.a |
| 127200958793,cksum,17225,R,65536,1966080,7034,libGraphicsMagick.a |
| [...] |
| |
| This may be useful for visualizing with another tool, for example, for |
| producing a scatter plot of ENDTIME vs LATENCY, to look for time-based |
| patterns. |
| |
| |
| USAGE message: |
| |
| # ./ext4slower -h |
| usage: ext4slower [-h] [-j] [-p PID] [min_ms] |
| |
| Trace common ext4 file operations slower than a threshold |
| |
| positional arguments: |
| min_ms minimum I/O duration to trace, in ms (default 10) |
| |
| optional arguments: |
| -h, --help show this help message and exit |
| -j, --csv just print fields: comma-separated values |
| -p PID, --pid PID trace this PID only |
| |
| examples: |
| ./ext4slower # trace operations slower than 10 ms (default) |
| ./ext4slower 1 # trace operations slower than 1 ms |
| ./ext4slower -j 1 # ... 1 ms, parsable output (csv) |
| ./ext4slower 0 # trace all operations (warning: verbose) |
| ./ext4slower -p 185 # trace PID 185 only |
