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.<\/p>\n
We first get a count of all waits in the trace…<\/p>\n
\r\n11:16:13 oracle@oh1xpwcdb01 \/u02\/admin\/wcprod\/udump >grep WAIT wcprod1_ora_2327.trc | cut -f2 -d\\' | sort | uniq -c | sort -n\r\n 1 gc current block 3-way\r\n 1 gc current grant busy\r\n 4 gc cr block 3-way\r\n 4 gc cr block busy\r\n 4 gc current block 2-way\r\n 8 gc remaster\r\n 9 gcs drm freeze in enter server mode\r\n 29 latch: cache buffers chains\r\n 38 gc cr block congested\r\n 72 latch: cache buffers lru chain\r\n 80 gc cr grant 2-way\r\n 123 latch free\r\n 126 db file parallel read\r\n 171 latch: gcs resource hash\r\n 367 latch: object queue header operation\r\n 531 gc current grant 2-way\r\n 2004 latch: KCL gc element parent latch\r\n 47434 db file scattered read\r\n 66236 gc cr multi block request\r\n 180037 gc cr disk read\r\n 197592 db file sequential read\r\n1580988 gc cr block 2-way\r\n<\/pre>\n…and then get the total number of seconds waited…<\/p>\n
\r\n11:17:24 oracle@oh1xpwcdb01 \/u02\/admin\/wcprod\/udump >grep \"ela=\" wcprod1_ora_2327.trc | cut -f3 -d\\' | awk '{SUM+=$2} END{print SUM\/1000000}'\r\n3783.22\r\n<\/pre>\n…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.<\/p>\n
\r\n11: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}' \r\n1724.6\r\n11: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}'\r\n1089.77\r\n11:21:30 oracle@oh1xpwcdb01 \/u02\/admin\/wcprod\/udump >\r\n<\/pre>\n","protected":false},"excerpt":{"rendered":"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…<\/p>\n