Archive

Posts Tagged ‘nfs’

resolved – fsinfo ERROR: Stale NFS file handle POST

May 15th, 2014 Comments off

Today when I tried mount NFS share from one NFS server, it timeout with "mount.nfs: Connection timed out".

I tried to search something in /var/log/messages but no useful info there was found. So I used tcpdump on NFS client:

[root@dcs-hm1-qa132 ~]# tcpdump -nn -vvv host 10.120.33.90 #server is 10.120.33.90, client is 10.120.33.130
23:49:11.598407 IP (tos 0x0, ttl 64, id 26179, offset 0, flags [DF], proto TCP (6), length 96)
10.120.33.130.1649240682 > 10.120.33.90.2049: 40 null
23:49:11.598741 IP (tos 0x0, ttl 62, id 61186, offset 0, flags [DF], proto TCP (6), length 80)
10.120.33.90.2049 > 10.120.33.130.1649240682: reply ok 24 null
23:49:11.598812 IP (tos 0x0, ttl 64, id 26180, offset 0, flags [DF], proto TCP (6), length 148)
10.120.33.130.1666017898 > 10.120.33.90.2049: 92 fsinfo fh Unknown/0100010000000000000000000000000000000000000000000000000000000000
23:49:11.599176 IP (tos 0x0, ttl 62, id 61187, offset 0, flags [DF], proto TCP (6), length 88)
10.120.33.90.2049 > 10.120.33.130.1666017898: reply ok 32 fsinfo ERROR: Stale NFS file handle POST:
23:49:11.599254 IP (tos 0x0, ttl 64, id 26181, offset 0, flags [DF], proto TCP (6), length 148)
10.120.33.130.1682795114 > 10.120.33.90.2049: 92 fsinfo fh Unknown/010001000000000000002FFF000002580000012C0007B0C00000000A00000000
23:49:11.599627 IP (tos 0x0, ttl 62, id 61188, offset 0, flags [DF], proto TCP (6), length 88)
10.120.33.90.2049 > 10.120.33.130.1682795114: reply ok 32 fsinfo ERROR: Stale NFS file handle POST:

The reason of "ERROR: Stale NFS file handle POST" may caused by the following reasons:

1.The NFS server is no longer available
2.Something in the network is blocking
3.In a cluster during failover of NFS resource the major & minor numbers on the secondary server taking over is different from that of the primary.

To resolve the issue, you can try bounce NFS service on NFS server using /etc/init.d/nfs restart.

Categories: Hardware, NAS, Storage Tags:

resolved – how to check nfs version in linux

September 11th, 2012 Comments off

To know nfs version in linux/solaris:

  • On the nfs server side, you can run a nfsstat -s to check. The used version of nfs will have data summary other than 0% ones, as the following:

root@doxer.org# nfsstat -s
Server rpc stats:
calls badcalls badauth badclnt xdrcall
28 0 0 0 0

Server nfs v3:
null getattr setattr lookup access readlink
3 11% 4 14% 0 0% 1 3% 4 14% 0 0%
read write create mkdir symlink mknod
0 0% 0 0% 0 0% 0 0% 0 0% 0 0%
remove rmdir rename link readdir readdirplus
0 0% 0 0% 0 0% 0 0% 0 0% 2 7%
fsstat fsinfo pathconf commit
9 33% 4 14% 0 0% 0 0%

  • On the nfs server, we can also have a checking on what versions(2/3/4) and transport protocols(tcp/udp) the nfs supported with the command "rpcinfo -p localhost|grep nfs":

 

root@doxer# rpcinfo -p localhost|grep nfs
100003 2 udp 2049 nfs
100003 3 udp 2049 nfs
100003 4 udp 2049 nfs
100003 2 tcp 2049 nfs
100003 3 tcp 2049 nfs
100003 4 tcp 2049 nfs

 

  • On the nfs client hosts, you can run a nfsstat -c to check the version the client is using. As always, the used version of nfs will have data summary other than 0% ones, as the following:

root@doxer.org# nfsstat -c

Client rpc:
Connection oriented:
calls badcalls badxids timeouts newcreds badverfs
1219760 322812 0 0 0 0
timers cantconn nomem interrupts
0 322808 0 0
Connectionless:
calls badcalls retrans badxids timeouts newcreds
0 0 0 0 0 0
badverfs timers nomem cantsend
0 0 0 0

Client nfs:
calls badcalls clgets cltoomany
753081 28 753081 0
Version 2: (0 calls)
null getattr setattr root lookup readlink
0 0% 0 0% 0 0% 0 0% 0 0% 0 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% 0 0% 0 0%
Version 3: (748700 calls)
null getattr setattr lookup access readlink
0 0% 140588 18% 61939 8% 184611 24% 150266 20% 8 0%
read write create mkdir symlink mknod
35415 4% 58540 7% 11703 1% 562 0% 248 0% 0 0%
remove rmdir rename link readdir readdirplus
3264 0% 0 0% 9 0% 0 0% 1165 0% 1219 0%
fsstat fsinfo pathconf commit
33435 4% 7160 0% 3309 0% 55259 7%

Client nfs_acl:
Version 2: (0 calls)
null getacl setacl getattr access
0 0% 0 0% 0 0% 0 0% 0 0%
Version 3: (4382 calls)
null getacl setacl
0 0% 4382 100% 0 0%

  • Also, you can run nfsstat -m on nfs client hosts to print information about each of the mounted NFS file systems(the output info has nfs version indicated also):

root@doxer.org # nfsstat -m
/apps/uriman/tmp from doxer:/export/was/trncsc_cell_urimantmp
Flags: vers=3,proto=tcp,sec=none,hard,intr,link,symlink,acl,rsize=32768,wsize=32768,retrans=5,timeo=600
Attr cache: acregmin=3,acregmax=60,acdirmin=30,acdirmax=60

PS:

  • Here's more about output analytic of nfsstat:

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:

Code View: Scroll / Show All

% 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.
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) 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:

Code View: Scroll / Show All

% 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.
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. Thenomem 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, 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:

Code View: Scroll / Show All

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 thebadverf 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 timeoon 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.1Chapter 17, and Chapter 18.

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.

threads high on JVM due to I/O bottleneck

April 6th, 2012 Comments off

I/O seems always a bottleneck to applications. And sometimes moving from hard drive to RAM disk is a good idea as the latter one is much more efficient than former.

Let's go analysing one stack trace of a blocked thread:

Thread "WebContainer : 1103": acquiring monitor java.util.HashSet owned by WebContainer : 1009 (0:00:03.769)
com.vgn.ext.templating.cache.BaseObjectCache.putVariation (BaseObjectCache.java:352, bci=121, server compiler)
blocked on java.util.HashSet (0x000000c9d5e606d0)
com.vgn.ext.templating.cache.BaseObjectCache.putRenderedManagedObject (BaseObjectCache.java:329, bci=36, server compiler)
com.foundation.dp.V7ObjectCache.putRenderedManagedObject (V7ObjectCache.java:372, bci=458, server compiler)
com.vgn.ext.templating.util.RenderUtil.renderContentItem (RenderUtil.java:249, bci=657, server compiler)
com.vgn.ext.templating.util.RenderUtil.renderRegionContent (RenderUtil.java:533, bci=79, server compiler)
com.vgn.ext.templating.taglib.ContentRegionTagSupport.renderRegion (ContentRegionTagSupport.java:626, bci=63, server compiler)
com.vgn.ext.templating.taglib.ContentRegionTagSupport.doStartTag (ContentRegionTagSupport.java:672, bci=180, server compiler)
com.ibm._jsp._contentRegion._jspService (_contentRegion.java:148, bci=561, server compiler)
com.ibm.ws.jsp.runtime.HttpJspBase.service (HttpJspBase.java:87, bci=3, server compiler)
javax.servlet.http.HttpServlet.service (HttpServlet.java:856, bci=30, server compiler)
com.ibm.ws.webcontainer.servlet.ServletWrapper.service (ServletWrapper.java:1146, bci=248, server compiler)
com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest (ServletWrapper.java:592, bci=1071, server compiler)
com.ibm.ws.wswebcontainer.servlet.ServletWrapper.handleRequest (ServletWrapper.java:525, bci=510, server compiler)
com.ibm.wsspi.webcontainer.servlet.GenericServletWrapper.handleRequest (GenericServletWrapper.java:122, bci=6, server compiler)
com.ibm.ws.jsp.webcontainerext.AbstractJSPExtensionServletWrapper.handleRequest (AbstractJSPExtensionServletWrapper.java:232, bci=539, server compiler)
com.ibm.ws.webcontainer.webapp.WebAppRequestDispatcher.include (WebAppRequestDispatcher.java:639, bci=704, server compiler)
com.vgn.ext.templating.portal.taglib.VAPIncludeTag.doStartTag (VAPIncludeTag.java:147, bci=562, server compiler)
com.ibm._jsp._view._jspx_meth_page_include$1page_0 (_view.java:455, bci=41, server compiler)
com.ibm._jsp._view._jspService (_view.java:231, bci=1038, server compiler)

From here we can conclude that the thread is waiting to acquire lock necessary before it attempts to put some rendered object.

Here's a stack trace of the running active thread:

Thread "WebContainer : 947": running
java.io.FileOutputStream.writeBytes (native method)
java.io.FileOutputStream.write (FileOutputStream.java:278, bci=4, server compiler)
java.io.ObjectOutputStream$BlockDataOutputStream.drain (ObjectOutputStream.java:1690, bci=36, server compiler)
java.io.ObjectOutputStream$BlockDataOutputStream.setBlockDataMode (ObjectOutputStream.java:1599, bci=14, server compiler)
java.io.ObjectOutputStream.writeObject0 (ObjectOutputStream.java:1090, bci=540, server compiler)
java.io.ObjectOutputStream.writeObject (ObjectOutputStream.java:307, bci=16, server compiler)
java.util.HashSet.writeObject (HashSet.java:254, bci=66, server compiler)
sun.reflect.GeneratedMethodAccessor208.invoke (unknown source, bci=40, server compiler)
sun.reflect.DelegatingMethodAccessorImpl.invoke (DelegatingMethodAccessorImpl.java:25, bci=6, server compiler)
java.lang.reflect.Method.invoke (Method.java:585, bci=111, server compiler)
java.io.ObjectStreamClass.invokeWriteObject (ObjectStreamClass.java:917, bci=20, server compiler)
java.io.ObjectOutputStream.writeSerialData (ObjectOutputStream.java:1344, bci=79, server compiler)
java.io.ObjectOutputStream.writeOrdinaryObject (ObjectOutputStream.java:1295, bci=64, server compiler)
java.io.ObjectOutputStream.writeObject0 (ObjectOutputStream.java:1084, bci=506, server compiler)
java.io.ObjectOutputStream.defaultWriteFields (ObjectOutputStream.java:1380, bci=115, server compiler)
java.io.ObjectOutputStream.writeSerialData (ObjectOutputStream.java:1352, bci=125, server compiler)
java.io.ObjectOutputStream.writeOrdinaryObject (ObjectOutputStream.java:1295, bci=64, server compiler)
java.io.ObjectOutputStream.writeObject0 (ObjectOutputStream.java:1084, bci=506, server compiler)
java.io.ObjectOutputStream.writeObject (ObjectOutputStream.java:307, bci=16, server compiler)
com.vgn.ext.templating.cache.DefaultObjectCache.addFile (DefaultObjectCache.java:356, bci=173, server compiler)
com.vgn.ext.templating.cache.DefaultObjectCache.putSimpleObject (DefaultObjectCache.java:1098, bci=91, server compiler)
com..foundation.dp.V7ObjectCache.putSimpleObject (V7ObjectCache.java:797, bci=36, server compiler)
com.vgn.ext.templating.cache.BaseObjectCache.putVariation (BaseObjectCache.java:366, bci=246, server compiler)
locked java.util.HashSet (0x000000c94019b9c8)
com.vgn.ext.templating.cache.BaseObjectCache.putRenderedManagedObject (BaseObjectCache.java:329, bci=36, server compiler)
com..foundation.dp.V7ObjectCache.putRenderedManagedObject (V7ObjectCache.java:372, bci=458, server compiler)
com.vgn.ext.templating.util.RenderUtil.renderContentItem (RenderUtil.java:249, bci=657, server compiler)
com.vgn.ext.templating.util.RenderUtil.renderRegionContent (RenderUtil.java:533, bci=79, server compiler)

We can conclude that active threads are attempting disk IO and are getting stuck in the write() syscall for a considerable amount of time. So let's went to the host to check I/O states:

root@doxer# iostat -xn
extended device statistics
r/s w/s kr/s kw/s wait actv wsvc_t asvc_t %w %b device
21.9 189.6 68.7 5433.3 1.0 1.6 4.9 7.4 9 47 testserver:/cache
9.0 421.7 229.3 13280.8 0.2 1.1 0.4 2.7 3 64 testserver:/cache
4.0 510.7 82.3 16310.0 0.5 1.5 0.9 2.9 7 62 testserver:/cache
14.1 692.6 190.3 21625.8 1.0 2.6 1.4 3.7 15 73 testserver:/cache
19.0 747.1 219.5 23096.4 1.7 3.5 2.2 4.6 22 74 testserver:/cache
1.0 392.0 25.9 12433.3 0.0 0.6 0.0 1.6 1 55 testserver:/cache
5.0 417.9 97.9 13284.8 0.1 0.9 0.2 2.1 2 58 testserver:/cache
7.0 425.9 186.5 13368.8 0.2 1.3 0.4 2.9 4 67 testserver:/cache
4.0 537.1 55.8 17002.2 1.0 1.7 1.9 3.1 10 65 testserver:/cache
11.0 911.0 110.6 28490.8 2.4 4.1 2.6 4.4 29 76 testserver:/cache
7.0 377.4 110.0 11897.0 0.0 1.0 0.0 2.5 1 63 testserver:/cache
3.0 597.9 28.9 18825.1 0.7 1.9 1.2 3.2 12 60 testserver:/cache
1.0 502.0 25.2 15639.9 0.3 1.3 0.6 2.6 7 55 testserver:/cache
1.0 495.0 22.5 15739.3 1.1 1.8 2.3 3.7 12 64 testserver:/cache
9.9 555.2 114.1 17626.5 0.9 2.2 1.6 3.9 12 67 testserver:/cache
21.1 747.8 61.4 22946.8 5.1 3.4 6.6 4.4 24 77 testserver:/cache
6.0 794.8 130.4 25325.1 2.1 3.7 2.7 4.7 27 69 testserver:/cache
8.0 646.6 53.6 20225.4 1.4 2.5 2.2 3.8 17 65 testserver:/cache
7.0 380.3 157.4 12112.6 0.0 0.9 0.0 2.4 1 64 testserver:/cache
10.0 398.9 127.1 12610.9 0.1 1.1 0.2 2.7 2 68 testserver:/cache
10.0 843.4 94.1 26200.1 1.9 3.7 2.2 4.3 26 74 testserver:/cache
6.0 464.0 31.6 14471.7 0.4 1.5 0.8 3.2 6 63 testserver:/cache
0.0 619.0 0.0 19693.2 1.1 2.2 1.8 3.5 14 60 testserver:/cache
6.0 641.0 136.3 19917.7 1.3 2.6 2.0 4.0 18 70 testserver:/cache

Pretty heavy and with clear pattern! No other disks had any writes at all except for NFS share. If we changed the cache from NFS to tmpfs, this will improve write speeds dramatically.

PS:

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:

Code View: Scroll / Show All

% 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 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.

 

  • Some contents of this article is from book <Managing NFS and NIS>.