Often when I have a 10046 trace file, especially when looking at I/O issues, I want a histogram of I/O response time. To get I/O response time I’ve hacked out incomple awk scripts from time to time, always meaning to write a more complete one, well now I don’t have to. It’s already been done!
Here is a cool perl script from Clive Bostock: 10046.pl
(also checkout orasrp which produces a more indepth report in HTML. I like both. I like 10046.pl as a short easy portable script that I can modify, whereas orasrp is a binary and only works on some ports)
For example, if I trace a session with 10046, and retrieve the tracefile, then I can run:
$ 10046.pl -t mytrace.trc
and it will output a header and three sections
Header
- Summary of all events for tracefile
- Events by object summary
- Events by object histogram
This looks like
Header
Trace file mytrace.trcOracle Database 11g Enterprise Edition Release 11.1.0.7.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
ORACLE_HOME = /u02/oracle
System name: SunOS
Node name: toto
Release: 5.10
Version: Generic_142900-12
Machine: sun4u
Instance name: orcl
Redo thread mounted by this instance: 1
Oracle process number: 177
Unix process pid: 16553, image: oracle@toto
Trace input file : mytrace.trc
Wait summary
EVENT AGGREGATES================
Wait Event Count Elapsed(ms) Avg Ela (ms) %Total
~~~~~~~~~~~~~~~~~~~~~~~ ~~~~~ ~~~~~~~~~~~~ ~~~~~~~~~~~~ ~~~~~~~~~~
db file sequential read 2715 11593 4 3.74
direct path read 4484 4506 1 1.45
db file scattered read 141 898 6 0.29
log file sync 3 8 2 0.00
~~~~~~~~~~~~
Total Elapsed: 309821
Wait Summary by object
Object Id : Wait Event Count Tot Ela (ms) %Total Avg Ela (ms)~~~~~~~~~~ : ~~~~~~~~~~~~~~~~~~~~~~~~~~~ ~~~~~ ~~~~~~~~~~~~ ~~~~~ ~~~~~~~~~~~~~
28581 : direct path read 4484 4506 1.45 1
1756433 : db file sequential read 725 1891 0.61 2
764699 : db file sequential read 332 1762 0.57 5
37840 : db file sequential read 200 1044 0.34 5
38018 : db file sequential read 108 1009 0.33 9
81596 : db file scattered read 140 887 0.29 6
wait histogram by object
EVENT HISTOGRAM BREAKDOWN===========================
This section splits the event counts into elapsed time
buckets so that we can see if there are any suspiciousn
or anomalous response time / frequency patterns.
Object Id : Wait Event <1ms <2ms <4ms <8ms <16ms <32ms <64ms <128ms <256ms <512ms >=1024ms
~~~~~~~~~ : ~~~~~~~~~~~~~~~~~~~~~~~ ~~~~ ~~~~ ~~~~ ~~~~ ~~~~~ ~~~~~ ~~~~~ ~~~~~~ ~~~~~~ ~~~~~~ ~~~~~~~~
28581 : direct path read 7680 87 148 221 144 40 4 0 0 0 0
1756433 : db file sequential read 606 268 45 35 66 6 2 0 0 0 0
764699 : db file sequential read 74 119 11 78 78 9 0 0 0 0 0
37840 : db file sequential read 50 72 6 45 47 5 0 0 0 0 0
38018 : db file sequential read 12 38 7 10 30 12 5 0 0 0 0
81596 : db file scattered read 64 4 13 62 18 8 3 0 0 0 0
41995 : db file sequential read 20 39 0 7 16 8 4 0 0 0 0
108718 : db file sequential read 74 54 5 12 24 4 0 0 0 0 0
33490 : db file sequential read 0 5 11 25 19 4 0 0 0 0 0
