1N/A**************************************************************************
1N/A* The following are additional notes on the iosnoop program.
1N/A*
1N/A* $Id: iosnoop_notes.txt 44 2007-09-17 07:47:20Z brendan $
1N/A*
1N/A* COPYRIGHT: Copyright (c) 2007 Brendan Gregg.
1N/A**************************************************************************
1N/A
1N/A
1N/A* What does the output represent?
1N/A
1N/AThe output is disk events - I/O operations that cause the disk to physically
1N/Aread or write data. The output is not application I/O events which may be
1N/Aabsorbed by memory caches - many of which will be. The output really is
1N/Aphysical disk events.
1N/A
1N/Aiosnoop uses probes from the "io" provider - which traces the block device
1N/Adriver before disk events happen. disk events. The stack goes like this,
1N/A
1N/A application
1N/A |
1N/A V
1N/A syscall
1N/A |
1N/A V
1N/A vfs
1N/A |
1N/A V
1N/A ufs/zfs/...
1N/A |
1N/A V
1N/A block device driver
1N/A |
1N/A V
1N/A physical device driver
1N/A |
1N/A V
1N/A disk
1N/A
1N/ADue to caching (after vfs) few events will make it to the disk for iosnoop
1N/Ato see. If you want to trace all I/O activity, try using syscall provider
1N/Abased scripts first.
1N/A
1N/A
1N/A* What do the elapsed and delta times mean?
1N/A
1N/AGlad you asked!
1N/A
1N/AThe times may *not* be as useful as they appear. I should also add that
1N/Athis quickly becomes a very complex topic,
1N/A
1N/AThere are two different delta times reported. -D prints the
1N/Aelapsed time from the disk request (strategy) to the disk completion
1N/Aiodone); -o prints the time for the disk to complete that event
1N/Asince it's last event (time between iodones, or since idle->strategy).
1N/A
1N/AThe elapsed time is equivalent to the response time from the application
1N/Arequest to the application completion. The delta time resembles the
1N/Aservice time for this request (resembles means it will be generally
1N/Acorrect, but not 100% accurate). The service time is the the time for the
1N/Adisk to complete the request, after it has travelled through any bus or
1N/Aqueue.
1N/A
1N/Abuuuttt.... you need to think carefully about what these times mean before
1N/Ajumping to conclusions. For example,
1N/A
1N/A You troubleshoot an application by running iosnoop and filtering
1N/A on your application's PID. You notice large times for the disk events
1N/A (responce, service, for this example it doesn't matter).
1N/A Does this mean there is a problem with that application?
1N/A What could be happening is that a different application is also using
1N/A the disks at the same time, and is causing the disk heads to seek to
1N/A elsewhere on the disk surface - increasing both service and response time.
1N/A
1N/Ahmmm! so you can't just look at one application, one set of numbers, and
1N/Aunderstand fully what is going on.
1N/A
1N/ABut it gets worse. Disks implement "tagged queueing", where events in the
1N/Aqueue are reshuffeled to promote "elevator seeking" of the disk heads (this
1N/Areduces head seeking). So the time for a disk event can be effected not
1N/Ajust by the previous event (and previous location the heads had seeked to),
1N/Abut the surrounding events that enter the queue.
1N/A
1N/ASo the good and the bad. The good news is that iosnoop makes it easy to
1N/Afetch disk event data on a live system, the bad news is that understanding
1N/Aall the data is not really easy.
1N/A
1N/AFor further information on disk measurements see,
1N/A
1N/A "How do disks really work?" - Adrian Cockcroft, SunWorld Online, June 1996
1N/A "Sun Performance and Tuning" - Adrian Cockcroft, Richard Pettit
1N/A "Solaris Internals" - Richard McDougall, Jim Mauro
1N/A
1N/A
1N/A
1N/A* The output appears shuffled?
1N/A
1N/ARead the answer to this in ALLsnoop_notes.txt.
1N/A