1Demonstrations of ext4slower, the Linux eBPF/bcc version. 2 3 4ext4slower shows ext4 reads, writes, opens, and fsyncs, slower than a threshold. 5For example: 6 7# ./ext4slower 8Tracing ext4 operations slower than 10 ms 9TIME COMM PID T BYTES OFF_KB LAT(ms) FILENAME 1006:35:01 cron 16464 R 1249 0 16.05 common-auth 1106:35:01 cron 16463 R 1249 0 16.04 common-auth 1206:35:01 cron 16465 R 1249 0 16.03 common-auth 1306:35:01 cron 16465 R 4096 0 10.62 login.defs 1406:35:01 cron 16464 R 4096 0 10.61 login.defs 1506:35:01 cron 16463 R 4096 0 10.63 login.defs 1606:35:01 cron 16465 R 2972 0 18.52 pam_env.conf 1706:35:01 cron 16464 R 2972 0 18.51 pam_env.conf 1806:35:01 cron 16463 R 2972 0 18.49 pam_env.conf 1906:35:01 dumpsystemstat 16473 R 128 0 12.58 date 2006:35:01 debian-sa1 16474 R 283 0 12.66 sysstat 2106:35:01 debian-sa1 16474 R 128 0 10.39 sa1 2206:35:01 dumpsystemstat 16491 R 128 0 13.22 ifconfig 2306:35:01 DumpThreads 16534 R 128 0 12.78 cut 2406:35:01 cron 16545 R 128 0 14.76 sendmail 2506:35:01 sendmail 16545 R 274 0 10.88 dynamicmaps.cf 2606:35:02 postdrop 16546 R 118 0 32.94 Universal 2706:35:02 pickup 9574 R 118 0 21.02 localtime 28[...] 29 30This shows various system tasks reading from ext4. The high latency here is 31due to disk I/O, as I had just evicted the file system cache for this example. 32 33This "latency" is measured from when the operation was issued from the VFS 34interface to the file system, to when it completed. This spans everything: 35block device I/O (disk I/O), file system CPU cycles, file system locks, run 36queue latency, etc. This is a better measure of the latency suffered by 37applications reading from the file system than measuring this down at the 38block device interface. 39 40Note that this only traces the common file system operations previously 41listed: other file system operations (eg, inode operations including 42getattr()) are not traced. 43 44 45The threshold can be provided as an argument. Eg, I/O slower than 1 ms: 46 47# ./ext4slower 1 48Tracing ext4 operations slower than 1 ms 49TIME COMM PID T BYTES OFF_KB LAT(ms) FILENAME 5006:49:17 bash 3616 R 128 0 7.75 cksum 5106:49:17 cksum 3616 R 39552 0 1.34 [ 5206:49:17 cksum 3616 R 96 0 5.36 2to3-2.7 5306:49:17 cksum 3616 R 96 0 14.94 2to3-3.4 5406:49:17 cksum 3616 R 10320 0 6.82 411toppm 5506:49:17 cksum 3616 R 65536 0 4.01 a2p 5606:49:17 cksum 3616 R 55400 0 8.77 ab 5706:49:17 cksum 3616 R 36792 0 16.34 aclocal-1.14 5806:49:17 cksum 3616 R 15008 0 19.31 acpi_listen 5906:49:17 cksum 3616 R 6123 0 17.23 add-apt-repository 6006:49:17 cksum 3616 R 6280 0 18.40 addpart 6106:49:17 cksum 3616 R 27696 0 2.16 addr2line 6206:49:17 cksum 3616 R 58080 0 10.11 ag 6306:49:17 cksum 3616 R 906 0 6.30 ec2-meta-data 6406:49:17 cksum 3616 R 6320 0 10.00 animate.im6 6506:49:17 cksum 3616 R 5680 0 18.69 anytopnm 6606:49:17 cksum 3616 R 2671 0 20.27 apport-bug 6706:49:17 cksum 3616 R 12566 0 16.72 apport-cli 6806:49:17 cksum 3616 R 1622 0 7.95 apport-unpack 6906:49:17 cksum 3616 R 10440 0 2.37 appres 7006:49:17 cksum 3616 R 48112 0 5.42 whatis 7106:49:17 cksum 3616 R 14832 0 6.24 apt 7206:49:17 cksum 3616 R 65536 0 24.74 apt-cache 7306:49:17 cksum 3616 R 27264 0 1.68 apt-cdrom 7406:49:17 cksum 3616 R 23224 0 5.31 apt-extracttemplates 7506:49:17 cksum 3616 R 65536 0 8.08 apt-ftparchive 7606:49:17 cksum 3616 R 65536 128 2.92 apt-ftparchive 7706:49:17 cksum 3616 R 65536 0 9.58 aptitude-curses 7806:49:17 cksum 3616 R 65536 128 44.25 aptitude-curses 7906:49:17 cksum 3616 R 65536 384 1.69 aptitude-curses 80[...] 81 82This time a cksum(1) command can be seen reading various files (from /usr/bin). 83 84 85A threshold of 0 will trace all operations. Warning: the output will be 86verbose, as it will include all file system cache hits. 87 88# ./ext4slower 0 89Tracing ext4 operations 90TIME COMM PID T BYTES OFF_KB LAT(ms) FILENAME 9106:58:05 supervise 1884 O 0 0 0.00 status.new 9206:58:05 supervise 1884 W 18 0 0.02 status.new 9306:58:05 supervise 1884 O 0 0 0.00 status.new 9406:58:05 supervise 1884 W 18 0 0.01 status.new 9506:58:05 supervise 15817 O 0 0 0.00 run 9606:58:05 supervise 15817 R 92 0 0.00 run 9706:58:05 supervise 15817 O 0 0 0.00 bash 9806:58:05 supervise 15817 R 128 0 0.00 bash 9906:58:05 supervise 15817 R 504 0 0.00 bash 10006:58:05 supervise 15817 R 28 0 0.00 bash 10106:58:05 supervise 15817 O 0 0 0.00 ld-2.19.so 10206:58:05 supervise 15817 R 64 0 0.00 ld-2.19.so 10306:58:05 supervise 15817 R 392 0 0.00 ld-2.19.so 10406:58:05 run 15817 O 0 0 0.00 ld.so.cache 10506:58:05 run 15817 O 0 0 0.00 libtinfo.so.5.9 10606:58:05 run 15817 R 832 0 0.00 libtinfo.so.5.9 10706:58:05 run 15817 O 0 0 0.00 libdl-2.19.so 10806:58:05 run 15817 R 832 0 0.00 libdl-2.19.so 10906:58:05 run 15817 O 0 0 0.00 libc-2.19.so 11006:58:05 run 15817 R 832 0 0.00 libc-2.19.so 11106:58:05 supervise 1876 O 0 0 0.00 status.new 11206:58:05 supervise 1876 W 18 0 0.01 status.new 11306:58:05 supervise 1895 O 0 0 0.00 status.new 11406:58:05 supervise 1895 W 18 0 0.02 status.new 11506:58:05 supervise 1876 O 0 0 0.00 status.new 11606:58:05 supervise 1876 W 18 0 0.01 status.new 11706:58:05 supervise 1872 O 0 0 0.00 status.new 11806:58:05 supervise 1872 W 18 0 0.02 status.new 11906:58:05 supervise 1895 O 0 0 0.00 status.new 12006:58:05 supervise 1895 W 18 0 0.01 status.new 12106:58:05 supervise 15818 R 92 0 0.00 run 12206:58:05 supervise 15818 O 0 0 0.00 bash 12306:58:05 supervise 15818 R 128 0 0.00 bash 12406:58:05 supervise 15818 R 504 0 0.00 bash 12506:58:05 supervise 15818 R 28 0 0.00 bash 12606:58:05 supervise 15818 O 0 0 0.00 ld-2.19.so 12706:58:05 supervise 15818 R 64 0 0.00 ld-2.19.so 12806:58:05 supervise 15818 R 392 0 0.00 ld-2.19.so 12906:58:05 supervise 15818 O 0 0 0.00 run 13006:58:05 supervise 1888 O 0 0 0.00 status.new 13106:58:05 supervise 1888 W 18 0 0.01 status.new 13206:58:05 supervise 1888 O 0 0 0.00 status.new 13306:58:05 supervise 1888 W 18 0 0.02 status.new 13406:58:05 supervise 15822 R 119 0 0.00 run 13506:58:05 supervise 15822 O 0 0 0.00 bash 13606:58:05 supervise 15822 R 128 0 0.00 bash 13706:58:05 supervise 15822 R 504 0 0.00 bash 13806:58:05 supervise 15822 R 28 0 0.00 bash 13906:58:05 supervise 15822 O 0 0 0.00 ld-2.19.so 14006:58:05 supervise 15822 R 64 0 0.00 ld-2.19.so 14106:58:05 supervise 15822 R 392 0 0.00 ld-2.19.so 14206:58:05 supervise 1892 O 0 0 0.00 status.new 14306:58:05 supervise 1892 W 18 0 0.02 status.new 14406:58:05 supervise 1892 O 0 0 0.00 status.new 14506:58:05 supervise 1892 W 18 0 0.02 status.new 14606:58:05 supervise 15820 O 0 0 0.00 run 147[...] 148 149The output now includes open operations ("O"), and writes ("W"). 150 151 152A -j option will print just the fields (parsable output, csv): 153 154# ./ext4slower -j 1 155ENDTIME_us,TASK,PID,TYPE,BYTES,OFFSET_b,LATENCY_us,FILE 156127200712278,bash,17225,R,128,0,14329,cksum 157127200722986,cksum,17225,R,3274,0,8368,command-not-found 158127200735581,cksum,17225,R,65536,0,10903,libbfd-2.24-system.so 159127200738482,cksum,17225,R,65536,131072,2419,libbfd-2.24-system.so 160127200749226,cksum,17225,R,65536,655360,8995,libbfd-2.24-system.so 161127200776273,cksum,17225,R,55080,0,25297,libbind9.so.90.0.9 162127200784688,cksum,17225,R,65536,0,7873,libblas.so.3.0 163127200787551,cksum,17225,R,65536,131072,2386,libblas.so.3.0 164127200795524,cksum,17225,R,18624,0,4947,libcpupower.so.3.13.0-49 165127200802073,cksum,17225,R,65536,0,6410,libcwidget.so.3.0.0 166127200808718,cksum,17225,R,65536,131072,6181,libcwidget.so.3.0.0 167127200829518,cksum,17225,R,65536,0,14213,libdns.so.100.2.2 168127200832916,cksum,17225,R,65536,131072,2911,libdns.so.100.2.2 169127200841044,cksum,17225,R,65536,655360,6376,libdns.so.100.2.2 170127200853646,cksum,17225,R,956,0,1022,libdumbnet.la 171127200857814,cksum,17225,R,61096,0,4111,libdumbnet.so.1.0.1 172127200869655,cksum,17225,R,65536,0,11252,libgettextlib-0.18.3.so 173127200872985,cksum,17225,R,65536,131072,2882,libgettextlib-0.18.3.so 174127200883063,cksum,17225,R,65536,0,9661,libgettextsrc-0.18.3.so 175127200884767,cksum,17225,R,65536,131072,1251,libgettextsrc-0.18.3.so 176127200904830,cksum,17225,R,65536,0,19571,libgirepository-1.0.so.1.0.0 177127200906354,cksum,17225,R,65536,131072,1080,libgirepository-1.0.so.1.0.0 178127200936047,cksum,17225,R,65536,0,28674,libGraphicsMagick.a 179127200939091,cksum,17225,R,65536,131072,2576,libGraphicsMagick.a 180127200947295,cksum,17225,R,65536,655360,6463,libGraphicsMagick.a 181127200958793,cksum,17225,R,65536,1966080,7034,libGraphicsMagick.a 182[...] 183 184This may be useful for visualizing with another tool, for example, for 185producing a scatter plot of ENDTIME vs LATENCY, to look for time-based 186patterns. 187 188 189USAGE message: 190 191# ./ext4slower -h 192usage: ext4slower [-h] [-j] [-p PID] [min_ms] 193 194Trace common ext4 file operations slower than a threshold 195 196positional arguments: 197 min_ms minimum I/O duration to trace, in ms (default 10) 198 199optional arguments: 200 -h, --help show this help message and exit 201 -j, --csv just print fields: comma-separated values 202 -p PID, --pid PID trace this PID only 203 204examples: 205 ./ext4slower # trace operations slower than 10 ms (default) 206 ./ext4slower 1 # trace operations slower than 1 ms 207 ./ext4slower -j 1 # ... 1 ms, parsable output (csv) 208 ./ext4slower 0 # trace all operations (warning: verbose) 209 ./ext4slower -p 185 # trace PID 185 only 210