Hi Jorgen,
On Mon, Jul 27, 2009 at 08:56:00PM +0900, Jorgen Lundman wrote:
>
> Certainly.
>
> For the abridged text output, get:
> http://www.lundman.net/snoopdump.txt.gz (700kb)
>
> For the full dump:
> http://www.lundman.net/snoopdump.bin.gz (7mb)
>
> In this case, I used x4500-07, as it is otherwise entirely idle so that
> there is no other noise. It is a x4540, Open Solaris svn117.
>
> untar on the system, inside the pool,
> real 0m0.533s
>
> untar from prov01;
> real 3m36.220s
>
>
>
> Packets 0-75 are the mounting packets. The data transfers starts at 76.
> Immediately I can tell there were "multiple-second" pauses at 95, 101,
> 104, 107. Then it took off at moderate speed, but tapered off at the end.
>
>
> 94 0.00007 172.20.12.231 -> 172.20.12.239 NFS R 4 (open )
> NFS4ERR_GRACE PUTFH NFS4_OK SAVEFH NFS4_OK OPEN NFS4ERR_GRACE
>
> 95 0.05063 172.20.12.239 -> 172.20.12.231 TCP D=2049 S=574
> Ack=1621390269 Seq=3393151160 Len=0 Win=49640
>
> 96 9.94446 172.20.12.239 -> 172.20.12.231 NFS C 4 (open )
> PUTFH FH=A8F4 SAVEFH OPEN mt-testbg.cgi OT=CR(E) SQ=2 CT=N AC=W DN=N
> OO=0077 GETFH GETATTR 10011a...
At beginning we lost about 60 seconds (between packets 93 and 111) in open
operation. The server returned 6 times NFS4ERR_GRACE on client's open request.
And there is 10 second timeout between tries. We opened mt-testbg.cgi file
there.
This file get closed in packet 122. It is strange:
NFS4ERR_GRACE The server is in its recovery or grace period
which should match the lease period of the
server.
Some detailed analysis
----------------------
In packet 142 we opened mt-xmlrpc.cgi and we closed it in packet 151. It took
about 0.1 sec.
In packet 168: mt.cgi open, packet 177 close (took about 0.3 sec - most of the
time spent on server during open, about 0.25 sec).
The time between packets 151 and 168 (less than 0.1 sec) we spent removing old
mt.cgi file and other housekeeping.
So this seems fast for me.
Overview of whole snoop file
----------------------------
The snoop file contains more than 2250 open operations, so the rate is about
0.1 second per file. Do not forget, we performed about 2250 rm operations and
manu lookups too. If I am not missing anything the cadence is roughly same
across the whole snoop file.
If we consider this "slow" we should compare it with a "fast" case...
Note
----
The local untar operation (about 0.5 second) is fast probably because
everything happened in RAM on local machine.
HTH
>
>
>
> Please advise if I can help with anything else. It was mounted vers-4 as
> berfore.
>
> Lund
>
>
>
> Marcel Telka wrote:
>> Hi Jorgen,
>>
>> On Mon, Jul 27, 2009 at 05:34:04PM +0900, Jorgen Lundman wrote:
>>> What would be my next step in trying to work out why it takes more
>>> than 5 minutes to untar a 4MB tarball?
>>
>> I think the first step would be to see where we spent most of the time. For
>> example snoop captured during whole untar operation would show us such
>> information.
>>
>> So, please do a snoop and made the snoop file available for us somewhere.
>>
>>
>> Thanks.
>>
>
> --
> Jorgen Lundman | <lundman at lundman.net>
> Unix Administrator | +81 (0)3 -5456-2687 ext 1017 (work)
> Shibuya-ku, Tokyo | +81 (0)90-5578-8500 (cell)
> Japan | +81 (0)3 -3375-1767 (home)
> _______________________________________________
> nfs-discuss mailing list
> nfs-discuss at opensolaris.org
--
Marcel Telka
Solaris RPE
