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.

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 9do  dd if=$i of=/dev/nulldone 

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=00000000104 dd             33522         0.047360376       0.002048           return from _sigaction [2 usec]101 dd             33522         0.047365580       0.005204           kread LR = D01846E0163 dd             33522         0.047367098       0.001518           read(0,20020000,200) 1112 dd             33522         0.047378423       0.011325                   lock:          lock lock addr=32BD74A0 lock status=10000001 requested_mode=LOCK_READ return addr=54439F0 name=0000.0000211 dd             33522         0.047387579       0.009156                   NFS3_READ    D1=32BD742C D2=0000 D3=0000 D4=0200 D5=0088100 dd             33522         0.047420349       0.032770                           DATA ACCESS PAGE FAULT iar=1450E0 cpuid=031B2 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=76B7C1BA dd             33522         0.047467888       0.019276                   VMM start io:         V.S=0000.25695 ppage=22331                                                                                  client_segment interruptable large (type 0)                                                                                  bp=32A294E0 B_READ464 dd             33522         0.047491236       0.023348                   e_wakeup_one:   tid=19093 anchor=54AD48C lr=5462ED011F dd             33522         0.047494175       0.002939                   setrq:   cmd=kproc pi
d=18060 tid=19093 priority=60 policy=010E kproc          774           0.047502463       0.008288                   relock: lock addr=376620  oldtid=775  newtid=77510E kproc          18060         0.047507233       0.004770                   relock: lock addr=376620  oldtid=775  newtid=19093106 kproc          18060         0.047508775       0.001542                   dispatch:   cmd=kproc pid=18060 tid=19093 priority=60 old_tid=775 old_priority=127 CPUID=1 [276 usec]10E kproc          1290          0.047509449       0.000674                   relock: lock addr=376B20  oldtid=1291  newtid=129110C kproc          1290          0.047511328       0.001879                   dispatch:   idle process  pid=1290 tid=1291 priority=127 old_tid=21339 old_priority=60 CPUID=3200 kproc          18060         0.047512219       0.000891                   resume  kproc iar=3DB94 cpuid=01200 kproc          1290          0.047512821       0.000602                   resume  IDLE iar=1EB3C cpuid=03116 kproc          18060         0.047534001       0.021180                   xmalloc fastpath:   size=0018 align=0002 heap=3FFBD0B8116 kproc          18060         0.047536241       0.002240                   xmalloc return:     result=32CD4900464 kproc          18060         0.047550240       0.013999                   e_wakeup_one:   tid=37333 anchor=326E5140 lr=5461BAC11F kproc          18060         0.047552770       0.002530                   setrq:   cmd=kproc pid=18060 tid=37333 priority=60 policy=0460 kproc          18060         0.047561251       0.008481                   e_assert_wait:   tid=19093 anchor=54AD48C flag=0 lr=3E27810E kproc          516           0.047561949       0.000698                   relock: lock addr=3763A0  oldtid=517  newtid=517462 kproc          18060         0.047565153       0.003204                   e_block_thread:   tid=19093 anchor=54AD48C t_flags=4001000 lr=3E2A410E kproc          18060         0.047567442       0.002289                   relock: lock addr=3763A0  oldtid=517  newtid=37333106 kproc          18060         0.047569369       0.001927                   dispatch:   cmd=kproc pid=18060 tid=37333 priority=60 old_tid=517 old_priority=127 CPUID=0 [60 usec]10E kproc          774           0.047572212       0.002843                   relock: lock addr=376620  oldtid=775  newtid=775200 kproc          18060         0.047572983       0.000771                   resume  kproc iar=3DB94 cpuid=0010C kproc          774           0.047574260       0.001277                   dispatch:   idle process  pid=774 tid=775 priority=127 old_tid=19093 old_priority=60 CPUID=1200 kproc          774           0.047575464       0.001204                   resume  IDLE iar=1EB3C cpuid=01112 kproc          18060         0.047582427       0.006963                   lock:          lock lock addr=38B220 lock status=200091D5 requested_mode=LOCK_CWRITE return addr=14734 name=0000.0000113 kproc          18060         0.047587125       0.004698                   unlock: lock addr=38B220 lock status=0000 return addr=14868 name=0000.0000211 kproc          18060         0.047593124       0.005999                   NFS3_UTILITY 0000 0011 D2=3002DCC0 D3=1770 D4=65F883E7 D5=14F8211 kproc          18060         0.047595895       0.002771                   NFS3_ASYWKUP D1=326DAA44 D2=32CD4900 D3=14F8 D4=0004 D5=91D5211 kproc          18060         0.047602232       0.006337                   NFS3_BIO     D1=0001 D2=0000 D3=32BD742C D4=32A294E0 D5=0000211 kproc          18060         0.047603075       0.000843                   NFS3_BIO     D1=0002 D2=0000 D3=C0001 D4=0000 D5=1000211 kproc          18060         0.047604472       0.001397                   NFS3_BIO     D1=0006 D2=32BD742C D3=0000 D4=1000 D5=0000211 kproc          18060         0.047608447       0.003975                   NFS3_BIO     D1=0006 D2=32A294E0 D3=32BD742C D4=32A294E0 D5=0000211 kproc          18060         0.047612374       0.003927                   NFS3READ     D1=32BD742C D2=0000 D3=1000 D4=40000000 D5=0000112 kproc          18060         0.047625313       0.012939                   lock:          lock lock addr=328943C8 lock status=10000001 requested_mode=LOCK_READ return addr=5450EB4 name=0000.0000113 kproc          18060         0.047630421       0.005108                   unlock: lock addr=328943C8 lock status=0000 return addr=5450F0C name=0000.0000216 kproc          18060         0.047635143       0.004722                   CLNTTCP_INIT_ENTRY          CLIENT=30032814 addr=C0A8406E prog=186A3 vers=0003 cred=32C8F700216 kproc          18060         0.047635143*                                 CLNTRTCM_CREATE_ENTRY       svcaddr=326EA408 prog=186A3 vers=0003216 kproc          18060         0.047635143*                                 CLNTRTCM_CREATE_EXIT        rtcm=32710180216 kproc          18060         0.047646974       0.011831                   CLNTTCP_INIT_EXIT216 kproc          18060         0.047669166       0.022192                   CLNTTCP_CALLIT_ENTRY        CLIENT=30032814 proc=0006 xid=769BB4FD216 kproc          18060         0.047669166*                                 CLNTRTCM_HOLD               rtcm=32710180 refcnt=0001254 kproc          18060         0.047676153       0.006987                   MBUF m_getclustm canwait=M_WAIT type=MT_HEADER callfrom=0545A690 callfrom2=054603F4 pid=18060 (kproc)254 kproc          18060         0.047690755       0.014602                   MBUF return from m_getclustm mbuf=703F3B00 dataptr=708E5800216 kproc          18060         0.047690755*                                 CLNTRTCM_SEND_ENTRY         rtcm=32710180 CLIENT=30032814 mbuf=703F3B00253 kproc          18060         0.047738561       0.047806                   SOCK sosend soaddr=70744400 sndaddr=00000000 uio=00000000 top=1883192064 contrl=00000000254 kproc          18060         0.047774174       0.035613                   MBUF m_get canwait=M_DONTWAIT type=MT_HEADER callfrom=0526B2BC254 kproc          18060         0.047777595       0.003421                   MBUF return from m_get mbuf=708C7D00 dataptr=708C7D1C254 kproc          18060         0.047783811       0.006216                   MBUF m_copydata mbuf=703F3B00 offset=0 len=148 cpaddr=708C7D6C254 kproc          18060         0.047787762       0.003951                   MBUF return from m_copydata255 kproc          18060         0.047823761       0.035999                   NETIF_EN en_output(entry) ifp=326F44C0 m=708C7D00 family=2 ipaddr=192.168.64.110254 kproc          18060         0.047850844       0.027083                   MBUF m_copydata mbuf=708C7D00 offset=0 len=202 cpaddr=70819800254 kproc          18060         0.047853133       0.002289                   MBUF return from m_copydata2EA kproc          18060         0.047857711       0.004578                   PCI GXENT DD XMT: WQUE    d1=656E3400 d2=708C7D00 d3=000000CA2EA kproc          18060         0.047861494       0.003783                   PCI GXENT DD XMT: TtcB    d1=3287B000 d2=000000A6 d3=000000A62EA kproc          18060         0.047862168       0.000674                   PCI GXENT DD XMT: TtcC    d1=00000006 d2=00000000 d3=000000AC2EA kproc          18060         0.047864071       0.001903                   PCI GXENT DD XMT: TtcE    d1=000000AC d2=00000006 d3=00000000253 kproc          18060         0.047879203       0.015132                   SOCK return from sosend error=0216 kproc          18060         0.047879203*                                 CLNTRTCM_SEND_EXIT          return code=0000216 kproc          18060         0.047879203*                                 CLNTRTCM_RECV_ENTRY         rtcm=32710180 CLIENT=30032814 time_out=0BB8216 kproc          18060         0.047879203*                                 CLNTRTCM_RECV_ENTRY         rtcm=
00AB CLIENT=0008 time_out=65F883E7253 kproc          18060         0.047900696       0.021493                   SOCK soreceive soaddr=70744400 paddr=00000000 uio=F0299870 mpo=-265709480 contrl=00000000460 kproc          18060         0.047906985       0.006289                   e_assert_wait:   tid=37333 anchor=7074446C flag=1 lr=BA604112 kproc          18060         0.047912768       0.005783                   lock:          lock lock addr=38B220 lock status=10000001 requested_mode=LOCK_READ return addr=148CC name=0000.0000113 kproc          18060         0.047919129       0.006361                   unlock: lock addr=38B220 lock status=0000 return addr=14B10 name=0000.0000462 kproc          18060         0.047920068       0.000939                   e_block_thread:   tid=37333 anchor=7074446C t_flags=4001000 lr=BA71810E kproc          516           0.047930260       0.010192                   relock: lock addr=3763A0  oldtid=517  newtid=51710C kproc          516           0.047930862       0.000602                   dispatch:   idle process  pid=516 tid=517 priority=127 old_tid=37333 old_priority=60 CPUID=0200 kproc          516           0.047931994       0.001132                   resume  IDLE iar=1EB3C cpuid=00100 kproc          774           0.048047798       0.115804                           I/O INTERRUPT iar=1EAA0 cpuid=01102 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=70A380002EB kproc          774      1    0.048098711       0.011855                   PCI GXENT DD RCV: RDAT    d1=656E3400 d2=000005EA d3=000000002EB kproc          774      1    0.048099554       0.000843                   PCI GXENT DD RCV: RNOT    d1=656E3400 d2=7063E000 d3=000005EA700 kproc          774      1    0.048120782       0.021228                   UNDEFINED TRACE ID idx 0x22ed4 traceid 0700                                                                              hookword 700E0045 type 0E                                                                              hookdata 0045 05275A38 0537E520 00000000 00000000 00000000254 kproc          774      1    0.048172732       0.051950                   MBUF m_free mbuf=703F3B00 dataptr=708E5858 callfrom=05233E38 callfrom2=05235A8C pid=-1 (--1-)254 kproc          774      1    0.048187285       0.014553                   MBUF return from m_free mbuf=703F3B00464 kproc          774      1    0.048202610       0.015325                   e_wakeup_one:   tid=37333 anchor=7074446C lr=AF1C811F kproc          774      1    0.048204850       0.002240                   setrq:   cmd=kproc pid=18060 tid=37333 priority=60 policy=010E kproc          516      1    0.048214440       0.009590                   relock: lock addr=3763A0  oldtid=517  newtid=51710E kproc          18060    1    0.048218464       0.004024                   relock: lock addr=3763A0  oldtid=517  newtid=37333106 kproc          18060    1    0.048219331       0.000867                   dispatch:   cmd=kproc pid=18060 tid=37333 priority=60 old_tid=517 old_priority=127 CPUID=0 [649 usec]200 kproc          18060    1    0.048219957       0.000626                   resume  kproc iar=3DB94 cpuid=00112 kproc          18060         0.048222800       0.002843                   lock:          lock lock addr=38B220 lock status=200091D5 requested_mode=LOCK_CWRITE return addr=14734 name=0000.0000113 kproc          18060         0.048223860       0.001060                   unlock: lock addr=38B220 lock status=0000 return addr=14868 name=0000.00002EB kproc          774           0.048228992       0.005132                   PCI GXENT DD RCV: REND    d1=656E3400 d2=7063E000 d3=00000000254 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=70926000254 kproc          18060         0.048237520       0.001228                   MBUF m_copy mbuf=7063E000 offset=0 len=42EB kproc          774           0.048240387       0.002867                   PCI GXENT DD RCV: RDAT    d1=656E3400 d2=00000306 d3=00000000254 kproc          18060         0.048241013       0.000626                   MBUF m_get canwait=M_WAIT type=MT_DATA callfrom=000D52B42EB kproc          774           0.048241711       0.000698                   PCI GXENT DD RCV: RNOT    d1=656E3400 d2=70AF3300 d3=00000306700 kproc          774           0.048244771       0.003060                   UNDEFINED TRACE ID idx 0x230f4 traceid 0700                                                                              hookword 700E0045 type 0E                                                                              hookdata 0045 05275A38 0537E520 00000000 00000000 00000000254 kproc          18060         0.048247276       0.002505                   MBUF return from m_get mbuf=703F3B00 dataptr=703F3B14254 kproc          18060         0.048254360       0.007084                   MBUF return from m_copy top=703F3B002EB kproc          774           0.048258721       0.004361                   PCI GXENT DD RCV: REND    d1=656E3400 d2=70AF3300 d3=00000000103 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=01254 kproc          18060         0.048276743       0.006457                   MBUF m_free mbuf=703F3B00 dataptr=707B0036 callfrom=0545BE74 callfrom2=0545B77C pid=18060 (kproc)254 kproc          18060         0.048284285       0.007542                   MBUF return from m_free mbuf=703F3B00253 kproc          18060         0.048286935       0.002650                   SOCK soreceive soaddr=70744400 paddr=00000000 uio=F0299870 mpo=-265709480 contrl=00000000216 kproc          18060         0.048286935*                                 CLNTRTCM_SORECV_EXIT        return code=0000216 kproc          18060         0.048286935*                                 CLNTRTCM_RECV_EXIT_1        return code=0000254 kproc          18060         0.048364572       0.077637                   MBUF m_free mbuf=7063E000 dataptr=707B003A callfrom=0545AB90 callfrom2=054603F4 pid=18060 (kproc)254 kproc          18060         0.048373607       0.009035                   MBUF return from m_free mbuf=7063E000254 kproc          18060         0.048373992       0.000385                   MBUF m_free mbuf=70AF3300 dataptr=7051B036 callfrom=0545AB90 callfrom2=054603F4 pid=18060 (kproc)254 kproc          18060         0.048379293       0.005301                   MBUF return from m_free mbuf=70AF3300216 kproc          18060         0.048379293*                                 CLNTRTCM_RELE               rtcm=32710180 refcnt=0000216 kproc          18060         0.048379293*                                 CLNTTCP_CALLIT_EXIT         return code=0000211 kproc          18060         0.048398401       0.019108                   NFS3READ     D1=32BD742C D2=0001 D3=0800 D4=40001000 D5=0000211 kproc          18060         0.048442472       0.044071                   NFS3_BIO     D1=0010 D2=ECACBAD0 D3=32BD7400 D4=32BD7518 D5=F0299E18211 kproc          18060         0.048448038       0.005566                   NFS3_BIO     D1=0014 D2=32BD742C D3=0000 D4=1000 D5=400000
00211 kproc          18060         0.048451146       0.003108                   NFS3_BIO     D1=0011 D2=32A294E0 D3=32A294E0 D4=8C0001 D5=0000100 kproc          18060         0.048458422       0.007276                           QUEUED INTERRUPT iar=9428 cpuid=001BE 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_READ11F kproc          18060         0.048484084       0.009060                   setrq:   cmd=dd pid=33522 tid=21339 priority=60 policy=010E kproc          1290          0.048492565       0.008481                   relock: lock addr=376B20  oldtid=1291  newtid=129110E dd             33522         0.048496854       0.004289                   relock: lock addr=376B20  oldtid=1291  newtid=21339106 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=03100 dd             33522         0.048551743       0.053420                           DATA ACCESS PAGE FAULT iar=1450E8 cpuid=03200 kproc          18060         0.048552176       0.000433                   resume  kproc iar=9428 cpuid=001B2 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=0000211 kproc          18060         0.048556127       0.001277                   NFS3_BIO     D1=0013 D2=0001 D3=0000 D4=6120 D5=0000117 kproc          18060         0.048566319       0.010192                   xmfree fastpath:    address=32CD4900 heap=3FFBD0B8460 kproc          18060         0.048575017       0.008698                   e_assert_wait:   tid=37333 anchor=326E5140 flag=0 lr=54430A0112 kproc          18060         0.048578944       0.003927                   lock:          lock lock addr=38B220 lock status=10000001 requested_mode=LOCK_READ return addr=148CC name=0000.0000113 kproc          18060         0.048583112       0.004168                   unlock: lock addr=38B220 lock status=0000 return addr=14B10 name=0000.0000462 kproc          18060         0.048584099       0.000987                   e_block_thread:   tid=37333 anchor=326E5140 t_flags=1000 lr=54430C010E kproc          516           0.048589713       0.005614                   relock: lock addr=3763A0  oldtid=517  newtid=51710C kproc          516           0.048590556       0.000843                   dispatch:   idle process  pid=516 tid=517 priority=127 old_tid=37333 old_priority=60 CPUID=0200 kproc          516           0.048591519       0.000963                   resume  IDLE iar=1EB3C cpuid=001B9 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=03211 dd             33522         0.048610360       0.011084                   NFS3_READ    D1=32BD742C D2=0001 D3=0200 D4=0000 D5=0088113 dd             33522         0.048614287       0.003927                   unlock: lock addr=32BD74A0 lock status=0000 return addr=544397C name=0000.0000104 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=031B2 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=03101 dd             33522         0.048696474       0.027565           kwrite LR = D017DF0019C 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=0104 dd             33522         0.048717122       0.007638           return from kwrite [20 usec]

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