In this example we run psio for 10 seconds to an output file and then analyse the file using several techniques. First we create the output file, mars:> ./psio -o out3 10 Now we read the input file, mars:> ./psio -i out3 UID PID PPID %I/O STIME TTY TIME CMD brendan 28320 10093 59.7 04:02:30 pts/20 0:01 pkginfo root 0 0 27.3 Mar 16 ? 0:16 sched brendan 28318 24654 12.7 04:02:28 pts/4 0:00 pine root 5857 5856 0.2 Nov 08 ? 5:13 (squid) -s brendan 6094 10068 0.1 Nov 11 pts/15 7:51 opera root 1 0 0.0 Mar 16 ? 0:10 /etc/init - root 2 0 0.0 Mar 16 ? 0:01 pageout root 3 0 0.0 Mar 16 ? 18:45:07 fsflush [...] From the above it looks like "pkginfo" is causing most of the I/O, and certainly is causing the most I/O wait time. Lets see some more details, mars:> ./psio -xi out3 UID PID %CPU %I/Ot %I/Os %I/Oc %MEM S TIME CMD brendan 28320 3.9 59.7 16.5 60.4 0.5 S 0:01 pkginfo root 0 0.0 27.3 25.1 23.0 0.0 T 0:16 sched brendan 28318 0.7 12.7 58.3 16.3 0.9 S 0:00 pine root 5857 0.0 0.2 0.1 0.1 17.7 S 5:13 (squid) -s brendan 6094 0.0 0.1 0.0 0.1 5.6 S 7:51 opera root 1 0.0 0.0 0.0 0.0 0.1 S 0:10 /etc/init - root 2 0.0 0.0 0.0 0.0 0.0 S 0:01 pageout root 3 0.3 0.0 0.0 0.0 0.0 S 18:45:07 fsflush [...] Now it looks like pkginfo is causing many I/O calls (%I/Oc) but for little size (%I/Os). The program "pine" has transferred the most size. Lets take a closer look, mars:> ./psio -ni out3 UID PID IOTIME IOSIZE IOCOUNT CMD brendan 28320 4047 458241 434 pkginfo root 0 1849 697856 165 sched brendan 28318 863 1622016 117 pine root 5857 13 2048 1 (squid) -s brendan 6094 9 1024 1 opera root 1 0 0 0 /etc/init - root 2 0 0 0 pageout root 3 0 0 0 fsflush root 64 0 0 0 /usr/lib/sysevent/syseventd [...] Looks like most of pkginfo's I/O was at 1024 bytes per operation. pine is transferring at around 13K per operation. Lets see that by filesystem, mars:> ./psio -fni out3 UID PID IOTIME IOSIZE IOCOUNT CMD brendan 28320 4047 458241 434 pkginfo " " 4047 458241 434 /dev/dsk/c0t0d0s5, /var root 0 1849 697856 165 sched " " 999 220672 76 /dev/dsk/c0t0d0s3, /usr " " 701 394752 64 /dev/dsk/c0t0d0s5, /var " " 149 82432 25 /dev/dsk/c0t0d0s6, /export/home brendan 28318 863 1622016 117 pine " " 863 1622016 117 /dev/dsk/c0t0d0s6, /export/home root 5857 13 2048 1 (squid) -s " " 13 2048 1 /dev/dsk/c0t2d0s0, /squidcache brendan 6094 9 1024 1 opera " " 9 1024 1 /dev/dsk/c0t0d0s6, /export/home root 1 0 0 0 /etc/init - root 2 0 0 0 pageout root 3 0 0 0 fsflush [...] So pkginfo was grinding away at /var, and pine was reading a mailbox from /export/home. The "-f" option tries to print the block device name and mount point if they are available. Lets see that as percentages again, mars:> ./psio -fxi out3 UID PID %CPU %I/Ot %I/Os %I/Oc %MEM S TIME CMD brendan 28320 3.9 59.7 16.5 60.4 0.5 S 0:01 pkginfo " " " 59.7 16.5 60.4 /dev/dsk/c0t0d0s5, /var root 0 0.0 27.3 25.1 23.0 0.0 T 0:16 sched " " " 14.7 7.9 10.6 /dev/dsk/c0t0d0s3, /usr " " " 10.3 14.2 8.9 /dev/dsk/c0t0d0s5, /var " " " 2.2 3.0 3.5 /dev/dsk/c0t0d0s6, /export/home brendan 28318 0.7 12.7 58.3 16.3 0.9 S 0:00 pine " " " 12.7 58.3 16.3 /dev/dsk/c0t0d0s6, /export/home root 5857 0.0 0.2 0.1 0.1 17.7 S 5:13 (squid) -s " " " 0.2 0.1 0.1 /dev/dsk/c0t2d0s0, /squidcache brendan 6094 0.0 0.1 0.0 0.1 5.6 S 7:51 opera " " " 0.1 0.0 0.1 /dev/dsk/c0t0d0s6, /export/home root 1 0.0 0.0 0.0 0.0 0.1 S 0:10 /etc/init - root 2 0.0 0.0 0.0 0.0 0.0 S 0:01 pageout root 3 0.3 0.0 0.0 0.0 0.0 S 18:45:07 fsflush [...] If we'd still like to see more details about the I/O, event mode can be used. This is where the (somewhat raw) events are printed from the log. This example is trimmed in places so that this isn't dozens of pages long, mars:> ./psio -ei out3 UID PID IOTIME IOSIZE DEVICE INFO CMD root 0 11 8192 /export/home 16 sched root 0 3 8192 /export/home 1008 sched root 0 6 8192 /export/home 16256 sched root 0 1 8192 /export/home 16272 sched root 0 1 8192 /export/home 16288 sched root 0 10 8192 /export/home 274304 sched root 0 1 8192 /export/home 274320 sched root 0 11 8192 /export/home 690560 sched root 0 7 8192 /export/home 1000896 sched [...] root 5857 13 2048 /squidcache 0x3006e13e188 (squid) -s brendan 28318 4 8192 /export/home 0x300022c0558 pine brendan 28318 14 8192 /export/home 0x300022c0558 pine brendan 28318 9 8192 /export/home 0x300022c0558 pine brendan 28318 9 8192 /export/home 0x300022c0558 pine brendan 28318 1 8192 /export/home 0x300022c0558 pine brendan 28318 10 24576 /export/home 0x300022c0558 pine brendan 28318 9 8192 /export/home 0x300022c0558 pine brendan 28318 9 8192 /export/home 0x300022c0558 pine brendan 28318 7 49152 /export/home 0x300022c0558 pine brendan 28318 6 24576 /export/home 0x300022c0558 pine brendan 28318 1 8192 /export/home 0x300022c0558 pine brendan 28318 1 8192 /export/home 0x300022c0558 pine brendan 28318 6 8192 /export/home 0x300022c0558 pine [...] root 0 12 8192 /var 64 sched root 0 1 8192 /var 80 sched root 0 11 8192 /var 16256 sched root 0 1 8192 /var 16272 sched root 0 11 8192 /var 32448 sched root 0 3 8192 /var 32464 sched root 0 11 8192 /var 48640 sched root 0 4 8192 /var 64832 sched root 0 1 8192 /var 64848 sched root 0 14 8192 /var 81024 sched root 0 1 8192 /var 81040 sched [...] brendan 28320 20 1024 /var 0x3000370be50 pkginfo brendan 28320 6 1024 /var 0x300eb1f1e70 pkginfo brendan 28320 6 1024 /var 0x3002f1de0d8 pkginfo brendan 28320 7 1024 /var 0x3006e25c950 pkginfo brendan 28320 14 1024 /var 0x30004880c38 pkginfo brendan 28320 9 1024 /var 0x3006a9a1c88 pkginfo brendan 28320 11 1024 /var 0x30003710708 pkginfo brendan 28320 10 1024 /var 0x300035b2698 pkginfo brendan 28320 8 1024 /var 0x30096cbf620 pkginfo brendan 28320 11 1024 /var 0x300deb50b08 pkginfo brendan 28320 7 1024 /var 0x3006e2561d0 pkginfo brendan 28320 3 1024 /var 0x3006e0f8480 pkginfo brendan 28320 12 1024 /var 0x3006e0ad6c8 pkginfo brendan 28320 8 1024 /var 0x300035c2e00 pkginfo brendan 28320 10 1024 /var 0x30000cc30a8 pkginfo brendan 28320 8 1024 /var 0x3000390e128 pkginfo brendan 28320 5 1024 /var 0x3000483d658 pkginfo [...] This clearly shows pkginfo making numerous small operations of 1024 bytes, pine with much larger I/O operations, and "sched" (the kernel) working through the cylinder group blocks (the plain numbers are block addresses). The times as the kernel reads through the disk blocks are interesting - 12, 1, 11, 1, 11, 3, ... even though they are all 8 Kb. The difference is due to seek time for the disk heads, eg 16272 -> 32448 takes 11 ms, and 16256 -> 16272 takes 1 ms. To get some more info on the vnodes (0x...), "-m" can be used to run an "mdb -k" lookup on each of them. This can be very slow, and must be run as soon as possible after the log was created otherwise the vnodes can change in memory. mars:> ./psio -mei out3 UID PID IOTIME IOSIZE DEVICE INFO CMD root 0 11 8192 /export/home 16 sched root 0 3 8192 /export/home 1008 sched root 0 6 8192 /export/home 16256 sched [...] root 5857 13 2048 /squidcache /05/1B (squid) -s brendan 28318 4 8192 /export/home /brendan/mbox pine brendan 28318 14 8192 /export/home /brendan/mbox pine brendan 28318 9 8192 /export/home /brendan/mbox pine brendan 28318 9 8192 /export/home /brendan/mbox pine brendan 28318 1 8192 /export/home /brendan/mbox pine brendan 28318 10 24576 /export/home /brendan/mbox pine brendan 28318 9 8192 /export/home /brendan/mbox pine brendan 28318 9 8192 /export/home /brendan/mbox pine brendan 28318 7 49152 /export/home /brendan/mbox pine brendan 28318 6 24576 /export/home /brendan/mbox pine brendan 28318 1 8192 /export/home /brendan/mbox pine brendan 28318 1 8192 /export/home /brendan/mbox pine brendan 28318 6 8192 /export/home /brendan/mbox pine brendan 28318 9 8192 /export/home /brendan/mbox pine brendan 28318 9 8192 /export/home /brendan/mbox pine brendan 28318 9 8192 /export/home /brendan/mbox pine brendan 28318 11 8192 /export/home /brendan/mbox pine brendan 28318 2 8192 /export/home /brendan/mbox pine brendan 28318 9 8192 /export/home /brendan/mbox pine brendan 28318 9 8192 /export/home /brendan/mbox pine [...] root 0 12 8192 /var 64 sched root 0 1 8192 /var 80 sched root 0 11 8192 /var 16256 sched root 0 1 8192 /var 16272 sched root 0 11 8192 /var 32448 sched root 0 3 8192 /var 32464 sched [...] brendan 28320 20 1024 /var /sadm/pkg/SUNWifbcf/pkginfo pkginfo brendan 28320 6 1024 /var /sadm/pkg/SUNWifbgl/pkginfo pkginfo brendan 28320 6 1024 /var /sadm/pkg/SUNWifbgx/pkginfo pkginfo brendan 28320 7 1024 /var /sadm/pkg/SUNWifbr/pkginfo pkginfo brendan 28320 14 1024 /var /sadm/pkg/SUNWifbw/pkginfo pkginfo brendan 28320 9 1024 /var /sadm/pkg/SUNWifbx/pkginfo pkginfo brendan 28320 11 1024 /var /sadm/pkg/SUNWifp/pkginfo pkginfo brendan 28320 10 1024 /var /sadm/pkg/SUNWifph/pkginfo pkginfo brendan 28320 8 1024 /var /sadm/pkg/SUNWifph pkginfo brendan 28320 11 1024 /var /sadm/pkg/SUNWifpx/pkginfo pkginfo brendan 28320 7 1024 /var /sadm/pkg/SUNWigsr/pkginfo pkginfo brendan 28320 3 1024 /var /sadm/pkg/SUNWigsr pkginfo brendan 28320 12 1024 /var /sadm/pkg/SUNWigsu/pkginfo pkginfo brendan 28320 8 1024 /var /sadm/pkg/SUNWigsu pkginfo brendan 28320 10 1024 /var /sadm/pkg/SUNWigsuc/pkginfo pkginfo brendan 28320 8 1024 /var /sadm/pkg/SUNWigsuc pkginfo brendan 28320 5 1024 /var /sadm/pkg/SUNWigsud/pkginfo pkginfo brendan 28320 12 1024 /var /sadm/pkg/SUNWigsx/pkginfo pkginfo brendan 28320 14 1024 /var /sadm/pkg/SUNWinamd/pkginfo pkginfo brendan 28320 6 1024 /var /sadm/pkg/SUNWiniu8/pkginfo pkginfo brendan 28320 9 1024 /var /sadm/pkg/SUNWiniu8x/pkginfo pkginfo [...] So pine really was reading the mailbox. We can clearly see pkginfo work through the package directories reading each of their "pkginfo" files.