[PATCH] nfs-utils: display NFS RPC queue time for mountstats and nfs-iostat

[PATCH] nfs-utils: display NFS RPC queue time for mountstats and nfs-iostat

[Ryan Doyle]

[-- Attachment #1: Type: text/plain, Size: 326 bytes --]

Hi there

I've got a patch to display the NFS queue statistics for mountstats and nfsiostat exported in /proc/self/mountstats. The RTT and total execution time is currently displayed but I think it's also useful displaying how long the task was queued for too. If others agree, please feel free to apply it.

Cheers,
Ryan

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: report_nfs_queue_stats_v1.patch --]
[-- Type: text/x-patch; name="report_nfs_queue_stats_v1.patch", Size: 4475 bytes --]

diff --git a/tools/mountstats/mountstats.py b/tools/mountstats/mountstats.py
index a68d702..29b5f5a 100644
--- a/tools/mountstats/mountstats.py
+++ b/tools/mountstats/mountstats.py
@@ -587,6 +587,7 @@ class DeviceData:
         ops = float(rpc_stats[0])
         retrans = float(rpc_stats[1] - rpc_stats[0])
         kilobytes = float(rpc_stats[3] + rpc_stats[4]) / 1024
+        queued_for = float(rpc_stats[5])
         rtt = float(rpc_stats[6])
         exe = float(rpc_stats[7])
 
@@ -596,11 +597,13 @@ class DeviceData:
             retrans_percent = (retrans * 100) / ops
             rtt_per_op = rtt / ops
             exe_per_op = exe / ops
+            queued_for_per_op = queued_for / ops
         else:
             kb_per_op = 0.0
             retrans_percent = 0.0
             rtt_per_op = 0.0
             exe_per_op = 0.0
+            queued_for_per_op = 0.0
 
         op += ':'
         print(format(op.lower(), '<16s'), end='')
@@ -609,7 +612,8 @@ class DeviceData:
         print(format('kB/op', '>16s'), end='')
         print(format('retrans', '>16s'), end='')
         print(format('avg RTT (ms)', '>16s'), end='')
-        print(format('avg exe (ms)', '>16s'))
+        print(format('avg exe (ms)', '>16s'), end='')
+        print(format('avg queue (ms)', '>16s'))
 
         print(format((ops / sample_time), '>24.3f'), end='')
         print(format((kilobytes / sample_time), '>16.3f'), end='')
@@ -617,7 +621,8 @@ class DeviceData:
         retransmits = '{0:>10.0f} ({1:>3.1f}%)'.format(retrans, retrans_percent).strip()
         print(format(retransmits, '>16'), end='')
         print(format(rtt_per_op, '>16.3f'), end='')
-        print(format(exe_per_op, '>16.3f'))
+        print(format(exe_per_op, '>16.3f'), end='')
+        print(format(queued_for_per_op, '>16.3f'))
 
     def display_iostats(self, sample_time):
         """Display NFS and RPC stats in an iostat-like way
diff --git a/tools/nfs-iostat/nfs-iostat.py b/tools/nfs-iostat/nfs-iostat.py
index 577a23d..0d8b216 100644
--- a/tools/nfs-iostat/nfs-iostat.py
+++ b/tools/nfs-iostat/nfs-iostat.py
@@ -326,6 +326,7 @@ class DeviceData:
         ops = float(rpc_stats[0])
         retrans = float(rpc_stats[1] - rpc_stats[0])
         kilobytes = float(rpc_stats[3] + rpc_stats[4]) / 1024
+        queued_for = float(rpc_stats[5])
         rtt = float(rpc_stats[6])
         exe = float(rpc_stats[7])
 
@@ -335,11 +336,13 @@ class DeviceData:
             retrans_percent = (retrans * 100) / ops
             rtt_per_op = rtt / ops
             exe_per_op = exe / ops
+            queued_for_per_op = queued_for / ops
         else:
             kb_per_op = 0.0
             retrans_percent = 0.0
             rtt_per_op = 0.0
             exe_per_op = 0.0
+            queued_for_per_op = 0.0
 
         op += ':'
         print(format(op.lower(), '<16s'), end='')
@@ -348,7 +351,8 @@ class DeviceData:
         print(format('kB/op', '>16s'), end='')
         print(format('retrans', '>16s'), end='')
         print(format('avg RTT (ms)', '>16s'), end='')
-        print(format('avg exe (ms)', '>16s'))
+        print(format('avg exe (ms)', '>16s'), end='')
+        print(format('avg queue (ms)', '>16s'))
 
         print(format((ops / sample_time), '>24.3f'), end='')
         print(format((kilobytes / sample_time), '>16.3f'), end='')
@@ -356,7 +360,8 @@ class DeviceData:
         retransmits = '{0:>10.0f} ({1:>3.1f}%)'.format(retrans, retrans_percent).strip()
         print(format(retransmits, '>16'), end='')
         print(format(rtt_per_op, '>16.3f'), end='')
-        print(format(exe_per_op, '>16.3f'))
+        print(format(exe_per_op, '>16.3f'), end='')
+        print(format(queued_for_per_op, '>16.3f'))
 
     def ops(self, sample_time):
         sends = float(self.__rpc_data['rpcsends'])
diff --git a/tools/nfs-iostat/nfsiostat.man b/tools/nfs-iostat/nfsiostat.man
index b477a9a..9ae94c5 100644
--- a/tools/nfs-iostat/nfsiostat.man
+++ b/tools/nfs-iostat/nfsiostat.man
@@ -90,6 +90,13 @@ This is the duration from the time that NFS client does the RPC request to its k
 .RE
 .RE
 .RE
+.RS 8
+- \fBavg queue (ms)\fR
+.RS
+This is the duration from the time the NFS client created the RPC request task to the time the request is transmitted.
+.RE
+.RE
+.RE
 .TP
 Note that if an interval is used as argument to \fBnfsiostat\fR, then the diffrence from previous interval will be displayed, otherwise the results will be from the time that the share was mounted.
 

Re: [PATCH] nfs-utils: display NFS RPC queue time for mountstats and nfs-iostat

[Steve Dickson]

On 10/29/2017 11:30 PM, Ryan Doyle wrote:
> Hi there
> 
> I've got a patch to display the NFS queue statistics for mountstats and nfsiostat exported in /proc/self/mountstats. The RTT and total execution time is currently displayed but I think it's also useful displaying how long the task was queued for too. If others agree, please feel free to apply it.

In the future please use the proper format for posting
a patch that is described in 
    https://www.kernel.org/doc/html/v4.12/process/submitting-patches.html

Basically, inline the patch, have a subject and description
section and a proper Signed-off-by: line. But since I 
found another bug while testing your patch and I'm about
to make a release I'll go ahead and add the Signed-off-by: line

Patch committed! 

steved.