diff options
Diffstat (limited to 'Examples/pfilestat_example.txt')
| -rw-r--r-- | Examples/pfilestat_example.txt | 200 |
1 files changed, 200 insertions, 0 deletions
diff --git a/Examples/pfilestat_example.txt b/Examples/pfilestat_example.txt new file mode 100644 index 000000000000..b2c54a031f0c --- /dev/null +++ b/Examples/pfilestat_example.txt @@ -0,0 +1,200 @@ +The following are sample outputs of the pfilestat tool for various scenarios. + + + +Starting with something simple, + +Running: dd if=/dev/rdsk/c0d0s0 of=/dev/null bs=56k # x86, 32-bit + + # ./pfilestat `pgrep -x dd` + + STATE FDNUM Time Filename + read 3 2% /devices/pci@0,0/pci-ide@1f,1/ide@0/cmdk@0,0 + write 4 3% /devices/pseudo/mm@0:null + waitcpu 0 7% + running 0 16% + sleep-r 0 69% + + STATE FDNUM KB/s Filename + write 4 53479 /devices/pseudo/mm@0:null + read 3 53479 /devices/pci@0,0/pci-ide@1f,1/ide@0/cmdk@0,0 + + Total event time (ms): 4999 Total Mbytes/sec: 104 + +Most of the time we are sleeping on read, which is to be expected as dd on +the raw device is simple -> read:entry, strategy, biodone, read:return. +CPU time in read() itself is small. + + + +Now for the dsk device, + +Running: dd if=/dev/dsk/c0d0s0 of=/dev/null bs=56k # x86, 32-bit + + # ./pfilestat `pgrep -x dd` + + STATE FDNUM Time Filename + write 4 5% /devices/pseudo/mm@0:null + waitcpu 0 8% + running 0 15% + sleep-r 0 18% + read 3 53% /devices/pci@0,0/pci-ide@1f,1/ide@0/cmdk@0,0 + + STATE FDNUM KB/s Filename + read 3 53492 /devices/pci@0,0/pci-ide@1f,1/ide@0/cmdk@0,0 + write 4 53492 /devices/pseudo/mm@0:null + + Total event time (ms): 4914 Total Mbytes/sec: 102 + +Woah, we are now spending much more time in read()! I imagine segmap is +a busy bee. The "running" and "write" times are hardly different. + + + +Now for a SPARC demo of the same, + +Running: dd if=/dev/dsk/c0d0s0 of=/dev/null bs=56k # SPARC, 64-bit + + # ./pfilestat `pgrep -x dd` + + STATE FDNUM Time Filename + write 4 3% /devices/pseudo/mm@0:zero + waitcpu 0 7% + running 0 17% + read 3 24% /devices/pci@1f,0/pci@1,1/ide@3/dad@0,0:a + sleep-r 0 54% + + STATE FDNUM KB/s Filename + read 3 13594 /devices/pci@1f,0/pci@1,1/ide@3/dad@0,0:a + write 4 13606 /devices/pseudo/mm@0:zero + + Total event time (ms): 4741 Total Mbytes/sec: 25 + +I did prime the cache by running this a few times first. There is less +read() time than with the x86 32-bit demo, as I would guess that the +process is more often exhausting the (faster) segmap cache and getting +to the point where it must sleep. (However, do take this comparison with +a grain of salt - my development servers aren't ideal for comparing +statistics: one is a 867 MHz Pentium, and the other a 360 MHz Ultra 5). + +The file system cache is faster on 64-bit systems due to the segkpm +enhancement in Solaris 10. For details see, +http://blogs.sun.com/roller/page/rmc?entry=solaris_10_fast_filesystem_cache + + + +Now, back to x86. + +Running: tar cf /dev/null / + + # ./pfilestat `pgrep -x tar` + + STATE FDNUM Time Filename + read 11 0% /extra1/test/amd64/libCstd.so.1 + read 11 0% /extra1/test/amd64/libXm.so + read 11 0% /extra1/test/amd64/libXm.so.4 + read 11 1% /extra1/test/amd64/libgtk-x11-2.0.so + read 11 2% /extra1/test/amd64/libgtk-x11-2.0.so.0 + waitcpu 0 2% + read 9 4% /extra1/5000 + write 3 7% /devices/pseudo/mm@0:null + running 0 19% + sleep-r 0 46% + + STATE FDNUM KB/s Filename + read 11 293 /extra1/test/amd64/libgdk-x11-2.0.so + read 11 295 /extra1/test/amd64/libgdk-x11-2.0.so.0 + read 9 476 /extra1/1000 + read 11 526 /extra1/test/amd64/libCstd.so.1 + read 11 594 /extra1/test/amd64/libXm.so.4 + read 11 594 /extra1/test/amd64/libXm.so + read 11 1603 /extra1/test/amd64/libgtk-x11-2.0.so.0 + read 11 1606 /extra1/test/amd64/libgtk-x11-2.0.so + read 9 4078 /extra1/5000 + write 3 21254 /devices/pseudo/mm@0:null + + Total event time (ms): 4903 Total Mbytes/sec: 41 + +Fair enough. tar is crusing along at 21 Mbytes/sec (writes to fd 3!). + + + +More interesting is to do the following, + +Running: tar cf - / | gzip > /dev/null + + # ./pfilestat `pgrep -x tar` + + STATE FDNUM Time Filename + read 11 0% /extra1/test/amd64/libm.so + read 11 0% /extra1/test/amd64/libm.so.2 + read 11 0% /extra1/test/amd64/libnsl.so + read 11 0% /extra1/test/amd64/libnsl.so.1 + read 11 0% /extra1/test/amd64/libc.so.1 + write 3 2% <none> + waitcpu 0 4% + sleep-r 0 4% + running 0 6% + sleep-w 0 78% + + STATE FDNUM KB/s Filename + read 11 74 /extra1/test/amd64/libldap.so + read 11 75 /extra1/test/amd64/libldap.so.5 + read 11 75 /extra1/test/amd64/libresolv.so.2 + read 11 76 /extra1/test/amd64/libresolv.so + read 11 97 /extra1/test/amd64/libm.so.2 + read 11 98 /extra1/test/amd64/libm.so + read 11 174 /extra1/test/amd64/libnsl.so + read 11 176 /extra1/test/amd64/libnsl.so.1 + read 11 216 /extra1/test/amd64/libc.so.1 + write 3 3022 <none> + + Total event time (ms): 4911 Total Mbytes/sec: 6 + +Woah now, tar is writing 3 Mbytes/sec - AND spending 78% of it's time on +sleep-w, sleeping on writes! Of course, this is because we are piping the +output to gzip, which is spending a while compressing the data. 78% +matches the time gzip was on the CPU (using either "prstat -m" or dtrace +to measure; procfs's pr_pctcpu would take too long to catch up). + + + + +Also interesting is, + +Running: perl -e 'while (1) {;}' & +Running: perl -e 'while (1) {;}' & +Running: perl -e 'while (1) {;}' & +Running: perl -e 'while (1) {;}' & +Running: tar cf /dev/null / + + # ./pfilestat `pgrep -x tar` + + STATE FDNUM Time Filename + read 11 0% /extra1/test/amd64/libxml2.so.2 + read 11 0% /extra1/test/amd64/libgdk-x11-2.0.so.0 + read 11 0% /extra1/test/amd64/libgdk-x11-2.0.so + read 11 0% /extra1/test/amd64/libCstd.so.1 + read 11 0% /extra1/test/amd64/libgtk-x11-2.0.so.0 + read 11 2% /extra1/test/amd64/libgtk-x11-2.0.so + write 3 2% /devices/pseudo/mm@0:null + running 0 8% + sleep-r 0 22% + waitcpu 0 65% + + STATE FDNUM KB/s Filename + read 11 182 /extra1/test/amd64/libsun_fc.so + read 11 264 /extra1/test/amd64/libglib-2.0.so + read 11 266 /extra1/test/amd64/libglib-2.0.so.0 + read 11 280 /extra1/test/amd64/libxml2.so.2 + read 11 293 /extra1/test/amd64/libgdk-x11-2.0.so + read 11 295 /extra1/test/amd64/libgdk-x11-2.0.so.0 + read 11 526 /extra1/test/amd64/libCstd.so.1 + read 11 761 /extra1/test/amd64/libgtk-x11-2.0.so.0 + read 11 1606 /extra1/test/amd64/libgtk-x11-2.0.so + write 3 7881 /devices/pseudo/mm@0:null + + Total event time (ms): 4596 Total Mbytes/sec: 13 + +Now we have "waitcpu" as tar competes for CPU cycles along with the greedy +infinite perl processes. |