Note:
This is a reposting of an old blog post that was on dboptimizer.com but is no longer accessible
More trace file analyzer tools at http://ba6.us/node/177
Related blog post: Oracle “Physical I/O” ? not always physical with a 10046 parser specifically for I/O parsetrc.pl and readme
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: README.TXT 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.trc
Oracle 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.trcWait 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: 309821Wait 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 6wait 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
Comments