The nfsv3 provider provides probes for tracing NFS version 3 server activity.
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;
Below is a list of the probes along with the specific argument for each whose type is defined by the NFS v3 specification:
|
Some simple examples of nfsv3 provider usage follow.
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:
|
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:
|
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/ecpgThe fields printed are:
|
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
/start[args[1]->noi_xid] != 0/
{
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 67584Other 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 40622The 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:
|
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:
|