14.2. NFS statistics
The client- and server-side implementations
of NFS compile per-call
statistics of NFS service usage at both the RPC and application
layers.
nfsstat -c displays
the client-side statistics
while
nfsstat -s shows the server tallies. With
no arguments,
nfsstat prints out both sets of
statistics:
% nfsstat -s
Server rpc:
Connection oriented:
calls badcalls nullrecv badlen xdrcall dupchecks
10733943 0 0 0 0 1935861
dupreqs
0
Connectionless:
calls badcalls nullrecv badlen xdrcall dupchecks
136499 0 0 0 0 0
dupreqs
0
Server nfs:
calls badcalls
10870161 14
Version 2: (1716 calls)
null getattr setattr root lookup readlink
48 2% 0 0% 0 0% 0 0% 1537 89% 13 0%
read wrcache write create remove rename
0 0% 0 0% 0 0% 0 0% 0 0% 0 0%
link symlink mkdir rmdir readdir statfs
0 0% 0 0% 0 0% 0 0% 111 6% 7 0%
Version 3: (10856042 calls)
null getattr setattr lookup access readlink
136447 1% 4245200 39% 95412 0% 1430880 13% 2436623 22% 74093 0%
read write create mkdir symlink mknod
376522 3% 277812 2% 165838 1% 25497 0% 24480 0% 0 0%
remove rmdir rename link readdir readdirplus
359460 3% 33293 0% 8211 0% 69484 0% 69898 0% 876367 8%
fsstat fsinfo pathconf commit
1579 0% 7698 0% 4253 0% 136995 1%
Server nfs_acl:
Version 2: (2357 calls)
null getacl setacl getattr access
0 0% 5 0% 0 0% 2170 92% 182 7%
Version 3: (10046 calls)
null getacl setacl
0 0% 10039 99% 7 0%
The server-side RPC fields indicate if there are problems removing
the packets from the NFS service end point. The kernel reports
statistics on connection-oriented RPC and connectionless RPC
separately. The fields detail each kind of problem:
- calls
-
The NFS calls value represents the
total number of NFS Version 2, NFS
Version 3, NFS ACL Version 2 and NFS ACL Version 3 RPC calls made to
this server from all clients. The RPC calls value represents the
total number of NFS, NFS ACL, and NLM RPC calls made to this server
from all clients. RPC calls made for other services, such as NIS, are
not included in this count.
- badcalls
-
These are RPC requests that were rejected out of hand by the
server's RPC mechanism, before the request was passed to the
NFS service routines in the kernel. An RPC call will be rejected if
there is an authentication failure, where the calling client does not
present valid credentials.
- nullrecv
-
Not used in Solaris. Its value is always 0.
- badlen/xdrcall
-
The RPC request received by the server was too short
(badlen) or the XDR headers in the packet are
malformed (xdrcall ). Most likely this is due to
a malfunctioning client. It is rare, but possible, that the packet
could have been truncated or damaged by a network problem. On a local
area network, it's rare to have XDR headers damaged, but
running NFS over a wide-area network could result in malformed
requests. We'll look at ways of detecting and correcting packet
damage on wide-area networks in Section 18.4, "NFS over wide-area networks".
- dupchecks/dupreqs
-
The dupchecksfield indicates the number of RPC calls that were
looked up in the duplicate request cache. The dupreqs field indicates
the number of RPC calls that were actually found to be duplicates.
Duplicate requests occur as a result of client retransmissions. A
large number of dupreqs usually indicates that the server is not
replying fast enough to its clients. Idempotent requests can be
replayed without ill effects, therefore not all RPCs have to be
looked up on the duplicate request cache. This explains why the
dupchecks field does not match the calls field.
The statistics for each NFS version are reported independently,
showing the total number of NFS calls made to this server using each
version of the protocol. A version-specific breakdown by procedure of
the calls handled is also provided. Each of the call types
corresponds to a procedure within the NFS RPC and NFS_ACL RPC
services.
The null procedure is included
in
every RPC program for
pinging the RPC server. The null procedure
returns no value, but a successful return from a call to
null ensures that the network is operational and
that the server host is alive.
rpcinfo calls the
null procedure to check RPC server health. The automounter (see
Chapter 9, "The Automounter") calls the null procedure of all NFS servers
in parallel when multiple machines are listed for a single mount
point. The automounter and
rpcinfo should
account for the total
null calls reported by
nfsstat.
Client-side RPC statistics include the number of calls of each type
made to all servers, while the client NFS statistics indicate how
successful the client machine is in reaching NFS servers:
% nfsstat -c
Client rpc:
Connection oriented:
calls badcalls badxids timeouts newcreds badverfs
1753584 1412 18 64 0 0
timers cantconn nomem interrupts
0 1317 0 18
Connectionless:
calls badcalls retrans badxids timeouts newcreds
12443 41 334 80 166 0
badverfs timers nomem cantsend
0 4321 0 206
Client nfs:
calls badcalls clgets cltoomany
1661217 23 1661217 3521
Version 2: (234258 calls)
null getattr setattr root lookup readlink
0 0% 37 0% 0 0% 0 0% 184504 78% 811 0%
read wrcache write create remove rename
49 0% 0 0% 24301 10% 3 0% 2 0% 0 0%
link symlink mkdir rmdir readdir statfs
0 0% 0 0% 12 0% 12 0% 24500 10% 27 0%
Version 3: (1011525 calls)
null getattr setattr lookup access readlink
0 0% 417691 41% 14598 1% 223609 22% 47438 4% 695 0%
read write create mkdir symlink mknod
56347 5% 221334 21% 1565 0% 106 0% 48 0% 0 0%
remove rmdir rename link readdir readdirplus
807 0% 14 0% 676 0% 24 0% 475 0% 5204 0%
fsstat fsinfo pathconf commit
8 0% 10612 1% 95 0% 10179 1%
Client nfs_acl:
Version 2: (411477 calls)
null getacl setacl getattr access
0 0% 181399 44% 0 0% 185858 45% 44220 10%
Version 3: (3957 calls)
null getacl setacl
0 0% 3957 100% 0 0%
In addition to the total number of NFS calls made and the number of
rejected NFS calls (
badcalls), the client-side
statistics indicate if NFS calls are being delayed due to a lack of
client RPC handles. Client RPC handles are opaque pointers used by
the kernel to hold server connection information. In SunOS 4.x, the
number of client handles was fixed, causing the NFS call to block
until client handles became available. In Solaris, client handles are
allocated dynamically. The kernel maintains a cache of up to 16
client handles, which are reused to speed up communication with the
server. The
clgets count indicates the number of
times a client handle has been requested. If the NFS call cannot find
an unused client handle in the cache, it will not block until one
frees up. Instead, it will create a brand new client handle and
proceed. This count is reflected by
cltoomany.
The client handle is destroyed when the reply to the NFS call
arrives. This count is of little use to system administrators since
nothing can be done to increase the cache size and reduce the number
of misses.
Included in the client RPC statistics are counts
for various failures experienced
while trying to send NFS requests to a server:
- calls
-
Total number of calls made to all NFS servers.
- badcalls
-
Number of RPC calls that returned an error. The two most common RPC
failures are timeouts and interruptions, both of which increment the
badcalls counter. The connection-oriented RPC
statistics also increment the interrupts
counter. There is no equivalent counter for connectionless RPC
statistics. If a server reply is not received within the RPC timeout
period, an RPC error occurs. If the RPC call is interrupted, as it
may be if a filesystem is mounted with the intr
option, then an RPC interrupt code is returned to the caller.
nfsstat also reports the
badcalls count in the NFS statistics. NFS call
failures do not include RPC timeouts or interruptions, but do include
other RPC failures such as authentication errors (which will be
counted in both the NFS and RPC level statistics).
- badxids
-
The number of bad XIDs. The XID in an NFS request is a serial number
that uniquely identifies the request. When a request is
retransmitted, it retains the same XID through the entire timeout and
retransmission cycle. With the Solaris multithreaded kernel, it is
possible for the NFS client to have several RPC requests outstanding
at any time, to any number of NFS servers. When a response is
received from an NFS server, the client matches the XID in the
response to an RPC call in progress. If an XID is seen for which
there is no active RPC call -- because the client already
received a response for that XID -- then the client increments
badxid. A high badxid count, therefore, indicates that the server is
receiving some retransmitted requests, but is taking a long time to
reply to all NFS requests. This scenario is explored in Section 18.1, "Slow server compensation".
- timeouts
-
Number of calls that timed out waiting for a server's response.
For hard-mounted filesystems, calls that time out are retransmitted,
with a new timeout period that may be longer than the previous one.
However, calls made on soft-mounted filesystems may eventually fail
if the retransmission count is exceeded, so that the call counts obey
the relationship:
timeout + badcalls >= retrans
The final retransmission of a request on a soft-mounted filesystem
increments
badcalls (as previously explained).
For example, if a filesystem is mounted with
retrans=5, the client reissues the same request
five times before noting an RPC failure. All five requests are
counted in
timeout, since no replies are
received. Of the failed attempts, four are counted in the
retrans statistic and the last shows up in
badcalls.
- newcreds
-
Number of times client authentication information had to be
refreshed. This statistic only applies if a secure RPC mechanism has
been integrated with the NFS service.
- badverfs
-
Number of times server replies could not be authenticated. The number
of times the client could not guarantee that the server was who it
says it was. These are likely due to packet retransmissions more than
security breaches, as explained later in this section.
- timers
-
Number of times the starting RPC call timeout value was greater than
or equal to the minimum specified timeout value for the call. Solaris
attempts to dynamically tune the initial timeout based on the history
of calls to the specific server. If the server has been sluggish in
its reponse to this type of RPC call, the timeout will be greater
than if the server had been replying normally. It makes sense to wait
longer before retransmitting for the first time, since history
indicates that this server is slow to reply. Most client
implementations use an exponential back-off strategy that doubles or
quadruples the timeout after each retransmission up to an
implementation-specific limit.
- cantconn
-
Number of times a connection-oriented RPC call failed due to a
failure to establish a connection to the server. The reasons why
connections cannot be created are varied; one example is the server
may not be running the nfsd daemon.
- nomem
-
Number of times a call failed due to lack of resources. The host is
low in memory and cannot allocate enough temporary memory to handle
the request.
- interrupts
-
Number of times a connection-oriented RPC call was interrupted by a
signal before completing. This counter applies to connection-oriented
RPC calls only. Interrupted connection and connectionless RPC calls
also increment badcalls.
- retrans
-
Number of calls that were retransmitted because no response was
received from the NFS server within the timeout period. This is only
reported for RPC over connectionless transports. An NFS client that
is experiencing poor server response will have a large number of
retransmitted calls.
- cantsend
-
Number of times a request could not be sent. This counter is
incremented when network plumbing problems occur. This will mostly
occur when no memory is available to allocate buffers in the various
network layer modules, or the request is interrupted while the client
is waiting to queue the request downstream. The
nomem and interrupts
counters report statistics encountered in the RPC software layer,
while the cantsend counter reports statistics
gathered in the kernel TLI layer.
The statistics shown by
nfsstat are cumulative
from the time the machine was booted, or the last time they were
zeroed using
nfsstat -z:
nfsstat -z Resets all counters.
nfsstat -sz Zeros server-side RPC and NFS statistics.
nfsstat -cz Zeros client-side RPC and NFS statistics.
nfsstat -crz Zeros client-side RPC statistics only.
Only the superuser can reset the counters.
nfsstat provides a very coarse look at NFS
activity and is limited in its usefulness for resolving performance
problems. Server statistics are collected for all clients, while in
many cases it is important to know the distribution of calls from
each client. Similarly, client-side statistics are aggregated for all
NFS servers.
However, you can still glean useful information from
nfsstat. Consider the case where a client
reports a high number of bad verifiers. The high
badverfs count is most likely an indication that
the client is having to retransmit its secure RPC requests. As
explained in
Section 12.1, "User-oriented network security", every secure RPC call has a
unique credential and verifier with a unique timestamp (in the case
of AUTH_DES) or a unique sequence number (in the case of RPCSEC_GSS).
The client expects the server to include this verifier (or some form
of it) in its reply, so that the client can verify that it is indeed
obtaining the reply from the server it called.
Consider the scenario where the client makes a secure RPC call using
AUTH_DES, using timestamp T1 to generate its verifier. If no reply is
received within the timeout period, the client retransmits the
request, using timestamp T1+delta to generate its verifier (bumping
up the
retrans count). In the meantime, the
server replies to the original request using timestamp T1 to generate
its verifier:
RPC call (T1) --->
** time out **
RPC call (retry: T1+delta) --->
<--- Server reply to first RPC call (T1 verifier)
The reply to the client's original request will cause the
verifier check to fail because the client now expects T1+delta in the
verifier, not T1. This consequently bumps up the
badverf count. Fortunately, the Solaris client
will wait for more replies to its retransmissions and, if the reply
passes the verifier test, an NFS authentication error will be
avoided. Bad verifiers are not a big problem, unless the count gets
too high, especially when the system starts experiencing NFS
authentication errors. Increasing the NFS
timeo
on the mount or automounter map may help alleviate this problem. Note
also that this is less of a problem with TCP than UDP. Analysis of
situations such as this will be the focus of
Section 16.1, "Characterization of NFS behavior",
Chapter 17, "Network Performance Analysis", and
Chapter 18, "Client-Side Performance Tuning".
For completeness, we should mention that verifier failures can also
be caused when the security content expires before the response is
received. This is rare but possible. It usually occurs when you have
a network partition that is longer than the lifetime of the security
context. Another cause might be a significant time skew between the
client and server, as well as a router with a ghost packet stored,
that fires after being delayed for a very long time. Note that this
is not a problem with TCP.
14.2.1. I/O statistics
Solaris'
iostat utility has been
extended to report I/O statistics on
NFS mounted filesystems, in addition to its traditional reports on
disk, tape I/O, terminal activity, and CPU utilization. The
iostat utility helps you measure and monitor
performance by providing disk and network I/O throughput,
utilization, queue lengths and response time.
The
-xn directives instruct
iostat to report extended disk statistics in
tabular form, as well as display the names of the devices in
descriptive format (for example, server:/export/path). The following
example shows the output of
iostat -xn 20 during
NFS activity on the client, while it concurrently reads from two
separate NFS filesystems. The server
assisi is
connected to the same hub to which the client is connected, while the
test server
paris is on the other side of the
hub and other side of the building network switches. The two servers
are identical; they have the same memory, CPU, and OS configuration:
% iostat -xn 20
...
extended device statistics
r/s w/s kr/s kw/s wait actv wsvc_t asvc_t %w %b device
0.0 0.1 0.0 0.4 0.0 0.0 0.0 3.6 0 0 c0t0d0
0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0 fd0
0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0 rome:vold(pid239)
9.7 0.0 310.4 0.0 0.0 3.3 0.2 336.7 0 100 paris:/export
34.1 0.0 1092.4 0.0 0.0 3.2 0.2 93.2 0 99 assisi:/export
The
iostat utility iteratively reports the disk
statistics every 20 seconds and calculates its statistics based on a
delta from the previous values. The first set of statistics is
usually uninteresting, since it reports the cumulative values since
boot time. You should focus your attention on the following set of
values reporting the current disk and network activity. Note that the
previous example does not show the cumulative statistics. The output
shown represents the second set of values, which report the I/O
statistics within the last 20 seconds. The first two lines represent
the header, then every disk and NFS filesystem on the system is
presented in separate lines. The first line reports statistics for
the local hard disk
c0t0d0. The second line
reports statistics for the local floppy disk
fd0. The third line reports statistics for the
volume manager
vold. In Solaris, the volume
manager is implemented as an NFS user-level server. The fourth and
fifth lines report statistics for the NFS filesystems mounted on this
host. Included in the statistics are various values that will help
you analyze the performance of the NFS activity:
- r/s
-
Represents the number of read operations per second during the
time interval specified. For NFS filesystems, this value represents
the number of times the remote server was called to read data from a
file, or read the contents of a directory. This quantity accounts for
the number of read, readdir, and readdir+ RPCs performed during this
interval. In the previous example, the client contacted the server
assisi an average of 34.1 times per second to
either read the contents of a file, or list the contents of
directories.
- w/s
-
Represents the number of write operations per second during the time
interval specified. For NFS filesystems, this value represents the
number of times the remote server was called to write data to a file.
It does not include directory operations such as mkdir, rmdir, etc.
This quantity accounts for the number of write RPCs performed during
this interval.
- kr/s
-
Represents the number of kilobytes per
second read during this interval. In the
preceding example, the client is reading data at an average of
1,092.4 KB/s from the NFS server assisi. The optional
-M directive would instruct
iostat to display data throughput in MB/sec
instead of KB/sec.
- kw/s
-
Represents the number of kilobytes
written per second during this interval. The
optional -M directive would instruct
iostat to display data throughput in MB/sec.
- wait
-
Reports the average number of requests waiting
to be
processed. For NFS filesystems, this value gets incremented when a
request is placed on the asynchronous request queue, and gets
decreased when the request is taken off the queue and handed off to
an NFS async thread to perform the RPC call. The length of the wait
queue indicates the number of requests waiting to be sent to the NFS
server.
- actv
-
Reports the number of requests actively being processed (i.e., the
length of the run queue). For NFS filesystems, this number represents
the number of active NFS async threads waiting for the NFS server to
respond (i.e., the number of outstanding requests being serviced by
the NFS server). In the preceding example, the client has on average
3.2 outstanding RPCs pending for a reply by the server
assisi at all times during the interval
specified. This number is controlled by the maximum number of NFS
async threads configured on the system. Chapter 18, "Client-Side Performance Tuning"
will explain this in more detail.
- wsvc_t
-
Reports the time spent in the wait queue in milliseconds. For NFS
filesystems, this is the time the request waited before it could be
sent out to the server.
- asvc_t
-
Reports the time spent in the run queue in milliseconds. For NFS
filesystems, this represents the average amount of time the client
waits for the reply to its RPC requests, after they have been sent to
the NFS server. In the preceding example, the server
assisi takes on average 93.2 milliseconds to
reply to the client's requests, where the server
paris takes 336.7 milliseconds. Recall that the
server assisi and the client are physically
connected to the same hub, whereas packets to and from the server
paris have to traverse multiple switches to
communicate with the client. Analysis of nfsstat
-s on paris indicated a large amount of NFS traffic
directed at this server at the same time. This, added to server load,
accounts for the slow response time.
- %w
-
Reports the percentage of time that transactions are present in the
wait queue ready to be processed. A large number for an NFS filesytem
does not necessarily indicate a problem, given that there are
multiple NFS async threads that perform the work.
- %b
-
Reports the percentage of time that actv is
non-zero (at least one request is being processsed). For NFS
filesystems, it represents the activity level of the server mount
point. 100% busy does not indicate a problem since the NFS server has
multiple nfsd threads that can handle concurrent RPC requests. It
simply indicates that the client has had requests continuously
processed by the server during the measurement time.
 |  |  |
| 14. NFS Diagnostic Tools |  | 14.3. snoop |
