This morning, I enabled a 10046 trace at level 12 for a slow session. I did not scope the trace interval (ala Cary Milsap), so I didn’t even have the query text in the trace file (although I knew what it was). The resulting trace file was huge at 200MB. I didn’t want to lose the information in it, so I came up with what is below.
We first get a count of all waits in the trace…
11:16:13 oracle@oh1xpwcdb01 /u02/admin/wcprod/udump >grep WAIT wcprod1_ora_2327.trc | cut -f2 -d\' | sort | uniq -c | sort -n
1 gc current block 3-way
1 gc current grant busy
4 gc cr block 3-way
4 gc cr block busy
4 gc current block 2-way
8 gc remaster
9 gcs drm freeze in enter server mode
29 latch: cache buffers chains
38 gc cr block congested
72 latch: cache buffers lru chain
80 gc cr grant 2-way
123 latch free
126 db file parallel read
171 latch: gcs resource hash
367 latch: object queue header operation
531 gc current grant 2-way
2004 latch: KCL gc element parent latch
47434 db file scattered read
66236 gc cr multi block request
180037 gc cr disk read
197592 db file sequential read
1580988 gc cr block 2-way
…and then get the total number of seconds waited…
11:17:24 oracle@oh1xpwcdb01 /u02/admin/wcprod/udump >grep "ela=" wcprod1_ora_2327.trc | cut -f3 -d\' | awk '{SUM+=$2} END{print SUM/1000000}'
3783.22
…and for Oracle support, we were interested in a huge amount of undo reads (I’ll save that for another post). As such, I extracted the time spent in seconds on reads against the undo datafiles for each of the events listed below.
11:20:41 oracle@oh1xpwcdb01 /u02/admin/wcprod/udump >grep "db file sequential read" wcprod1_ora_2327.trc | grep "file#=2[19,29,30]" | awk '{SUM+=$8} END{print SUM/1000000}'
1724.6
11:21:14 oracle@oh1xpwcdb01 /u02/admin/wcprod/udump >grep "gc cr block 2-way" wcprod1_ora_2327.trc | grep "p1=2[19,29,30]" | awk '{SUM+=$8} END{print SUM/1000000}'
1089.77
11:21:30 oracle@oh1xpwcdb01 /u02/admin/wcprod/udump >