Waiting for a Long Time – What is Going On?

7 12 2010

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?

————————–

1 (pages 27 and 406):

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 

————————–

2 (pages 28, 323, and 405):

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 

————————–

3 (pages 28 and 405):

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?


Actions

Information

4 responses

7 12 2010
Niall Litchfield

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.

7 12 2010
Charles Hooper

#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? :-) )

7 12 2010
Chris Saxon

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…

7 12 2010
Charles Hooper

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.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s




Follow

Get every new post delivered to your Inbox.

Join 140 other followers

%d bloggers like this: