`nfsv3` Provider

The nfsv3 provider provides probes for tracing NFS version 3 server activity.

Arguments

All NFS operation probes have the first argument in common:

	args[0]		conninfo_t *		socket connection information

The conninfo_t structure is already used by the iSCSI target provider (iscsi) and the NFS v4 provider (nfsv4), and is intended for use by all provider which are providing some higher level protocol (e.g. iscsi, nfs, http, ftp).

	typedef struct conninfo {
		string ci_local;        /* local host address */
		string ci_remote;       /* remote host address */
		string ci_protocol;     /* protocol (ipv4, ipv6, etc) */
	} conninfo_t;

Operation probes have their second argument in common:

	args[1]		nfsv3opinfo_t *		NFS v3 operation properties

	typedef struct nfsv3opinfo {
		string noi_curpath;	/* current file handle path (if any) */
		cred_t *noi_cred;	/* credentials */
		uint64_t noi_xid;	/* transaction ID */
	} nfsv4opinfo_t;

Top

Probes

Below is a list of the probes along with the specific argument for each whose type is defined by the NFS v3 specification:

probe name	`args[2]`
nfsv3:::op-access-start	ACCESS3args *
nfsv3:::op-access-done	ACCESS3res *
nfsv3:::op-commit-start	COMMIT3args *
nfsv3:::op-commit-done	COMMIT3res *
nfsv3:::op-create-start	CREATE3args *
nfsv3:::op-create-done	CREATE3res *
nfsv3:::op-fsinfo-start	FSINFO3args *
nfsv3:::op-fsinfo-done	FSINFO3res *
nfsv3:::op-fsstat-start	FSSTAT3args *
nfsv3:::op-fsstat-done	FSSTAT3res *
nfsv3:::op-getattr-start	GETATTR3args *
nfsv3:::op-getattr-done	GETATTR3res *
nfsv3:::op-lookup-start	LOOKUP3args *
nfsv3:::op-lookup-done	LOOKUP3res *
nfsv3:::op-link-start	LINK3args *
nfsv3:::op-link-done	LINK3res *
nfsv3:::op-mkdir-start	MKDIR3args *
nfsv3:::op-mkdir-done	MKDIR3res *
nfsv3:::op-mknod-start	MKNOD3args *
nfsv3:::op-mknod-done	MKNOD3res *
nfsv3:::op-null-start	-
nfsv3:::op-null-done	-
nfsv3:::op-pathconf-start	PATHCONF3args *
nfsv3:::op-pathconf-done	PATHCONF3res *
nfsv3:::op-read-start	READ3args *
nfsv3:::op-read-done	READ3res *
nfsv3:::op-readdir-start	READDIR3args *
nfsv3:::op-readdir-done	READDIR3res *
nfsv3:::op-readdirplus-start	READDIRPLUS3args *
nfsv3:::op-readdirplus-done	READDIRPLUS3res *
nfsv3:::op-readlink-start	READLINK3args *
nfsv3:::op-readlink-done	READLINK3res *
nfsv3:::op-remove-start	REMOVE3args *
nfsv3:::op-remove-done	REMOVE3res *
nfsv3:::op-renamestart	RENAME3args *
nfsv3:::op-rename-done	RENAME3res *
nfsv3:::op-rmdir-start	RMDIR3args *
nfsv3:::op-rmdir-done	RMDIR3res *
nfsv3:::op-setattr-start	SETATTR3args *
nfsv3:::op-setattr-done	SETATTR3res *
nfsv3:::op-symlink-start	SYMLINK3args *
nfsv3:::op-symlink-done	SYMLINK3res *
nfsv3:::op-write-start	WRITE3args *
nfsv3:::op-write-done	WRITE3res *

Note that op-null-* probes have an undefined args[2].

Top

Examples

Some simple examples of nfsv3 provider usage follow.

nfsv3rwsnoop.d

This DTrace scripts traces NFSv3 read and write requests, showing details of each operation:

#!/usr/sbin/dtrace -s

#pragma D option quiet
#pragma D option switchrate=10hz

dtrace:::BEGIN
{
        printf("%-16s %-18s %2s %-8s %6s %s\n", "TIME(us)",
            "CLIENT", "OP", "OFFSET", "BYTES", "PATHNAME");
}

nfsv3:::op-read-start
{
        printf("%-16d %-18s %2s %-8d %6d %s\n", timestamp / 1000,
            args[0]->ci_remote, "R", args[2]->offset / 1024, args[2]->count,
            args[1]->noi_curpath);
}

nfsv3:::op-write-start
{
        printf("%-16d %-18s %2s %-8d %6d %s\n", timestamp / 1000,
            args[0]->ci_remote, "W", args[2]->offset / 1024,
            args[2]->data.data_len, args[1]->noi_curpath);
}

The following output shows a read of /export/stuff/bin/ghex2, then a read of /export/stuff/bin/gksu, and finally a write of /export/stuff/words12:

# ./nfsv3iosnoop.d
TIME(us)         CLIENT             OP OFFSET    BYTES PATHNAME 
4299383207       192.168.17.75       R 0          4096 /export/stuff/bin/ghex2
4299391813       192.168.17.75       R 4         28672 /export/stuff/bin/ghex2
4299395700       192.168.17.75       R 32        32768 /export/stuff/bin/ghex2
4299396038       192.168.17.75       R 96        32768 /export/stuff/bin/ghex2
4299396462       192.168.17.75       R 128        8192 /export/stuff/bin/ghex2
4299396550       192.168.17.75       R 64        32768 /export/stuff/bin/ghex2
4320233417       192.168.17.75       R 0          4096 /export/stuff/bin/gksu
4320240902       192.168.17.75       R 4         28672 /export/stuff/bin/gksu
4320242434       192.168.17.75       R 32        32768 /export/stuff/bin/gksu
4320242730       192.168.17.75       R 64        24576 /export/stuff/bin/gksu
4333460565       192.168.17.75       W 0         32768 /export/stuff/words12
4333461477       192.168.17.75       W 32        32768 /export/stuff/words12
4333463264       192.168.17.75       W 64        32768 /export/stuff/words12
4333463567       192.168.17.75       W 96        32768 /export/stuff/words12
4333463893       192.168.17.75       W 128       32768 /export/stuff/words12
4333464202       192.168.17.75       W 160       32768 /export/stuff/words12
4333464451       192.168.17.75       W 192       10055 /export/stuff/words12

The fields printed are:

field	description
`TIME(us)`	Time of event in microseconds
`CLIENT`	Remote client IP address
`OP`	`R` == read, `W` == write
`OFFSET`	File offset of I/O, in Kbytes
`BYTES`	Bytes of I/O
`PATHNAME`	Pathname of file, if known

Note: The output may be shuffled slightly on multi-CPU servers due to DTrace per-CPU buffering; post sort the TIME column if needed.

nfsv3ops.d

This DTrace script counts NFSv3 operations by client, printing a summary every 5 seconds:

#!/usr/sbin/dtrace -s

#pragma D option quiet

dtrace:::BEGIN
{
        trace("Tracing... Interval 5 secs.\n");
}

nfsv3:::op-*
{
        @ops[args[0]->ci_remote, probename] = count();
}

profile:::tick-5sec,
dtrace:::END
{
        printf("\n   %-32s %-28s %8s\n", "Client", "Operation", "Count");
        printa("   %-32s %-28s %@8d\n", @ops);
        trunc(@ops);
}

The following output shows which client is sending which NFSv3 operations:

# ./nfsv3ops.d
Tracing... Interval 5 secs.

   Client                           Operation                       Count
   192.168.17.75                    op-commit-done                      1
   192.168.17.75                    op-commit-start                     1
   192.168.17.75                    op-create-done                      1
   192.168.17.75                    op-create-start                     1
   192.168.17.75                    op-access-done                      6
   192.168.17.75                    op-access-start                     6
   192.168.17.75                    op-read-done                        6
   192.168.17.75                    op-read-start                       6
   192.168.17.75                    op-write-done                       7
   192.168.17.75                    op-write-start                      7
   192.168.17.75                    op-lookup-done                      8
   192.168.17.75                    op-lookup-start                     8
   192.168.17.75                    op-getattr-done                    10
   192.168.17.75                    op-getattr-start                   10
  
   Client                           Operation                       Count
   
   Client                           Operation                       Count
   192.168.17.75                    op-getattr-done                     1
   192.168.17.75                    op-getattr-start                    1

The fields printed are:

field	description
`Client`	Remote client IP address
`Operation`	NFSv3 operation, described using the `nfsv3` provider probename
`Count`	Operations during this interval

nfsv3fileio.d

This DTrace script prints a summary of file read and write bytes:

#!/usr/sbin/dtrace -s

#pragma D option quiet

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

nfsv3:::op-read-done
{
        @readbytes[args[1]->noi_curpath] = sum(args[2]->res_u.ok.data.data_len);
}


nfsv3:::op-write-done
{
        @writebytes[args[1]->noi_curpath] = sum(args[2]->res_u.ok.count);
}

dtrace:::END
{
        printf("\n%12s %12s  %s\n", "Rbytes", "Wbytes", "Pathname");
        printa("%@12d %@12d  %s\n", @readbytes, @writebytes);
}

This output shows a few files were read, and one was written:

# ./nfsv3fileio.d
Tracing... Hit Ctrl-C to end.
^C

      Rbytes       Wbytes  Pathname
           0       206663  /export/stuff/words10
        8624            0  /export/stuff/bin/echo-client-2
       13228            0  /export/stuff/bin/echo
      496292            0  /export/stuff/bin/ecpg

The fields printed are:

field	description
`Rbytes`	Bytes read for this pathname
`Wbytes`	Bytes written to this pathname
`Pathname`	Pathname of NFS file

nfsv3rwtime.d

This DTrace script prints a summary NFSv3 read and write elapsed times (latencies), 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");
}

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

nfsv3:::op-read-done,
nfsv3:::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("NFSv3 read/write distributions (us):\n");
        printa(@rw);

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

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

This output below shows a clear peak in the read time distribution plot in the 64 to 127 microsecond range, and a second smaller peak between 4 and 16 milliseconds:

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

  write                                             
           value  ------------- Distribution ------------- count    
              16 |                                         0        
              32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
              64 |                                         0        

  read                                              
           value  ------------- Distribution ------------- count    
               8 |                                         0        
              16 |@                                        1        
              32 |@                                        1        
              64 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@           36       
             128 |@                                        1        
             256 |@                                        1        
             512 |                                         0        
            1024 |                                         0        
            2048 |@                                        1        
            4096 |@@@                                      3        
            8192 |@@@                                      4        
           16384 |                                         0        


NFSv3 read/write by host (total us):

  192.168.17.75                                                 81674

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

  /export/stuff/motd                                               63
  /export/stuff/bin/daps                                         5876
  /export/stuff/bin/date                                         8150
  /export/stuff/bin/dasher                                      67584

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

The next example also shows a pair of peaks, the first around a fraction of a millisecond, the second at around 4 milliseconds:

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

  read                                              
           value  ------------- Distribution ------------- count    
               8 |                                         0        
              16 |@                                        4        
              32 |@                                        5        
              64 |@@@@@@                                   22       
             128 |@@@@                                     13       
             256 |@@@@@@@@@                                30       
             512 |@@                                       7        
            1024 |@                                        3        
            2048 |@@@                                      12       
            4096 |@@@@@@@                                  26       
            8192 |@@@@                                     15       
           16384 |@                                        2        
           32768 |                                         0        


NFSv3 read/write by host (total us):

  192.168.17.75                                                414458

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

  /export/stuff/bin/cal                                         11225
  /export/stuff/bin/cjpeg                                       11947
  /export/stuff/bin/charmap                                     12347
  /export/stuff/bin/cdda2wav.bin                                13449
  /export/stuff/bin/chkey                                       13963
  /export/stuff/bin/cputrack                                    14533
  /export/stuff/bin/catman                                      15535
  /export/stuff/bin/csslint-0.6                                 18302
  /export/stuff/bin/col                                         19926
  /export/stuff/bin/cdrecord.bin                                40622

The first peak is likely to be NFS operations hitting the memory cache, and the second those that missed and went to disk. Further use of DTrace can confirm this theory.

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

nfsv3io.d

This is a simple DTrace script to provide basic I/O details by host every 5 seconds:

#!/usr/sbin/dtrace -s

#pragma D option quiet

dtrace:::BEGIN
{
        interval = 5;
        printf("Tracing... Interval %d secs.\n", interval);
        tick = interval;
}

nfsv3:::op-*
{
        @ops[args[0]->ci_remote] = count();
}

nfsv3:::op-read-done
{
        @reads[args[0]->ci_remote] = count();
        @readbytes[args[0]->ci_remote] = sum(args[2]->res_u.ok.data.data_len);
}


nfsv3:::op-write-done
{
        @writes[args[0]->ci_remote] = count();
        @writebytes[args[0]->ci_remote] = sum(args[2]->res_u.ok.count);
}

profile:::tick-1sec
/tick-- == 0/
{
        normalize(@ops, interval);
        normalize(@reads, interval);
        normalize(@writes, interval);
        normalize(@writebytes, 1024 * interval);
        normalize(@readbytes, 1024 * interval);
        printf("\n   %-32s %6s %6s %6s %6s %8s\n", "Client", "r/s", "w/s",
            "kr/s", "kw/s", "ops/s");
        printa("   %-32s %@6d %@6d %@6d %@6d %@8d\n", @reads, @writes,
            @readbytes, @writebytes, @ops);
        trunc(@ops);
        trunc(@reads);
        trunc(@writes);
        trunc(@readbytes);
        trunc(@writebytes);
        tick = interval;
}

This output shows 192.168.17.75 calling NFSv3 reads and writes:

# ./nfsv3io.d
Tracing... Interval 5 secs.

   Client                              r/s    w/s   kr/s   kw/s    ops/s
   192.168.17.75                        27      1    686     40      100

   Client                              r/s    w/s   kr/s   kw/s    ops/s
   192.168.17.75                         0      0      0      0        8

   Client                              r/s    w/s   kr/s   kw/s    ops/s
   0.0.0.0                               0      0      0      0        0
   192.168.17.75                         2      0     28      0       18
^C

Other details can be calculated from the output, such as average read and write size (eg, 686(kr/s) / 27(r/s) = 25.4 average kr). These could also be added to the script to be printed as columns.

The fields printed are:

field	description
`Client`	Remote client IP address
`r/s`	reads per second
`w/s`	writes per second
`kr/s`	kilobytes read per second
`kw/s`	kilobytes written per second
`ops/s`	total NFSv3 operations per second (including the reads and writes)

nfsv3 Provider

nfsv3 Provider

Arguments

Probes

Examples

nfsv3rwsnoop.d

nfsv3ops.d

nfsv3fileio.d

nfsv3rwtime.d

nfsv3io.d

`nfsv3` Provider