Reading a trace report

The header of the trace report tells you when and where the trace was taken, as well as the command that was used to produce it.

Thu Oct 28 13:34:05 1999
System: AIX texmex Node: 4
Machine: 000691854C00
Internet Protocol Address: 09359BBB 9.53.155.187
Buffering: Kernel Heap

trace -a -k 20e,20f -o trc_raw

ID  PROCESS NAME  PID     ELAPSED_SEC    DELTA_MSEC  APPL  SYSCALL KERNEL  INTERRUPT
101 ksh           8526    0.005833472    0.107008          kfork LR = D0040AF8
101 ksh           7214    0.012820224    0.031744          execve LR = 10015390
134 cp            7214    0.014451456    0.030464          exec:  cmd=cp ../bin/track /tmp/junk pid=7214 tid=24713

In cp.rpt2 you can see the following information:

• The fork(), exec(), and page fault activities of the cp process.
• The opening of the input file for reading and the creation of the /tmp/junk file
• The successive read()/write() system calls to accomplish the copy.
• The process cp becoming blocked while waiting for I/O completion, and the wait process being dispatched.
• How logical-volume requests are translated to physical-volume requests.
• The files are mapped rather than buffered in traditional kernel buffers, and the read accesses cause page faults that must be resolved by the Virtual Memory Manager.
• The Virtual Memory Manager senses sequential access and begins to prefetch the file pages.
• The size of the prefetch becomes larger as sequential access continues.
• When possible, the disk device driver coalesces multiple file requests into one I/O request to the drive.

The trace output looks a little overwhelming at first. This is a good example to use as a learning aid. If you can discern the activities described, you are well on your way to being able to use the trace facility to diagnose system-performance problems.