CASE STUDY ON BUFFER BUSY WAIT EVENT

PURPOSE
-------

This document discusses a rare and difficult to diagnose database performance 
problem characterized by extremely high buffer busy waits that occur at 

seemingly random times.  The problem persists even after traditional buffer 
busy wait tuning practices are followed (typically, increasing the number of 
freelists for an object).  
 
SCOPE & APPLICATION

-------------------

This document is intended for support analysts and customers.  It applies to 
both Unix and Windows-based systems, although the examples here will be 
particular to a Unix-based (Solaris) system.


In addition to addressing a specific buffer busy wait performance problem, 
in section II, this document presents various techniques to diagnose and 
resolve this problem by using detailed data from a real-world example.  The 

techniques illustrated here may be used to diagnose other I/O and performance 
problems.



RESOLVING INTENSE AND "RANDOM" BUFFER BUSY WAIT PERFORMANCE PROBLEMS
--------------------------------------------------------------------


This document is composed of two sections; a summary section that broadly 
discusses the problem and its resolution, and a detailed diagnostics section 
that shows how to collect and analyze various database and operating system 

diagnostics related to this problem.  The detailed diagnostics section is 
provided to help educate the reader with techniques that may be useful in
other situations.


I.  Summary
~~~~~~~~~~~

1.  Problem Description

~~~~~~~~~~~~~~~~~~~~~~~

At seemingly random times without regard to overall load on the database, 
the following symptoms may be witnessed:

- Slow response times on an instance-wide level
- long wait times for "buffer busy waits" in Bstat/Estat or Statpack reports

- large numbers of sessions waiting on buffer busy waits for a group of 
        objects (identified in v$session_wait)
 
Some tuning effort may have been spent in identifying the segments 
involved in the buffer busy waits and rebuilding those segments with a higher 

number of freelists or freelist groups (from 8.1.6 on one can dynamically add 
process freelists; segments only need to be rebuilt if changing freelist 
groups).  Even after adding freelists, the problem continues and is not 

diminished in any way (although regular, concurrency-based buffer busy waits 
may be reduced).
 
 
2.  Problem Diagnosis
~~~~~~~~~~~~~~~~~~~~~
 
     The problem may be diagnosed by observing the following:

 
        - The alert.log file shows many occurrences of ORA-600, ORA-7445 and 
          core dumps during or just before the time of the problem.
 
        - The core_dump_dest directory contains large core dumps during the 

          time of the problem. There may either be many core dumps or a few 
          very large core dumps (100s of MB per core file), depending on the 
          size of the SGA.
 
        - sar -d shows devices that are completely saturated and have high 

          request queues and service times.  These devices and/or their 
          controllers are part of logical volumes used for database files.
 
        - Buffer busy waits, write complete waits, db file parallel writes and 

          enqueue waits are high (in top 5 waits, usually in that order).  
          Note that in environments using Oracle Advanced Replication, the 
          buffer busy waits may at times appear on segments related to 

          replication (DEF$_AQCALL table, TRANORDER index, etc...).
 
 
3.  Problem Resolution
~~~~~~~~~~~~~~~~~~~~~~
 
The cause for the buffer busy waits and other related waits might be a 
saturated disk controller or subsystem impacting the database's ability to read

 or write blocks.  The disk/controller may be saturated because of the many 
core dumps occurring simultaneously requiring hundreds of megabytes each.  If 
the alert.log or core_dump_dest directory has no evidence of core dumps, then 

the source of the I/O saturation must be found.  It may be due to non-database 
processes, another database sharing the same filesystems, or a poorly tuned 
I/O subsystem.
 
 The solution is as follows:


  1) Find the root cause for the I/O saturation (core dumps, 
                   another process or database, or poorly performing I/O 
                   subsystem) and resolve it.
 OR, 
  2) If evidence of core dumps are found:

   -  Find the causes for the core dumps and resolve 
                           them (patch, etc)
   -  Move the core_dump_dest location to a filesystem 
                           not shared with database files.

   -  Use the following init.ora parameters to reduce 
                           or avoid the core dumps:
    shadow_core_dump = partial
    background_core_dump = partial
   These core dump parameters can also be set to "none" 

                        but this is not recommended unless the causes for the 
                        core dumps have been identified.
 
 
 
II.  Detailed Diagnostics with Examples
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

 
     This section provides details into the diagnostic tools and methods used 
to resolve this problem and are intended to help illustrate the use of various 
diagnostics that may be applied in other situations.

 
 
1.  Diagnostics
~~~~~~~~~~~~~~~
 
     The following diagnostics will help fingerprint the problem.
 
        - alert.log and trace files in the background_dump_dest, user_dump_dest,
          and core_dump_dest directories 

        - iostat or sar data (on Windows, the Performance Monitor utility with 
          disk counters activated) with filesystem mapping tools or techniques 
          (e.g., Veritas vxprint)
        - StatsPack or BSTAT/ESTAT reports

        - V$SESSION_WAIT
 

A. ALERT.LOG file
~~~~~~~~~~~~~~~~~

The alert.log file should always be checked in any database diagnostic effort. 
In this case, the following entries were created during the time of the buffer

busy wait problem:

Wed May 16 00:38:15 2001
Errors in file /db_admin/prod/bdump/mlrep_s008_2731.trc:
ORA-07445: exception encountered: core dump [kzdurtc()+4] [SIGBUS] [Invalid address alignment] [859063291] [] []

Wed May 16 00:38:15 2001
Errors in file /db_admin/prod/bdump/mlrep_s014_2737.trc:
ORA-07445: exception encountered: core dump [kzdurtc()+4] [SIGSEGV] [Address not mapped to object] [926430458] [] []
Wed May 16 00:41:13 2001

Errors in file /db_admin/prod/bdump/mlrep_s005_930.trc:
ORA-07445: exception encountered: core dump [kzdurtc()+4] [SIGBUS] [Invalid address alignment] [1178678525] [] []

The stack traces corresponding to the core files indicated a problem during 

the login process.  It was discovered that a core dump could be caused if 
users accidentally entered passwords greater than 48 characters.  Furthermore, 
in this web-based application, users did not receive an error and would retry 

the login, producing another core dump with each click of the mouse.


B. SAR Diagnostics
~~~~~~~~~~~~~~~~~~

SAR, IOSTAT, or similar tools are critical to diagnosing this problem because 
they show the health of the I/O system during the time of the problem.  The 

SAR data for the example we are looking at is shown below (shown 
using "sar -d -f /var/adm/sa/sa16"):

SunOS prod1 5.6 Generic_105181-23 sun4u    05/16/01

01:00:00 device        %busy   avque   r+w/s  blks/s  avwait  avserv


         sd22            100    72.4    2100    2971     0.0    87.0
         sd22,c            0     0.0       0       0     0.0     0.0
         sd22,d            0     0.0       0       0     0.0     0.0
         sd22,e          100    72.4    2100    2971     0.0    87.0

                                 /\
                                 ||
  extremely high queue values (usually less than 2 during peak)

By mapping the sd22 device back to the device number (c3t8d0) and then back to 

the logical volume through to the filesystem (using "df" and Veritas' 
utility /usr/sbin/vxprint), it was determined the filesystem shared the same 
controller (c3) as several database files (among them were the datafiles for 

the SYSTEM tablespace).  

By looking within the filesystems using the aforementioned controller (c3), 
several very large (1.8 GB) core dumps were found in the core_dump_dest 
directory, produced around the time of the problem.

 

C.  StatsPack
~~~~~~~~~~~~~

During an episode of the performance problem, it is very helpful to collect 
samples using StatsPack.  The interval between samples is ideally about 
15 minutes, but even 1-hour intervals are acceptable.  It is very valuable to 

also collect baseline samples of the same interval during similar activity 
levels when there is NOT a problem.  By having the baseline, one will be able 
to see how certain statistics reflect the problem.



i.  Waits Events:  During the problem episode, "buffer busy waits" and "write 
complete waits" will be seen as the highest wait events.  During the baseline 
load, these events are not significant.  Other significant wait events during 

the problem may be "enqueue" and "db file parallel writes".  For example:

                                                                  Avg
                                                      Total Wait  wait  Waits

Event                               Waits   Timeouts   Time (cs)  (ms)   /txn
---------------------------- ------------ ---------- ----------- ----- ------
buffer busy waits                 225,559    211,961  24,377,029  1081    4.0 

enqueue                            25,731     21,756   6,786,722  2638    0.5
Parallel Query Idle Wait - S        9,980      7,929   1,762,606  1766    0.2
SQL*Net message from dblink       435,845          0   1,288,965    30    7.7

db file parallel write              4,252          0   1,287,023  3027    0.1
write complete waits                5,872      5,658     581,066   990    0.1
db file sequential read         1,249,981          0     510,793     4   22.0



ii.  Statistics:  There may be evidence of DB Writer falling behind and slow 
write performance as follows:

   -  low number of DBWR Timeouts
   -  the ratio (free buffers inspected)/(free buffers requested) * 100% > 5%

   -  much higher number for "dirty buffers inspected" than normal baseline


The following lists some key statistics to look at:

Statistic                          Total   per Second    per Trans

----------------------- ---------------- ------------ ------------
consistent changes                43,523         12.1          2.4     Much
free buffer inspected              6,087          1.7          0.3 <== higher

free buffer requested            416,010        115.6         23.1     than
logons cumulative                 15,718          4.4          0.9     normal
physical writes                   24,757          6.9          1.4

write requests                       634          0.2          0.0

It's important to look at workload parameters to ensure the problem isn't due 
to simply more work being done.  The statistic "consistent changes", 

"logons cumulative", "physical writes", and "write requests" are all compared 
to a baseline.


iii.  Tablespace I/O Summary  

The average wait times for tablespaces will be dramatically higher.


Tablespace IO Summary for DB: PROD  Instance: PROD  Snaps:    3578 -   3579 
                                                                              
                        Avg Read                  Total Avg Wait

Tablespace        Reads   (ms)        Writes      Waits   (ms)  
----------- ----------- -------- ----------- ---------- --------
BOM            482,368      7.0      18,865      3,161    205.9    very
CONF           157,288      0.6         420        779   9897.3 <= high

CTXINDEX        36,628      0.5           7          4     12.5    very
RBS                613    605.7      23,398      8,253   7694.6 <= high
SYSTEM          18,360      3.6         286         78    745.5
DB_LOW_DATA     16,560      2.6       1,335         14     24.3


Similar statistics per datafile may be seen in the "File IO Statistics" 
section of StatsPack.


iv.  Buffer Busy Wait Statistics

Buffer wait Statistics for DB: PROD  Instance: PROD  Snaps:    3578 -   3579

                                                                              
                                 Tot Wait    Avg                              
Class                    Waits  Time (cs) Time (cs)                           

------------------ ----------- ---------- ---------                           
data block             216,577 ##########       108  <== severe contention on 
undo header              5,072    609,734       120      data blks                     

undo block               3,770    333,876        89      ("off the scale")                     
free list                   70     17,426       249                           
segment header               8         34         4                           



v.  Enqueues

The StatsPack data for this case study shows many SQ (sequence) enqueue waits. 
SQ enqueues are held while Oracle updates the dictionary entry of the sequence 
with the next value (or starting value for the next batch of sequence numbers 

to cache).  The object id of the sequence is found by looking at the p2 column 
of v$session_wait for 'enqueue' events and selecting from DBA_OBJECTS using the
object_id (you must convert the value in the p2 column to decimal first).  

In this case it was for sys.sessaud$.  This means the SYSTEM tablespace is 
being impacted by the I/O problems and is taking a long time to generate the 
next sequence number for "sessaud$".

Enqueue activity for DB: MLREP  Instance: MLREP  Snaps:    3578 -   3579      

                                                                              
Enqueue            Gets      Waits                                            
---------- ------------ ----------                                            

SQ                5,130      1,345  <== Drill down v$session_wait.p2 and  
TX               80,735         63       DBA_OBJECTSfor object_id. In  
SR                8,207          7       this case it was for sys.audses$                                     

TM               93,225          4                                            
CF                1,396          1            



vi.  Buffer Pool Statistics

The buffer pool statistics should be compared with the baseline.  During the 

performance problem write complete waits may be 10 to 100 times longer than 
during the baseline load  (without the problem):

Buffer Pool Sets for DB: PROD  Instance: PROD  Snaps:    3578 -   3579      
                                                                              

                                                        Free    Write   Buffer
Set      Buffer  Consistent    Physical    Physical   Buffer Complete     Busy
 Id        Gets        Gets       Reads      Writes    Waits    Waits    Waits

--- ----------- ----------- ----------- ----------- -------- -------- --------
  1      99,132   4,060,929      97,235       2,860        0      384  148,348
  2      97,773   3,359,172      96,851       3,185        0      221      640

  3      97,320   3,486,183      96,592       3,014        0      303    1,024
  4      96,961   1,943,505      96,366       2,723        0      232      598
  5      97,182   1,508,089      96,223       2,798        0      107    5,731

 ...                                                      /\
                                                                   ||
    these are 10 times greater than baseline



D.  V$SESSION_WAIT 
~~~~~~~~~~~~~~~~~~


V$SESSION_WAIT can be used to see how many sessions are impacted by the buffer 
busy wait problem in real-time using a query as follows:

SELECT count(*), event
FROM v$session_wait
WHERE wait_time = 0

 AND event NOT IN ('smon timer','pmon timer','rdbms ipc message', 
    'SQL*Net message from client')
GROUP BY event
ORDER BY 1 DESC;

Output:

  COUNT(*) EVENT
---------- ----------------------------------------------------------------

       122 buffer busy waits
   15 enqueue
   15 enqueue
    5 db file parallel write
         3 SQL*Net message from dblink
         2 latch free
         1 SQL*Net more data to client


To see the file and block numbers in more detail:


SELECT count(*) NUM_WAITERS, p1 FILE#, p2 BLK#, p3 CLASS
FROM v$session_wait
WHERE event = 'buffer busy waits'
GROUP BY p1, p2, p3

NUM_WAITERS    FILE#   BLK#     CLASS
------------   -----  -------  ------

92             2      13487      1016
73             2      27762      1016
32             1      29697      1016

This shows that during the execution of the above query, there were 92 waiters 
for file 2, block 13487.


To find the object name and type for the objects being wait on, use the 
following query (supplying the file numbers and block numbers shown above):

SELECT owner,segment_name,segment_type
FROM dba_extents

WHERE file_id=&file
AND &blockid BETWEEN block_id AND block_id + blocks

After querying against DBA_EXTENTS and supplying the file and block numbers, 
the following correlation can be made: 
 
NUM_WAITERS   OWNER.SEGMENT_NAME       TYPE     FILE#    BLK#      CLASS

------------  -------------------    ---------  ----   -------    ------
92             SYSTEM.DEF$_TRANORDER   INDEX     2      13487      1016
73             SYSTEM.DEF$_AQCALL      TABLE     2      27762      1016

32             SYSTEM.DEF$_TRANORDER   INDEX     1      29697      1016

Normally, one would rebuild the above segments with more freelists or freelists
 groups (in 8.1.6 or higher you can add process freelists without rebuilding 

the segment) to reduce contention.  However, in this case more freelists won't 
help.



2.  Resolving the Problem
~~~~~~~~~~~~~~~~~~~~~~~~~~

With the above diagnostics, it was possible to conclude that the core dumps 

caused disk controller saturation and impeded the database from reading and 
writing blocks.  By scanning back through the alert.log file and looking for 
occurrences of similar core dumps, it was possible to ascertain when the 

problems had appeared.  Looking at StatsPack data for the same time period 
seen in the alert.log file, the buffer busy waits were indeed the highest 
wait event.

Since the customer could not change the application to limit the password 

length and there were no other places to put the core_dump_dest files, the 
following changes were made to the init.ora file:

 shadow_core_dump = partial
 background_core_dump = partial

These changes caused the core dumps to be created AFTER the oracle processes 

are detached from the SGA.  The resulting core dumps were 24 MB on average 
instead of 1.8 GB.  Later occurrences of core dumps were seen in the alert.log 
and cdump directory, with no buffer busy wait side effects or performance 

degradation (and no I/O impact visible in sar data); this confirmed that 
the init.ora changes solved the problem.