Demonstrations of nfsslower, the Linux eBPF/bcc version.
nfsslower show NFS reads, writes, opens and getattrs, slower than a
threshold. For example:
./nfsslower.py
Tracing NFS operations that are slower than 10 ms
TIME COMM PID T BYTES OFF_KB LAT(ms) FILENAME
11:25:16 dd 21295 W 1048576 15360 14.84 1.test
11:25:16 dd 21295 W 1048576 16384 12.73 1.test
11:25:16 dd 21295 W 1048576 17408 24.27 1.test
11:25:16 dd 21295 W 1048576 18432 22.93 1.test
11:25:16 dd 21295 W 1048576 19456 14.65 1.test
11:25:16 dd 21295 W 1048576 20480 12.58 1.test
11:25:16 dd 21297 W 1048576 6144 10.50 1.test.w
11:25:16 dd 21297 W 1048576 7168 16.65 1.test.w
11:25:16 dd 21297 W 1048576 8192 13.01 1.test.w
11:25:16 dd 21297 W 1048576 9216 14.06 1.test.w
This shows NFS writes from dd each 1MB in size to 2 different files. The
writes all had latency higher than 10ms.
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:
RPC latency, network latency, file system CPU cycles, file system locks, run
queue latency, etc. This is a better measure of the latency suffered by
applications reading from a NFS share and can better expose problems
experienced by NFS clients.
Note that this only traces the common NFS operations (read,write,open and
getattr). I chose to include getattr as a significant percentage of NFS
traffic end up being getattr calls and are a good indicator of problems
with an NFS server.
The threshold can be provided as an argument. E.g. I/O slower than 1 ms:
./nfsslower.py 1
Tracing NFS operations that are slower than 1 ms
TIME COMM PID T BYTES OFF_KB LAT(ms) FILENAME
11:40:16 cp 21583 R 131072 0 4.35 1.test
11:40:16 cp 21583 R 131072 256 1.87 1.test
11:40:16 cp 21583 R 131072 384 2.99 1.test
11:40:16 cp 21583 R 131072 512 4.19 1.test
11:40:16 cp 21583 R 131072 640 4.25 1.test
11:40:16 cp 21583 R 131072 768 4.65 1.test
11:40:16 cp 21583 R 131072 1280 1.08 1.test
11:40:16 cp 21583 R 131072 1408 3.29 1.test
11:40:16 cp 21583 R 131072 1792 3.12 1.test
11:40:16 cp 21583 R 131072 3712 3.55 1.test
11:40:16 cp 21583 R 131072 3840 1.12 1.test
11:40:16 cp 21583 R 131072 4096 3.23 1.test
11:40:16 cp 21583 R 131072 4224 2.73 1.test
11:40:16 cp 21583 R 131072 4352 2.73 1.test
11:40:16 cp 21583 R 131072 4480 6.09 1.test
11:40:16 cp 21583 R 131072 5120 4.40 1.test
[...]
This shows all NFS_READS that were more than 1ms. Depending on your
latency to your fileserver, you might need to tweak this value to
remove
A threshold of 0 will trace all operations. Warning: the output will be
verbose, as it will include all file system cache hits.
./nfsslower.py 0
Tracing NFS operations
11:56:50 dd 21852 W 1048576 0 0.42 1.test
11:56:50 dd 21852 W 1048576 1024 0.46 1.test
11:56:50 dd 21852 W 1048576 2048 0.36 1.test
11:56:50 cp 21854 G 0 0 0.35 1.test
11:56:50 cp 21854 O 0 0 0.33 1.test
11:56:50 cp 21854 G 0 0 0.00 1.test
11:56:50 cp 21854 R 131072 0 0.07 1.test
11:56:50 cp 21854 R 131072 128 0.02 1.test
11:56:50 cp 21854 R 131072 256 0.02 1.test
11:56:50 cp 21854 R 131072 384 0.02 1.test
11:56:50 cp 21854 R 131072 512 0.02 1.test
11:56:50 cp 21854 R 131072 640 0.02 1.test
11:56:50 cp 21854 R 131072 768 0.02 1.test
11:56:50 cp 21854 R 131072 896 0.02 1.test
11:56:50 cp 21854 R 131072 1024 0.02 1.test
11:56:50 cp 21854 R 131072 1152 0.02 1.test
11:56:50 cp 21854 R 131072 1280 0.02 1.test
11:56:50 cp 21854 R 131072 1408 0.02 1.test
11:56:50 cp 21854 R 131072 1536 0.02 1.test
11:56:50 cp 21854 R 131072 1664 0.02 1.test
11:56:50 cp 21854 R 131072 1792 0.02 1.test
11:56:50 cp 21854 R 131072 1920 0.02 1.test
11:56:50 cp 21854 R 131072 2048 0.02 1.test
11:56:50 cp 21854 R 131072 2176 0.04 1.test
11:56:50 cp 21854 R 131072 2304 0.02 1.test
11:56:50 cp 21854 R 131072 2432 0.03 1.test
11:56:50 cp 21854 R 131072 2560 0.03 1.test
11:56:50 cp 21854 R 131072 2688 0.02 1.test
11:56:50 cp 21854 R 131072 2816 0.03 1.test
11:56:50 cp 21854 R 131072 2944 0.02 1.test
11:56:50 cp 21854 R 0 3072 0.00 1.test
11:56:50 ls 21855 G 0 0 0.00 1.test
11:56:50 ls 21856 G 0 0 0.36 music
11:56:50 ls 21856 G 0 0 0.00 music
11:56:50 ls 21856 G 0 0 0.00 test
11:56:50 ls 21856 G 0 0 0.00 ff
11:56:50 ls 21856 G 0 0 0.00 34.log
11:56:50 ls 21856 G 0 0 0.00 vmlinuz-linux
11:56:50 ls 21856 G 0 0 0.00 2.test
11:56:50 ls 21856 G 0 0 0.00 rt.log
11:56:50 ls 21856 G 0 0 0.00 1.lod
11:56:50 ls 21856 G 0 0 0.00 COPYRIGHT.txt
11:56:50 ls 21856 G 0 0 0.00 gg
11:56:50 ls 21856 G 0 0 0.00 qw.log
11:56:50 ls 21856 G 0 0 0.00 README.md
11:56:50 ls 21856 G 0 0 0.00 1.log
The output now includes open operations ("O"), and reads ("R") wand getattrs ("G").
A cp operation
A -j option will print just the fields (parsable output, csv):
./nfsslower.py -j 0
ENDTIME_us,TASK,PID,TYPE,BYTES,OFFSET_b,LATENCY_us,FILE
87054476520,dd,22754,W,1048576,0,425,1.test
87054482916,dd,22754,W,1048576,1048576,320,1.test
87054488179,dd,22754,W,1048576,2097152,389,1.test
87054511340,cp,22756,G,0,0,371,1.test
87054511685,cp,22756,O,0,0,306,1.test
87054511700,cp,22756,G,0,0,2,1.test
87054512325,cp,22756,R,131072,0,56,1.test
87054512432,cp,22756,R,131072,131072,22,1.test
87054512520,cp,22756,R,131072,262144,32,1.test
87054512600,cp,22756,R,131072,393216,21,1.test
87054512678,cp,22756,R,131072,524288,21,1.test
87054512803,cp,22756,R,131072,655360,56,1.test
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:
usage: nfsslower.py [-h] [-j] [-p PID] [min_ms]
Trace READ, WRITE, OPEN and GETATTR NFS calls slower than a threshold,supports NFSv{3,4}
positional arguments:
min_ms Minimum IO duration to trace in ms (default=10ms)
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
./nfsslower # trace operations slower than 10ms
./nfsslower 1 # trace operations slower than 1ms
./nfsslower -j 1 # ... 1 ms, parsable output (csv)
./nfsslower 0 # trace all nfs operations
./nfsslower -p 121 # trace pid 121 only
