nfsv4rwtime.d Reports Read and Writer Elapsed Times

This DTrace script prints a summary NFS version 4 read and write elapsed times, along with other details:

#!/usr/sbin/dtrace -s

#pragma D option quiet

inline int TOP_FILES = 10;

dtrace:::BEGIN
{
        printf("Tracing... Hit Ctrl-C to end.\n");
}

nfsv4:::op-read-start,
nfsv4:::op-write-start
{
        start[args[1]->noi_xid] = timestamp;
}

nfsv4:::op-read-done,
nfsv4:::op-write-done
{
        this->elapsed = timestamp - start[args[1]->noi_xid];
        @rw[probename == "op-read-done" ? "read" : "write"] =
            quantize(this->elapsed / 1000);
        @host[args[0]->ci_remote] = sum(this->elapsed);
        @file[args[1]->noi_curpath] = sum(this->elapsed);
        start[args[1]->noi_xid] = 0;
}

dtrace:::END
{
        printf("NFSv4 read/write distributions (us):\n");
        printa(@rw);

        printf("\nNFSv4 read/write by host (total us):\n");
        normalize(@host, 1000);
        printa(@host);

        printf("\nNFSv4 read/write top %d files (total us):\n", TOP_FILES);
        normalize(@file, 1000);
        trunc(@file, TOP_FILES);
        printa(@file);
}

This output below shows a peak in the read time distribution plot in the 64 to 127 microsecond range, and a second peak between 2 and 8 milliseconds:

# ./nfsv4rwtime.d 
Tracing... Hit Ctrl-C to end.
^C
NFSv4 read/write distributions (us):

  write                                             
           value  ------------- Distribution ------------- count    
              32 |                                         0        
              64 |@@@@@@                                   1        
             128 |@@@@@@@@@@@                              2        
             256 |@@@@@@@@@@@@@@@@@                        3        
             512 |@@@@@@                                   1        
            1024 |                                         0        

  read                                              
           value  ------------- Distribution ------------- count    
              16 |                                         0        
              32 |@@@@                                     6        
              64 |@@@@@@@@@@@@                             17       
             128 |@                                        1        
             256 |@@                                       3        
             512 |@                                        1        
            1024 |@@                                       3        
            2048 |@@@@@@@@                                 12       
            4096 |@@@@@@@@@@                               15       
            8192 |@                                        1        
           16384 |                                         0        


NFSv4 read/write by host (total us):

  192.0.2.14                                                148215

NFSv4 read/write top 10 files (total us):

  /export/share/bin/man                                          5020
  /export/share/bin/makeuuid                                     5132
  /export/share/bin/mc68030                                      5836
  /export/share/bin/m4                                           6446
  /export/share/bin/msgfmt                                       6669
  /export/share/bin/mkmsgs                                       6674
  /export/share/bin/mailstats                                    6935
  /export/share/bin/mkdir                                        7009
  /export/share/bin/mac                                          7693
  /export/share/bin/make                                        27903

Other details are printed, such as total read/write latency by host, and the top 10 files by latency.

The first peak in the read distribution is likely to be NFS operations hitting the memory cache, and the second those that missed and read from disk. The writes were all fast as they are likely to written to the memory cache and returned asynchronously. Further use of DTrace can confirm these theories.

The fields from the distribution plot are:

Field	Description
value	Minimum elapsed time for this event in microseconds
count	Number of events in this time range