nfsslower: trace slow NFS operations

* Initial commit of nfsslower, tracking NFS4_READ, NFS4_WRITE and NFS4_OPEN

* Added in documentation, examples, support for csv and tracing for GETATTR

* Added in man pages, READM mods and example file, to comply with
https://github.com/samuelnair/bcc/blob/master/CONTRIBUTING-SCRIPTS.md

* Changes to address comments from @brendangregg and a small bug regarding
the output header not being printed when tracing all NFS operations

* Added nfsslower to the correct alphabetical postion

* Addressing Sasha's comments. I appreciate the thoroughness of the review

* Added test case for nfsslower and an extra function to check if the NFS kernel
module is loaded

README.md

@@ -117,6 +117,7 @@ pair of .c and .py files, and some are directories of files.
 - tools/[mdflush](tools/mdflush.py): Trace md flush events. [Examples](tools/mdflush_example.txt).
 - tools/[mysqld_qslower](tools/mysqld_qslower.py): Trace MySQL server queries slower than a threshold. [Examples](tools/mysqld_qslower_example.txt).
 - tools/[memleak](tools/memleak.py): Display outstanding memory allocations to find memory leaks. [Examples](tools/memleak_example.txt).
+- tools/[nfsslower](tools/nfsslower.py): Trace slow NFS operations. [Examples](tools/nfsslower_example.txt).
 - tools/[offcputime](tools/offcputime.py): Summarize off-CPU time by kernel stack trace. [Examples](tools/offcputime_example.txt).
 - tools/[offwaketime](tools/offwaketime.py): Summarize blocked time by kernel off-CPU stack and waker stack. [Examples](tools/offwaketime_example.txt).
 - tools/[oomkill](tools/oomkill.py): Trace the out-of-memory (OOM) killer. [Examples](tools/oomkill_example.txt).

man/man8/nfsslower.8

@@ -0,0 +1,122 @@
+.TH nfsslower 8  "2017-09-01" "USER COMMANDS"
+.SH NAME
+nfsslower \- Trace slow NFS file operations, with per-event details.
+.SH SYNOPSIS
+.B nfsslower [\-h] [\-j] [\-p PID] [min_ms]
+.SH DESCRIPTION
+This tool traces common NFSv3 & NFSv4 file operations: reads, writes, opens, and
+getattrs. It measures the time spent in these operations, and prints details
+for each that exceeded a threshold.
+
+WARNING: See the OVERHEAD section.
+
+By default, a minimum millisecond threshold of 10 is used. If a threshold of 0
+is used, all events are printed (warning: verbose).
+
+Since this works by tracing the nfs_file_operations interface functions, it
+will need updating to match any changes to these functions.
+
+This tool uses kprobes to instrument the kernel for entry and exit
+information, in the future a preferred way would be to use tracepoints.
+Currently there aren't any tracepoints available for nfs_read_file,
+nfs_write_file and nfs_open_file, nfs_getattr does have entry and exit
+tracepoints but we chose to use kprobes for consistency
+
+Since this uses BPF, only the root user can use this tool.
+.SH REQUIREMENTS
+CONFIG_BPF and bcc.
+.SH OPTIONS
+\-p PID
+Trace this PID only.
+.TP
+\-j
+Trace output in CSV format.
+.TP
+min_ms
+Minimum I/O latency (duration) to trace, in milliseconds. Default is 10 ms.
+.SH EXAMPLES
+.TP
+Trace synchronous file reads and writes slower than 10 ms:
+#
+.B nfsslower
+.TP
+Trace slower than 1 ms:
+#
+.B nfsslower 1
+.TP
+Trace slower than 1 ms, and output just the fields in parsable format (CSV):
+#
+.B nfsslower \-j 1
+.TP
+Trace all file reads and writes (warning: the output will be verbose):
+#
+.B nfsslower 0
+.TP
+Trace slower than 1 ms, for PID 181 only:
+#
+.B nfsslower \-p 181 1
+.SH FIELDS
+.TP
+TIME(s)
+Time of I/O completion since the first I/O seen, in seconds.
+.TP
+COMM
+Process name.
+.TP
+PID
+Process ID.
+.TP
+T
+Type of operation. R == read, W == write, O == open, G == getattr.
+.TP
+OFF_KB
+File offset for the I/O, in Kbytes.
+.TP
+BYTES
+Size of I/O, in bytes.
+.TP
+LAT(ms)
+Latency (duration) of I/O, measured from when it was issued by VFS to the
+filesystem, to when it completed. This time is inclusive of RPC latency,
+network latency, cache lookup, remote fileserver processing latency, etc. 
+Its a more accurate measure of the latency suffered by applications performing
+NFS read/write calls to a fileserver.
+.TP
+FILENAME
+A cached kernel file name (comes from dentry->d_iname).
+.TP
+ENDTIME_us
+Completion timestamp, microseconds (\-j only).
+.TP
+OFFSET_b
+File offset, bytes (\-j only).
+.TP
+LATENCY_us
+Latency (duration) of the I/O, in microseconds (\-j only).
+.SH OVERHEAD
+This adds low-overhead instrumentation to NFS operations,
+including reads and writes from the file system cache. Such read, writes and
+particularly getattrs can be very frequent (depending on the workload; eg, 1M/sec),
+at which point the overhead of this tool (even if it prints no "slower" events) can
+begin to become significant. Measure and quantify before use. If this
+continues to be a problem, consider switching to a tool that prints in-kernel
+summaries only. This tool has been tested with NFSv3 & NVSv4, but it might work
+with NFSv{1,2}, since it is tracing the generic functions from nfs_file_operations.
+.PP
+Note that the overhead of this tool should be less than fileslower(8), as
+this tool targets NFS functions only, and not all file read/write paths.
+.SH SOURCE
+This is from bcc.
+.IP
+https://github.com/iovisor/bcc
+.PP
+Also look in the bcc distribution for a companion nfsslower_examples.txt file containing
+example usage, output, and commentary for this tool.
+.SH OS
+Linux
+.SH STABILITY
+Unstable - in development.
+.SH AUTHOR
+Samuel Nair
+.SH SEE ALSO
+biosnoop(8), funccount(8), fileslower(8)

tests/python/test_tools_smoke.py

@@ -5,6 +5,7 @@
 import distutils.version
 import subprocess
 import os
+import re
 from unittest import main, skipUnless, TestCase
 
 TOOLS_DIR = "../../tools/"
@@ -50,6 +51,14 @@ def run_with_int(self, command, timeout=5, kill_timeout=5,
         self.assertTrue((rc == 0 and allow_early) or rc == 124
                         or (rc == 137 and kill), "rc was %d" % rc)
 
+    def kmod_loaded(self, mod):
+        mods = open("/proc/modules", "r")
+        reg = re.compile("^%s\s" % mod)
+        for line in mods:
+            if reg.match(line):
+                return 1
+            return 0
+
     def setUp(self):
         pass
 
@@ -209,6 +218,13 @@ def test_mysqld_qslower(self):
         # MySQL to be running, or it fails to attach.
         pass
 
+    @skipUnless(kernel_version_ge(4,4), "requires kernel >= 4.4")
+    def test_nfsslower(self):
+        if(self.kmod_loaded("nfs")):
+            self.run_with_int("nfsslower.py")
+        else:
+            pass
+
     @skipUnless(kernel_version_ge(4,6), "requires kernel >= 4.6")
     def test_offcputime(self):
         self.run_with_duration("offcputime.py 1")