1 The following are sample outputs of the pfilestat tool for various scenarios.
5 Starting with something simple,
7 Running: dd if=/dev/rdsk/c0d0s0 of=/dev/null bs=56k # x86, 32-bit
9 # ./pfilestat `pgrep -x dd`
11 STATE FDNUM Time Filename
12 read 3 2% /devices/pci@0,0/pci-ide@1f,1/ide@0/cmdk@0,0
13 write 4 3% /devices/pseudo/mm@0:null
18 STATE FDNUM KB/s Filename
19 write 4 53479 /devices/pseudo/mm@0:null
20 read 3 53479 /devices/pci@0,0/pci-ide@1f,1/ide@0/cmdk@0,0
22 Total event time (ms): 4999 Total Mbytes/sec: 104
24 Most of the time we are sleeping on read, which is to be expected as dd on
25 the raw device is simple -> read:entry, strategy, biodone, read:return.
26 CPU time in read() itself is small.
30 Now for the dsk device,
32 Running: dd if=/dev/dsk/c0d0s0 of=/dev/null bs=56k # x86, 32-bit
34 # ./pfilestat `pgrep -x dd`
36 STATE FDNUM Time Filename
37 write 4 5% /devices/pseudo/mm@0:null
41 read 3 53% /devices/pci@0,0/pci-ide@1f,1/ide@0/cmdk@0,0
43 STATE FDNUM KB/s Filename
44 read 3 53492 /devices/pci@0,0/pci-ide@1f,1/ide@0/cmdk@0,0
45 write 4 53492 /devices/pseudo/mm@0:null
47 Total event time (ms): 4914 Total Mbytes/sec: 102
49 Woah, we are now spending much more time in read()! I imagine segmap is
50 a busy bee. The "running" and "write" times are hardly different.
54 Now for a SPARC demo of the same,
56 Running: dd if=/dev/dsk/c0d0s0 of=/dev/null bs=56k # SPARC, 64-bit
58 # ./pfilestat `pgrep -x dd`
60 STATE FDNUM Time Filename
61 write 4 3% /devices/pseudo/mm@0:zero
64 read 3 24% /devices/pci@1f,0/pci@1,1/ide@3/dad@0,0:a
67 STATE FDNUM KB/s Filename
68 read 3 13594 /devices/pci@1f,0/pci@1,1/ide@3/dad@0,0:a
69 write 4 13606 /devices/pseudo/mm@0:zero
71 Total event time (ms): 4741 Total Mbytes/sec: 25
73 I did prime the cache by running this a few times first. There is less
74 read() time than with the x86 32-bit demo, as I would guess that the
75 process is more often exhausting the (faster) segmap cache and getting
76 to the point where it must sleep. (However, do take this comparison with
77 a grain of salt - my development servers aren't ideal for comparing
78 statistics: one is a 867 MHz Pentium, and the other a 360 MHz Ultra 5).
80 The file system cache is faster on 64-bit systems due to the segkpm
81 enhancement in Solaris 10. For details see,
82 http://blogs.sun.com/roller/page/rmc?entry=solaris_10_fast_filesystem_cache
88 Running: tar cf /dev/null /
90 # ./pfilestat `pgrep -x tar`
92 STATE FDNUM Time Filename
93 read 11 0% /extra1/test/amd64/libCstd.so.1
94 read 11 0% /extra1/test/amd64/libXm.so
95 read 11 0% /extra1/test/amd64/libXm.so.4
96 read 11 1% /extra1/test/amd64/libgtk-x11-2.0.so
97 read 11 2% /extra1/test/amd64/libgtk-x11-2.0.so.0
99 read 9 4% /extra1/5000
100 write 3 7% /devices/pseudo/mm@0:null
104 STATE FDNUM KB/s Filename
105 read 11 293 /extra1/test/amd64/libgdk-x11-2.0.so
106 read 11 295 /extra1/test/amd64/libgdk-x11-2.0.so.0
107 read 9 476 /extra1/1000
108 read 11 526 /extra1/test/amd64/libCstd.so.1
109 read 11 594 /extra1/test/amd64/libXm.so.4
110 read 11 594 /extra1/test/amd64/libXm.so
111 read 11 1603 /extra1/test/amd64/libgtk-x11-2.0.so.0
112 read 11 1606 /extra1/test/amd64/libgtk-x11-2.0.so
113 read 9 4078 /extra1/5000
114 write 3 21254 /devices/pseudo/mm@0:null
116 Total event time (ms): 4903 Total Mbytes/sec: 41
118 Fair enough. tar is crusing along at 21 Mbytes/sec (writes to fd 3!).
122 More interesting is to do the following,
124 Running: tar cf - / | gzip > /dev/null
126 # ./pfilestat `pgrep -x tar`
128 STATE FDNUM Time Filename
129 read 11 0% /extra1/test/amd64/libm.so
130 read 11 0% /extra1/test/amd64/libm.so.2
131 read 11 0% /extra1/test/amd64/libnsl.so
132 read 11 0% /extra1/test/amd64/libnsl.so.1
133 read 11 0% /extra1/test/amd64/libc.so.1
140 STATE FDNUM KB/s Filename
141 read 11 74 /extra1/test/amd64/libldap.so
142 read 11 75 /extra1/test/amd64/libldap.so.5
143 read 11 75 /extra1/test/amd64/libresolv.so.2
144 read 11 76 /extra1/test/amd64/libresolv.so
145 read 11 97 /extra1/test/amd64/libm.so.2
146 read 11 98 /extra1/test/amd64/libm.so
147 read 11 174 /extra1/test/amd64/libnsl.so
148 read 11 176 /extra1/test/amd64/libnsl.so.1
149 read 11 216 /extra1/test/amd64/libc.so.1
152 Total event time (ms): 4911 Total Mbytes/sec: 6
154 Woah now, tar is writing 3 Mbytes/sec - AND spending 78% of it's time on
155 sleep-w, sleeping on writes! Of course, this is because we are piping the
156 output to gzip, which is spending a while compressing the data. 78%
157 matches the time gzip was on the CPU (using either "prstat -m" or dtrace
158 to measure; procfs's pr_pctcpu would take too long to catch up).
165 Running: perl -e 'while (1) {;}' &
166 Running: perl -e 'while (1) {;}' &
167 Running: perl -e 'while (1) {;}' &
168 Running: perl -e 'while (1) {;}' &
169 Running: tar cf /dev/null /
171 # ./pfilestat `pgrep -x tar`
173 STATE FDNUM Time Filename
174 read 11 0% /extra1/test/amd64/libxml2.so.2
175 read 11 0% /extra1/test/amd64/libgdk-x11-2.0.so.0
176 read 11 0% /extra1/test/amd64/libgdk-x11-2.0.so
177 read 11 0% /extra1/test/amd64/libCstd.so.1
178 read 11 0% /extra1/test/amd64/libgtk-x11-2.0.so.0
179 read 11 2% /extra1/test/amd64/libgtk-x11-2.0.so
180 write 3 2% /devices/pseudo/mm@0:null
185 STATE FDNUM KB/s Filename
186 read 11 182 /extra1/test/amd64/libsun_fc.so
187 read 11 264 /extra1/test/amd64/libglib-2.0.so
188 read 11 266 /extra1/test/amd64/libglib-2.0.so.0
189 read 11 280 /extra1/test/amd64/libxml2.so.2
190 read 11 293 /extra1/test/amd64/libgdk-x11-2.0.so
191 read 11 295 /extra1/test/amd64/libgdk-x11-2.0.so.0
192 read 11 526 /extra1/test/amd64/libCstd.so.1
193 read 11 761 /extra1/test/amd64/libgtk-x11-2.0.so.0
194 read 11 1606 /extra1/test/amd64/libgtk-x11-2.0.so
195 write 3 7881 /devices/pseudo/mm@0:null
197 Total event time (ms): 4596 Total Mbytes/sec: 13
199 Now we have "waitcpu" as tar competes for CPU cycles along with the greedy
200 infinite perl processes.