{anchor:top}
h1. {anchor:CHP-nfsv3} {{nfsv3}} Provider
The {{nfsv3}} provider provides probes for tracing NFS version 3 server activity.
h2. {anchor:CHP-NFSv3-ARGS} Arguments
All NFS operation probes have the first argument in common:
{noformat}
args[0] conninfo_t * socket connection information
{noformat}
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).
{noformat}
typedef struct conninfo {
string ci_local; /* local host address */
string ci_remote; /* remote host address */
string ci_protocol; /* protocol (ipv4, ipv6, etc) */
} conninfo_t;
{noformat}
Operation probes have their second argument in common:
{noformat}
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;
{noformat}
[Top|#top]
h2. {anchor:CHP-NFSv3-Probes} 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|#top]
h2. {anchor:CHP-NFSv3-EXAMPLES} Examples
Some simple examples of {{nfsv3}} provider usage follow.
h6. nfsv3rwsnoop.d
This DTrace scripts traces NFSv3 read and write requests, showing details of each operation:
{noformat}
#!/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);
}
{noformat}
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}}:
{noformat}
# ./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
{noformat}
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.
h6. nfsv3ops.d
This DTrace script counts NFSv3 operations by client, printing a summary every 5 seconds:
{noformat}
#!/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);
}
{noformat}
The following output shows which client is sending which NFSv3 operations:
{noformat}
# ./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
{noformat}
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|
h6. nfsv3fileio.d
This DTrace script prints a summary of file read and write bytes:
{noformat}
#!/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);
}
{noformat}
This output shows a few files were read, and one was written:
{noformat}
# ./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
{noformat}
The fields printed are:
||field||description||
|{{Rbytes}}|Bytes read for this pathname|
|{{Wbytes}}|Bytes written to this pathname|
|{{Pathname}}|Pathname of NFS file|
h6. nfsv3rwtime.d
This DTrace script prints a summary NFSv3 read and write elapsed times (latencies), along with other details:
{noformat}
#!/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);
}
{noformat}
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:
{noformat}
# ./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
{noformat}
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:
{noformat}
# ./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
{noformat}
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|
h6. nfsv3io.d
This is a simple DTrace script to provide basic I/O details by host every 5 seconds:
{noformat}
#!/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;
}
{noformat}
This output shows {{192.168.17.75}} calling NFSv3 reads and writes:
{noformat}
# ./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
{noformat}
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)|
h1. {anchor:CHP-nfsv3} {{nfsv3}} Provider
The {{nfsv3}} provider provides probes for tracing NFS version 3 server activity.
h2. {anchor:CHP-NFSv3-ARGS} Arguments
All NFS operation probes have the first argument in common:
{noformat}
args[0] conninfo_t * socket connection information
{noformat}
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).
{noformat}
typedef struct conninfo {
string ci_local; /* local host address */
string ci_remote; /* remote host address */
string ci_protocol; /* protocol (ipv4, ipv6, etc) */
} conninfo_t;
{noformat}
Operation probes have their second argument in common:
{noformat}
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;
{noformat}
[Top|#top]
h2. {anchor:CHP-NFSv3-Probes} 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|#top]
h2. {anchor:CHP-NFSv3-EXAMPLES} Examples
Some simple examples of {{nfsv3}} provider usage follow.
h6. nfsv3rwsnoop.d
This DTrace scripts traces NFSv3 read and write requests, showing details of each operation:
{noformat}
#!/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);
}
{noformat}
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}}:
{noformat}
# ./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
{noformat}
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.
h6. nfsv3ops.d
This DTrace script counts NFSv3 operations by client, printing a summary every 5 seconds:
{noformat}
#!/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);
}
{noformat}
The following output shows which client is sending which NFSv3 operations:
{noformat}
# ./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
{noformat}
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|
h6. nfsv3fileio.d
This DTrace script prints a summary of file read and write bytes:
{noformat}
#!/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);
}
{noformat}
This output shows a few files were read, and one was written:
{noformat}
# ./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
{noformat}
The fields printed are:
||field||description||
|{{Rbytes}}|Bytes read for this pathname|
|{{Wbytes}}|Bytes written to this pathname|
|{{Pathname}}|Pathname of NFS file|
h6. nfsv3rwtime.d
This DTrace script prints a summary NFSv3 read and write elapsed times (latencies), along with other details:
{noformat}
#!/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);
}
{noformat}
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:
{noformat}
# ./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
{noformat}
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:
{noformat}
# ./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
{noformat}
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|
h6. nfsv3io.d
This is a simple DTrace script to provide basic I/O details by host every 5 seconds:
{noformat}
#!/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;
}
{noformat}
This output shows {{192.168.17.75}} calling NFSv3 reads and writes:
{noformat}
# ./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
{noformat}
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)|