Friday 16 March 2007

Quickdraw

There's .47 of a second between these two images. In the second image you can see a small yellow box. The box makes a loud beep, then measures the time it takes for you to fire the gun using a microphone also in the yellow box. The beep goes off at a random time after the button is pressed so that you can't try and guess.

Thursday 15 March 2007

AIX Trace of cached NFS read Vs Uncached



(A wide screen is needed to view the trace files.)

Here are two examples of a cached NFS read Vs an un-cached NFS read on an AIX system (AIX version 4.?) The cached read completes in 119usecs. The uncached read completes in 1251us (1.2ms). These timings are taken from the trace output.

To get this data I ran the AIX utilities trace and trcrpt, against a short script called ‘read.ksh’ that simply contains:-

for i in 1 2 3 4 5 6 7 8 9
do
dd if=$i of=/dev/null
done

Where the files 1..9 reside on a NFS filesystem. The unached version was de-cached by writing to the files, immediately prior to reading them. The cached version was traced after reading in the files a second time. Since the files had not been updated the NFS client was able to use the pages in cache.

In the trace output of the uncached read, you can clearly see that the OS has to do a lot of work to go and get the data, including setting up TCP connections, creating and moving mbuf’s around and so on. Whereas the cached read, just copied (or maps) the block which already exists in the kernels buffer cache (I'm no AIX expert but that's what it looks like to me).

Collect the data using ‘trace’.
tx03:/tt/gjl>trace -a -k "20e,20f" -o /tmp/trc_read_ksh_raw ; /tt04/gjl/read.ksh; trcstop

Parse the data using ‘trcrpt’.
tx03:/tt/gjl>trcrpt -k "1b0,1b1" -O "exec=on,pid=on" /tmp/trc_read_ksh_raw > /tmp/trcrpt_read_ksh_nocache.out

View using ‘vi’.
tx03:/tt/gjl>view /tmp/trcrpt_read_ksh_cached.out


By contrast, both cached and un-cached versions of read, go over the wire to get the file attributes during an open. This is reflected in the nfs stats that we collect at the filer. So each open will result in a getattr regardless of the actiemo settings. However, if we only read then we can continue to get cached results.

As soon as the file is written to EVEN IF IT IS FROM THE SAME CLIENT. The cache is invalidated, and the read has to go over the wire (OTW) to get it.

Cached trace excerpt:


In this example PID 28694 is the PID of the ‘dd’ process.

104 dd 28694 0.052245935 0.002120 return from _sigaction [2 usec]
101 dd 28694 0.052251404 0.005469 kread LR = D01846E0
163 dd 28694 0.052253090 0.001686 read(0,20020000,200) 1
112 dd 28694 0.052264680 0.011590 lock: lock lock addr=32BD74A0 lock status=10000001 requested_mode=LOCK_READ return addr=54439F0 name=0000.0000
211 dd 28694 0.052275017 0.010337 NFS3_READ D1=32BD742C D2=0000 D3=0000 D4=0200 D5=0088
100 dd 28694 0.052309257 0.034240 DATA ACCESS PAGE FAULT iar=1450E8 cpuid=02
1B2 dd 28694 0.052311594 0.002337 VMM pagefault: V.S=0020.8A8D
working_storage process_private computational (type 2)
1B9 dd 28694 0.052352966 0.041372 VMM zero filled page: V.S=0020.8A8D ppage=72B90
working_storage process_private computational (type 2)
200 dd 28694 0.052354893 0.001927 resume dd iar=1450E8 cpuid=02
211 dd 28694 0.052366025 0.011132 NFS3_READ D1=32BD742C D2=0001 D3=0200 D4=0000 D5=0088
113 dd 28694 0.052368988 0.002963 unlock: lock addr=32BD74A0 lock status=0000 return addr=544397C name=0000.0000
104 dd 28694 0.052370963 0.001975 return from kread [119 usec]
100 dd 28694 0.052380095 0.009132 DATA ACCESS PAGE FAULT iar=10002FD4 cpuid=02
1B2 dd 28694 0.052381974 0.001879 VMM pagefault: V.S=0000.3857B
working_storage computational permfreeze (type 1)
1B9 dd 28694 0.052420478 0.038504 VMM zero filled page: V.S=0000.3857B ppage=448A5
working_storage computational permfreeze (type 1)
200 dd 28694 0.052422164 0.001686 resume dd iar=10002FD4 cpuid=02
101 dd 28694 0.052449536 0.027372 kwrite LR = D017DF00
19C dd 28694 0.052451632 0.002096 write(6,20001358,8)
11F dd 28694 0.052463077 0.011445 setrq: cmd=dd pid=31976 tid=36943 priority=60 policy=0
104 dd 28694 0.052471149 0.008072 return from kwrite [21 usec]
10E kproc 1290 0.052472281 0.001132 relock: lock addr=376B20 oldtid=1291 newtid=1291
101 dd 28694 0.052474570 0.002289 kread LR = D01846E0
163 dd 28694 0.052477075 0.002505 read(3,20000B70,4)
10E dd 31976 0.052478496 0.001421 relock: lock addr=376B20 oldtid=1291 newtid=36943


Uncached trace excerpt.


In this example, PID 33522 is the PIS of the ‘dd’ process itself. Later we see another PID 10860, identified as a ‘kproc’ which seems to be a kernel thread acting on behalf of the userland thread. In this case it is doing NFS work (kprocs are used to implement AIO FWIW). Other kproc’s are used to run the idle thread.


addr new sigaction=2FF22850 addr old sigaction=00000000
104 dd 33522 0.047360376 0.002048 return from _sigaction [2 usec]
101 dd 33522 0.047365580 0.005204 kread LR = D01846E0
163 dd 33522 0.047367098 0.001518 read(0,20020000,200) 1
112 dd 33522 0.047378423 0.011325 lock: lock lock addr=32BD74A0 lock status=10000001 requested_mode=L
OCK_READ return addr=54439F0 name=0000.0000
211 dd 33522 0.047387579 0.009156 NFS3_READ D1=32BD742C D2=0000 D3=0000 D4=0200 D5=0088
100 dd 33522 0.047420349 0.032770 DATA ACCESS PAGE FAULT iar=1450E0 cpuid=03
1B2 dd 33522 0.047423047 0.002698 VMM pagefault: V.S=0000.25695
client_segment interruptable large (type 0)
2FC dd 33522 0.047448612 0.025565 Link Register=76B7C
1BA dd 33522 0.047467888 0.019276 VMM start io: V.S=0000.25695 ppage=22331
client_segment interruptable large (type 0)
bp=32A294E0 B_READ
464 dd 33522 0.047491236 0.023348 e_wakeup_one: tid=19093 anchor=54AD48C lr=5462ED0
11F dd 33522 0.047494175 0.002939 setrq: cmd=kproc pid=18060 tid=19093 priority=60 policy=0
10E kproc 774 0.047502463 0.008288 relock: lock addr=376620 oldtid=775 newtid=775
10E kproc 18060 0.047507233 0.004770 relock: lock addr=376620 oldtid=775 newtid=19093
106 kproc 18060 0.047508775 0.001542 dispatch: cmd=kproc pid=18060 tid=19093 priority=60 old_tid=775 old_priori
ty=127 CPUID=1 [276 usec]
10E kproc 1290 0.047509449 0.000674 relock: lock addr=376B20 oldtid=1291 newtid=1291
10C kproc 1290 0.047511328 0.001879 dispatch: idle process pid=1290 tid=1291 priority=127 old_tid=21339 old_p
riority=60 CPUID=3
200 kproc 18060 0.047512219 0.000891 resume kproc iar=3DB94 cpuid=01
200 kproc 1290 0.047512821 0.000602 resume IDLE iar=1EB3C cpuid=03
116 kproc 18060 0.047534001 0.021180 xmalloc fastpath: size=0018 align=0002 heap=3FFBD0B8
116 kproc 18060 0.047536241 0.002240 xmalloc return: result=32CD4900
464 kproc 18060 0.047550240 0.013999 e_wakeup_one: tid=37333 anchor=326E5140 lr=5461BAC
11F kproc 18060 0.047552770 0.002530 setrq: cmd=kproc pid=18060 tid=37333 priority=60 policy=0
460 kproc 18060 0.047561251 0.008481 e_assert_wait: tid=19093 anchor=54AD48C flag=0 lr=3E278
10E kproc 516 0.047561949 0.000698 relock: lock addr=3763A0 oldtid=517 newtid=517
462 kproc 18060 0.047565153 0.003204 e_block_thread: tid=19093 anchor=54AD48C t_flags=4001000 lr=3E2A4
10E kproc 18060 0.047567442 0.002289 relock: lock addr=3763A0 oldtid=517 newtid=37333
106 kproc 18060 0.047569369 0.001927 dispatch: cmd=kproc pid=18060 tid=37333 priority=60 old_tid=517 old_priori
ty=127 CPUID=0 [60 usec]
10E kproc 774 0.047572212 0.002843 relock: lock addr=376620 oldtid=775 newtid=775
200 kproc 18060 0.047572983 0.000771 resume kproc iar=3DB94 cpuid=00
10C kproc 774 0.047574260 0.001277 dispatch: idle process pid=774 tid=775 priority=127 old_tid=19093 old_pri
ority=60 CPUID=1
200 kproc 774 0.047575464 0.001204 resume IDLE iar=1EB3C cpuid=01
112 kproc 18060 0.047582427 0.006963 lock: lock lock addr=38B220 lock status=200091D5 requested_mode=LOC
K_CWRITE return addr=14734 name=0000.0000
113 kproc 18060 0.047587125 0.004698 unlock: lock addr=38B220 lock status=0000 return addr=14868 name=0000.0000
211 kproc 18060 0.047593124 0.005999 NFS3_UTILITY 0000 0011 D2=3002DCC0 D3=1770 D4=65F883E7 D5=14F8
211 kproc 18060 0.047595895 0.002771 NFS3_ASYWKUP D1=326DAA44 D2=32CD4900 D3=14F8 D4=0004 D5=91D5
211 kproc 18060 0.047602232 0.006337 NFS3_BIO D1=0001 D2=0000 D3=32BD742C D4=32A294E0 D5=0000
211 kproc 18060 0.047603075 0.000843 NFS3_BIO D1=0002 D2=0000 D3=C0001 D4=0000 D5=1000
211 kproc 18060 0.047604472 0.001397 NFS3_BIO D1=0006 D2=32BD742C D3=0000 D4=1000 D5=0000
211 kproc 18060 0.047608447 0.003975 NFS3_BIO D1=0006 D2=32A294E0 D3=32BD742C D4=32A294E0 D5=0000
211 kproc 18060 0.047612374 0.003927 NFS3READ D1=32BD742C D2=0000 D3=1000 D4=40000000 D5=0000
112 kproc 18060 0.047625313 0.012939 lock: lock lock addr=328943C8 lock status=10000001 requested_mode=L
OCK_READ return addr=5450EB4 name=0000.0000
113 kproc 18060 0.047630421 0.005108 unlock: lock addr=328943C8 lock status=0000 return addr=5450F0C name=0000.00
00
216 kproc 18060 0.047635143 0.004722 CLNTTCP_INIT_ENTRY CLIENT=30032814 addr=C0A8406E prog=186A3 vers=00
03 cred=32C8F700
216 kproc 18060 0.047635143* CLNTRTCM_CREATE_ENTRY svcaddr=326EA408 prog=186A3 vers=0003
216 kproc 18060 0.047635143* CLNTRTCM_CREATE_EXIT rtcm=32710180
216 kproc 18060 0.047646974 0.011831 CLNTTCP_INIT_EXIT
216 kproc 18060 0.047669166 0.022192 CLNTTCP_CALLIT_ENTRY CLIENT=30032814 proc=0006 xid=769BB4FD
216 kproc 18060 0.047669166* CLNTRTCM_HOLD rtcm=32710180 refcnt=0001
254 kproc 18060 0.047676153 0.006987 MBUF m_getclustm canwait=M_WAIT type=MT_HEADER callfrom=0545A690 callfrom2=0
54603F4 pid=18060 (kproc)
254 kproc 18060 0.047690755 0.014602 MBUF return from m_getclustm mbuf=703F3B00 dataptr=708E5800
216 kproc 18060 0.047690755* CLNTRTCM_SEND_ENTRY rtcm=32710180 CLIENT=30032814 mbuf=703F3B00
253 kproc 18060 0.047738561 0.047806 SOCK sosend soaddr=70744400 sndaddr=00000000 uio=00000000 top=1883192064 con
trl=00000000
254 kproc 18060 0.047774174 0.035613 MBUF m_get canwait=M_DONTWAIT type=MT_HEADER callfrom=0526B2BC
254 kproc 18060 0.047777595 0.003421 MBUF return from m_get mbuf=708C7D00 dataptr=708C7D1C
254 kproc 18060 0.047783811 0.006216 MBUF m_copydata mbuf=703F3B00 offset=0 len=148 cpaddr=708C7D6C
254 kproc 18060 0.047787762 0.003951 MBUF return from m_copydata
255 kproc 18060 0.047823761 0.035999 NETIF_EN en_output(entry) ifp=326F44C0 m=708C7D00 family=2 ipaddr=192.168.64
.110
254 kproc 18060 0.047850844 0.027083 MBUF m_copydata mbuf=708C7D00 offset=0 len=202 cpaddr=70819800
254 kproc 18060 0.047853133 0.002289 MBUF return from m_copydata
2EA kproc 18060 0.047857711 0.004578 PCI GXENT DD XMT: WQUE d1=656E3400 d2=708C7D00 d3=000000CA
2EA kproc 18060 0.047861494 0.003783 PCI GXENT DD XMT: TtcB d1=3287B000 d2=000000A6 d3=000000A6
2EA kproc 18060 0.047862168 0.000674 PCI GXENT DD XMT: TtcC d1=00000006 d2=00000000 d3=000000AC
2EA kproc 18060 0.047864071 0.001903 PCI GXENT DD XMT: TtcE d1=000000AC d2=00000006 d3=00000000
253 kproc 18060 0.047879203 0.015132 SOCK return from sosend error=0
216 kproc 18060 0.047879203* CLNTRTCM_SEND_EXIT return code=0000
216 kproc 18060 0.047879203* CLNTRTCM_RECV_ENTRY rtcm=32710180 CLIENT=30032814 time_out=0BB8
216 kproc 18060 0.047879203* CLNTRTCM_RECV_ENTRY rtcm=00AB CLIENT=0008 time_out=65F883E7
253 kproc 18060 0.047900696 0.021493 SOCK soreceive soaddr=70744400 paddr=00000000 uio=F0299870 mpo=-265709480 co
ntrl=00000000
460 kproc 18060 0.047906985 0.006289 e_assert_wait: tid=37333 anchor=7074446C flag=1 lr=BA604
112 kproc 18060 0.047912768 0.005783 lock: lock lock addr=38B220 lock status=10000001 requested_mode=LOC
K_READ return addr=148CC name=0000.0000
113 kproc 18060 0.047919129 0.006361 unlock: lock addr=38B220 lock status=0000 return addr=14B10 name=0000.0000
462 kproc 18060 0.047920068 0.000939 e_block_thread: tid=37333 anchor=7074446C t_flags=4001000 lr=BA718
10E kproc 516 0.047930260 0.010192 relock: lock addr=3763A0 oldtid=517 newtid=517
10C kproc 516 0.047930862 0.000602 dispatch: idle process pid=516 tid=517 priority=127 old_tid=37333 old_pri
ority=60 CPUID=0
200 kproc 516 0.047931994 0.001132 resume IDLE iar=1EB3C cpuid=00
100 kproc 774 0.048047798 0.115804 I/O INTERRUPT iar=1EAA0 cpuid=01
102 kproc 774 1 0.048053050 0.005252 slih cpuid=01 gxentdd [3851 usec]
254 kproc 774 1 0.048073266 0.020216 MBUF m_getclustm canwait=M_DONTWAIT type=MT_DATA callfrom=051DFFB4 callfrom2
=051E4690 pid=-1 (--1-)
254 kproc 774 1 0.048086856 0.013590 MBUF return from m_getclustm mbuf=70662200 dataptr=70A38000
2EB kproc 774 1 0.048098711 0.011855 PCI GXENT DD RCV: RDAT d1=656E3400 d2=000005EA d3=00000000
2EB kproc 774 1 0.048099554 0.000843 PCI GXENT DD RCV: RNOT d1=656E3400 d2=7063E000 d3=000005EA
700 kproc 774 1 0.048120782 0.021228 UNDEFINED TRACE ID idx 0x22ed4 traceid 0700
hookword 700E0045 type 0E
hookdata 0045 05275A38 0537E520 00000000 00000000 00000000
254 kproc 774 1 0.048172732 0.051950 MBUF m_free mbuf=703F3B00 dataptr=708E5858 callfrom=05233E38 callfrom2=05235
A8C pid=-1 (--1-)
254 kproc 774 1 0.048187285 0.014553 MBUF return from m_free mbuf=703F3B00
464 kproc 774 1 0.048202610 0.015325 e_wakeup_one: tid=37333 anchor=7074446C lr=AF1C8
11F kproc 774 1 0.048204850 0.002240 setrq: cmd=kproc pid=18060 tid=37333 priority=60 policy=0
10E kproc 516 1 0.048214440 0.009590 relock: lock addr=3763A0 oldtid=517 newtid=517
10E kproc 18060 1 0.048218464 0.004024 relock: lock addr=3763A0 oldtid=517 newtid=37333
106 kproc 18060 1 0.048219331 0.000867 dispatch: cmd=kproc pid=18060 tid=37333 priority=60 old_tid=517 old_priori
ty=127 CPUID=0 [649 usec]
200 kproc 18060 1 0.048219957 0.000626 resume kproc iar=3DB94 cpuid=00
112 kproc 18060 0.048222800 0.002843 lock: lock lock addr=38B220 lock status=200091D5 requested_mode=LOC
K_CWRITE return addr=14734 name=0000.0000
113 kproc 18060 0.048223860 0.001060 unlock: lock addr=38B220 lock status=0000 return addr=14868 name=0000.0000
2EB kproc 774 0.048228992 0.005132 PCI GXENT DD RCV: REND d1=656E3400 d2=7063E000 d3=00000000
254 kproc 774 0.048231907 0.002915 MBUF m_getclustm canwait=M_DONTWAIT type=MT_DATA callfrom=051DFFB4 callfrom2
=051E4690 pid=-1 (--1-)
254 kproc 774 0.048236292 0.004385 MBUF return from m_getclustm mbuf=7089DD00 dataptr=70926000
254 kproc 18060 0.048237520 0.001228 MBUF m_copy mbuf=7063E000 offset=0 len=4
2EB kproc 774 0.048240387 0.002867 PCI GXENT DD RCV: RDAT d1=656E3400 d2=00000306 d3=00000000
254 kproc 18060 0.048241013 0.000626 MBUF m_get canwait=M_WAIT type=MT_DATA callfrom=000D52B4
2EB kproc 774 0.048241711 0.000698 PCI GXENT DD RCV: RNOT d1=656E3400 d2=70AF3300 d3=00000306
700 kproc 774 0.048244771 0.003060 UNDEFINED TRACE ID idx 0x230f4 traceid 0700
hookword 700E0045 type 0E
hookdata 0045 05275A38 0537E520 00000000 00000000 00000000
254 kproc 18060 0.048247276 0.002505 MBUF return from m_get mbuf=703F3B00 dataptr=703F3B14
254 kproc 18060 0.048254360 0.007084 MBUF return from m_copy top=703F3B00
2EB kproc 774 0.048258721 0.004361 PCI GXENT DD RCV: REND d1=656E3400 d2=70AF3300 d3=00000000
103 kproc 774 0.048266407 0.007686 return from slih rc=0000 cpuid=01 [213 usec]
200 kproc 774 0.048270286 0.003879 resume IDLE iar=1EAA0 cpuid=01
254 kproc 18060 0.048276743 0.006457 MBUF m_free mbuf=703F3B00 dataptr=707B0036 callfrom=0545BE74 callfrom2=0545B
77C pid=18060 (kproc)
254 kproc 18060 0.048284285 0.007542 MBUF return from m_free mbuf=703F3B00
253 kproc 18060 0.048286935 0.002650 SOCK soreceive soaddr=70744400 paddr=00000000 uio=F0299870 mpo=-265709480 co
ntrl=00000000
216 kproc 18060 0.048286935* CLNTRTCM_SORECV_EXIT return code=0000
216 kproc 18060 0.048286935* CLNTRTCM_RECV_EXIT_1 return code=0000
254 kproc 18060 0.048364572 0.077637 MBUF m_free mbuf=7063E000 dataptr=707B003A callfrom=0545AB90 callfrom2=05460
3F4 pid=18060 (kproc)
254 kproc 18060 0.048373607 0.009035 MBUF return from m_free mbuf=7063E000
254 kproc 18060 0.048373992 0.000385 MBUF m_free mbuf=70AF3300 dataptr=7051B036 callfrom=0545AB90 callfrom2=05460
3F4 pid=18060 (kproc)
254 kproc 18060 0.048379293 0.005301 MBUF return from m_free mbuf=70AF3300
216 kproc 18060 0.048379293* CLNTRTCM_RELE rtcm=32710180 refcnt=0000
216 kproc 18060 0.048379293* CLNTTCP_CALLIT_EXIT return code=0000
211 kproc 18060 0.048398401 0.019108 NFS3READ D1=32BD742C D2=0001 D3=0800 D4=40001000 D5=0000
211 kproc 18060 0.048442472 0.044071 NFS3_BIO D1=0010 D2=ECACBAD0 D3=32BD7400 D4=32BD7518 D5=F0299E18
211 kproc 18060 0.048448038 0.005566 NFS3_BIO D1=0014 D2=32BD742C D3=0000 D4=1000 D5=40000000
211 kproc 18060 0.048451146 0.003108 NFS3_BIO D1=0011 D2=32A294E0 D3=32A294E0 D4=8C0001 D5=0000
100 kproc 18060 0.048458422 0.007276 QUEUED INTERRUPT iar=9428 cpuid=00
1BE kproc 18060 0.048475024 0.016602 VMM page fault end: V.S=0000.25695 ppage=22331
client_segment interruptable large (type 0)
error=0000 B_READ
11F kproc 18060 0.048484084 0.009060 setrq: cmd=dd pid=33522 tid=21339 priority=60 policy=0
10E kproc 1290 0.048492565 0.008481 relock: lock addr=376B20 oldtid=1291 newtid=1291
10E dd 33522 0.048496854 0.004289 relock: lock addr=376B20 oldtid=1291 newtid=21339
106 dd 33522 0.048497480 0.000626 dispatch: cmd=dd pid=33522 tid=21339 priority=60 old_tid=1291 old_priority
=127 CPUID=3 [278 usec]
200 dd 33522 0.048498323 0.000843 resume dd iar=1450E0 cpuid=03
100 dd 33522 0.048551743 0.053420 DATA ACCESS PAGE FAULT iar=1450E8 cpuid=03
200 kproc 18060 0.048552176 0.000433 resume kproc iar=9428 cpuid=00
1B2 dd 33522 0.048553935 0.001759 VMM pagefault: V.S=0020.4245
working_storage process_private computational (type 2)
211 kproc 18060 0.048554850 0.000915 NFS3_BIO D1=0012 D2=0001 D3=0000 D4=0000 D5=0000
211 kproc 18060 0.048556127 0.001277 NFS3_BIO D1=0013 D2=0001 D3=0000 D4=6120 D5=0000
117 kproc 18060 0.048566319 0.010192 xmfree fastpath: address=32CD4900 heap=3FFBD0B8
460 kproc 18060 0.048575017 0.008698 e_assert_wait: tid=37333 anchor=326E5140 flag=0 lr=54430A0
112 kproc 18060 0.048578944 0.003927 lock: lock lock addr=38B220 lock status=10000001 requested_mode=LOC
K_READ return addr=148CC name=0000.0000
113 kproc 18060 0.048583112 0.004168 unlock: lock addr=38B220 lock status=0000 return addr=14B10 name=0000.0000
462 kproc 18060 0.048584099 0.000987 e_block_thread: tid=37333 anchor=326E5140 t_flags=1000 lr=54430C0
10E kproc 516 0.048589713 0.005614 relock: lock addr=3763A0 oldtid=517 newtid=517
10C kproc 516 0.048590556 0.000843 dispatch: idle process pid=516 tid=517 priority=127 old_tid=37333 old_pri
ority=60 CPUID=0
200 kproc 516 0.048591519 0.000963 resume IDLE iar=1EB3C cpuid=00
1B9 dd 33522 0.048597349 0.005830 VMM zero filled page: V.S=0020.4245 ppage=9F00
working_storage process_private computational (type 2)
200 dd 33522 0.048599276 0.001927 resume dd iar=1450E8 cpuid=03
211 dd 33522 0.048610360 0.011084 NFS3_READ D1=32BD742C D2=0001 D3=0200 D4=0000 D5=0088
113 dd 33522 0.048614287 0.003927 unlock: lock addr=32BD74A0 lock status=0000 return addr=544397C name=0000.00
00
104 dd 33522 0.048616961 0.002674 return from kread [1251 usec]
100 dd 33522 0.048626792 0.009831 DATA ACCESS PAGE FAULT iar=10002FD4 cpuid=03
1B2 dd 33522 0.048629032 0.002240 VMM pagefault: V.S=0000.2C2FE
working_storage computational permfreeze (type 1)
1B9 dd 33522 0.048667464 0.038432 VMM zero filled page: V.S=0000.2C2FE ppage=7D1E7
working_storage computational permfreeze (type 1)
200 dd 33522 0.048668909 0.001445 resume dd iar=10002FD4 cpuid=03
101 dd 33522 0.048696474 0.027565 kwrite LR = D017DF00
19C dd 33522 0.048698714 0.002240 write(6,20001358,8)
11F dd 33522 0.048709484 0.010770 setrq: cmd=dd pid=27412 tid=34955 priority=60 policy=0
104 dd 33522 0.048717122 0.007638 return from kwrite [20 usec]

Detailed description of an NFS Read

Here's a blog post by a guy at Sun which goes into very deep detail on what happens when a read() is done against a file on an NFS filesystem. Amongst other things it explains, why we see GETATTR's turn up at the NFS server, even when the attributes should be cached locally (the answer is that a GETATTR is performed at file open() time regardless of the timeouts on the attribute cache) There is a 40 page PDF document linked to the post.

http://blogs.sun.com/vallishguru/entry/solaris_kernel_nfs_client_s