xref: /src/external/cddl/dtracetoolkit/dist/Docs/Examples/pfilestat_example.txt

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.