nfsv3rwtime.d Reports Read and Write Elapsed Times
This DTrace script prints a summary NFS version 3 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");
}
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.0.2.75 14089
NFSv4 read/write top 10 files (total us):
/export/stuff/motd 63
/export/stuff/bin/daps 5876
/export/stuff/bin/date 8150Other 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.0.2.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:
| Field | Description |
|---|---|
|
|
Minimum elapsed time for this event in microseconds |
|
|
Number of events in this time range |