December 7, 2010
I recently reviewed the book “Oracle Tuning the Definitive Reference Second Edition”, and did not provide an in-depth technical review of the entire book. This blog article series will dig into some of the pages that were not specifically included in the review.
Over the years I have seen several “Top 5 Timed Events” sections from Statspack and AWR reports. I recall after reading the “Oracle Performance Tuning 101” book several years ago, the feeling of being quite confused. Why? No, it was not a problem with the book – the book made a lot of sense. After reading the book I searched the Internet looking for more information, for example, for clear indicators that the LOG_BUFFER parameter was undersized. Is 512KB enough, is 1MB enough, or maybe I have an extreme case that needs a 2MB value for the LOG_BUFFER parameter? I found a number of web pages in a Google search, and some of those pages included “Top 5” wait event output. On one of those web pages the author indicated that the “Top 5” wait event output indicated an undersized value for the LOG_BUFFER parameter, so I cross-referenced the wait event names with my notes from the “Oracle Performance Tuning 101” book, and then became very confused. No wonder Oracle Database performance tuning is so hard – the “Oracle Performance Tuning 101” book notes caused me to arrive at a completely different problem point than what the author of the web page stated. After examining more “Top 5” wait event output sections, and digesting the “Optimizing Oracle Performance” book, I decided that my original opinion about the “Top 5” sections were more than likely correct.
Let’s try an experiment (or a quiz, if you prefer). I will show you a slightly modified version of a “Top 5” wait event section from the “Oracle Tuning the Definitive Reference Second Edition” book, and you tell me your thoughts about that “Top 5” section. For example: are there any consistency problems, what does the “Top 5” section indicate, how does your interpretation of the “Top 5” section compare with that of the book author? For an example of what I am trying to uncover, take a look at this blog article. The last four “Top 5” sections are from the AskTom website – any opinions on those “Top 5” sections?
————————–
Top 5 Timed Events ~~~~~~~~~~~~~~~~~~ % Total Event Waits Time (s) Ela Time -------------------------- --------- ---------- -------- db file sequential read 5,196 14,292 48.53 db file scattered read 51,038 6,492 22.05 library cache load lock 1,346 2,726 9.25 CPU time 2,308 7.84 log file parallel write 38,314 1,674 5.67
————————–
Top 5 Timed Events ~~~~~~~~~~~~~~~~~~ % Total Event Waits Time (s) Ela Time -------------------------------- ----------- -------- CPU time 9,702 8,084 55.75 db file sequential read 3,936 3,994 27.56 log file sync 598,194 738 5.07 db file scattered read 106,062 660 4.56 log file parallel write 605,360 380 2.61
————————–
Top 5 Timed Events ~~~~~~~~~~~~~~~~~~ % Total Event Waits Time (cs) Wt Time -------------------------- -------- ------- -------- SQL*Net more data to client 1,957,467 4,737,686 99.77 db file sequential read 683,830 3,065 .07 db file parallel write 3,791 2,500 .05 rdbms ipc reply 13 2,306 .04 db file scattered read 8,443 1,223 .02
————————–
4 (page 105):
Top 5 Wait Events ~~~~~~~~~~~~~~~~~~ % Total Event Waits Time (cs) Wt Time -------------------------- -------- --------- ------- enqueue 51,802 959,308 46.70 db file scattered read 21,114,884 394,410 29.21 db file sequential read 1,448,650 393,166 9.13 latch free 2,301,958 102,168 4.98 log file parallel write 297,864 79,644 3.87
————————–
5 (page 107):
Top 5 Timed Events ~~~~~~~~~~~~~~~~~~ % Total Event Waits Time (s) Ela Time --------------------------- ------------ ---------- ------------ db file scattered read 651,038 6,492 82.03 library cache load lock 9,346 2,726 9.27 db file sequential read 1,069,196 14,292 4.53 CPU time 2,308 1,290 3.84 log file parallel write 38,314 1,674 1.67
————————–
6 (page 158):
Top 5 Timed Events ~~~~~~~~~~~~~~~~~~ % Total Event Waits Time (s) Ela Time --------------------------- ------------ ----------- ----------- CPU time 326,364 88.22 db file sequential read 3,085,708 17,102 4.63 log file sync 3,648,938 16,804 4.53 log file parallel write 3,621,256 7,239 1.31 SQL*Net more data to client 30,842,404 1,314 .36
————————–
7 (page 158):
Top 5 Timed Events ~~~~~~~~~~~~~~~~~~ % Total Event Waits Time (s) DB Time --------------------------- ------------ ----------- ----------- log file parallel write 19,340 582 55.66 log file sync 18,586 556 53.13 CPU time 450 43.11 db file parallel write 9,844 402 38.54 control file parallel write 2,564 130 12.41
————————–
8 (page 324):
Top 5 Timed Events ~~~~~~~~~~~~~~~~~~ % Total Event Waits Time (s) Ela Time ------------------------ --------- ----------- -------- db file sequential read 1,137,896 8,750 66.14 CPU time 3,966 30.00 db file scattered read 212,574 130 .98 log file sync 14,106 100 .76 log buffer space 3,434 94 .70
————————–
9 (page 511):
Top 5 Timed Events ~~~~~~~~~~~~~~~~~~ % Total Event Waits Ela Time -------------------------- --------- -------- db file sequential read 5,196 48.53 db file scattered read 51,038 22.05 library cache load lock 1,346 9.25 CPU time 88 7.84 log file parallel write 38,314 5.67
————————–
10 (page 512):
Top 5 Timed Events ~~~~~~~~~~~~~~~~~~ % Total Event Waits Ela Time -------------------------- --------- -------- db file sequential read 5,196 48.53 db file scattered read 51,038 22.05 library cache load lock 1,346 9.25 CPU time 4,308 7.84 log file parallel write 38,314 5.67
————————–
11 (page 1002):
Top 5 Timed Events ~~~~~~~~~~~~~~~~~~ % Total Event Waits Time (s) Ela Time -------------------------------- ----------- -------- db file scattered read 5,196 14,292 58.53 db file sequential read 51,038 6,492 12.05 library cache load lock 1,346 2,726 9.25 CPU time 2,308 7.84 log file parallel write 38,314 1,674 5.67
————————–
12 (AskTom):
Top 5 Timed Events ~~~~~~~~~~~~~~~~~~ % Total Event Waits Time (s) Ela Time -------------------------------------------- ------------ ----------- -------- CPU time 19,612 35.04 latch free 899,688 14,371 25.68 db file scattered read 16,333,411 13,105 23.42 SQL*Net message from dblink 439,535 4,440 7.93 direct path write 405,226 1,509 2.70
————————–
13 (AskTom):
Top 5 Timed Events ~~~~~~~~~~~~~~~~~~ % Total Event Waits Time (s) Ela Time -------------------------------------------- ------------ ----------- -------- CPU time 2,446 75.27 log file sync 12,883 212 6.52 latch free 17,869 182 5.60 log file parallel write 35,538 174 5.34 SQL*Net break/reset to client 5,544 80 2.46
————————–
14 (AskTom):
Top 5 Timed Events ~~~~~~~~~~~~~~~~~~ % Total Event Waits Time (s) Ela Time -------------------------------------------- ------------ ----------- -------- CPU time 3,747 66.52 enqueue 2,129 1,350 23.97 db file sequential read 37,842 286 5.07 log file sync 9,743 65 1.15 LGWR wait for redo copy 58,067 61 1.08
————————–
15 (AskTom):
Top 5 Timed Events ~~~~~~~~~~~~~~~~~~ % Total Event Waits Time (s) Ela Time -------------------------------------------- ------------ ----------- -------- CPU time 19,612 35.04 latch free 899,688 14,371 25.68 db file scattered read 16,333,411 13,105 23.42 SQL*Net message from dblink 439,535 4,440 7.93 direct path write 405,226 1,509 2.70
————————–
Confused? Or did you do well in this quiz?
Charles Hooper's Oracle Notes 
Hi Charles,
I’d certainly be more than a little worried about a system (excerpt 1) that on average was taking 2.75 seconds to do a single block read. Perhaps unlike the imps in the wonderful iconograph these data imps have gone on strike. It’s possible of course that these figures are blown by bugs in the data – sometimes oracle has been known to print incorrect values in extended sql trace ela values, possibly some versions of statspack/awr have encountered similar issues.
The second extract has a value in the “Waits” column against CPU Time which should not be there and single block reads that take on average one second per read.
#1 is obviously from a server using a very advanced RAID 10 floppy array, or maybe it is a bug, or maybe… what is that supposed to be showing? (I added a link to the page in the book)
#2 is a problem that I reported to the author of this book in the OTN forums last year (http://forums.oracle.com/forums/thread.jspa?threadID=972294 – interesting couple of comments in that thread: “You say that you have not read this book. I never put too much credence into reviews by people who have not read the book!” “PLEASE do not de-rail Yasser’s thread with off-point reviews of books that you haven’t read, Charles, it’s not fair to Yasser.” – have we found the reason why I bought this book? 🙂 )
I find these quite confusing.
The numbers don’t appear to add up correctly in several of the examples and several number recur in the first eleven:
The db file sequential/scattered read events appear in 1, 5, 9, 10 and 11 with very similar/the same numbers for either waits or time, but differ slightly on the other columns each time.
In 4, the times for sequential and scattered read are very similar, yet have vastly different % of elapsed (29 vs 9). In 5, the events aren’t ordered by time, and the % elapsed don’t correspond to the times taken (the top event is over 80% of elapsed time, despite consuming less than half the time of the third).
The percentage of elapsed times add up to over 200% in seven; this seems unusual to me, though I may not be understanding something which is causing this.
The first eleven are also inconsistent with the display of the time column – sometime it’s shown and sometimes it isn’t…
Chris,
Nice examination of the “Top 5” sections. I have now included links to the pages in the book – the next step is to see if the “Top 5” sections show what the author claims.