Skip navigation

The following was simulated on 12.1.0.2 but it's similar on older versions (=> 10gR2 though).

When faced with the "buffer busy waits" wait event, it's interesting to find out which blocks are being accessed simultaneously, and thus generating that wait event, so as to determine which part of your code is causing that Concurrency.  Granted, an AWR report will report the most contended for segments (in the "Segments by Buffer Busy Waits" section), but they may not necessarily be the segments behind the "buffer busy waits"  events you want to investigate.

So let's have several concurrent sessions update the same blocks and observe what happens.  Then we will discover how to determine which object those blocks belong to.


I've got a CHANNELS2 table that contains 5 rows scattered over 4 blocks. 

BLOCKS    TABLE_NAME

4    CHANNELS2

 

I am going to update that table heavily with 6 concurrent sessions.  Each session is going to update all of that same CHANNELS2 table 1 million times (nevermind the usefulness of this -- it's strictly for demo purposes). 

BEGIN

FOR i IN 1 .. 100000 loop

UPDATE channels2 SET channel_id=rownum+i;

COMMIT ;

END loop;

END;

/

 

While the 6 concurrent user sessions are running, my SYSTEM session will monitor v$session in real-time to observe those "buffer busy waits" wait events, with that SELECT, run manually at short intervals:

SELECT username,SID,p1,p2,event,status,logon_time,blocking_session,wait_time,ROW_WAIT_OBJ#,ROW_WAIT_ROW# FROM v$session WHERE TYPE='USER' ORDER BY logon_time;

In order to witness that for yourselves, please watch the enclosed short video, which has the added boon to demonstrate how to do it in a nifty way with SQLDeveloper.

The important information reported by that SELECT is the P1 and P2 columns, which, for each buffer busy wait, list the file_id and the block id of the data block that is being contended for.

SH    247    111286803 buffer busy waits                   ACTIVE   04:12:28                        0 964370
SH    249    111286803 buffer busy waits                    ACTIVE   04:14:34                        0 964370
SH    131    111286803 buffer busy waits                   ACTIVE   04:14:40                        0 964370

 

7 rows selected

 

USERNAME   SID    P1    P2 EVENT                               STATUS   LOGON_TIME BLOCKING_SESSION  WAIT_TIME ROW_ ROW_

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

SYSTEM129 1413697536     1 SQL*Net message to client           ACTIVE   02:58:50                       -1 938870
SH    250 1415053318262167 enq: TX - row lock contention       ACTIVE   03:31:25           247     0 964370
SH    364    111286803 buffer busy waits                   ACTIVE   03:32:46                        0 964370
SH    362 1413697536     1 SQL*Net message from client         INACTIVE 03:33:39                        0   -10
SH    247    111286803 buffer busy waits                   ACTIVE   04:12:28                        0 964370
SH    249    111286803 buffer busy waits                   ACTIVE   04:14:34                        0 964370
SH    131    111286803 buffer busy waits                   ACTIVE   04:14:40                       -1   -10

 

7 rows selected

 

USERNAME   SID    P1    P2 EVENT                               STATUS   LOGON_TIME BLOCKING_SESSION  WAIT_TIME ROW_ ROW_

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

SYSTEM129 1413697536     1 SQL*Net message to client           ACTIVE   02:58:50                       -1 938870
SH    250 2364282784   354 latch: In memory undo latch         ACTIVE   03:31:25           247     0 964370
SH    364    111286803 buffer busy waits                   ACTIVE   03:32:46                        0 964370
SH    362 1413697536     1 SQL*Net message from client         INACTIVE 03:33:39                        0   -10
SH    247     4   224 buffer busy waits                   ACTIVE   04:12:28                       -1   -10
SH    249    111286803 buffer busy waits                   ACTIVE   04:14:34                        0 964370
SH    131    111286803 buffer busy waits                   ACTIVE   04:14:40                        0 964370

 

So, as the video plainly shows (and the short text excertp here above), the most contended for block is block 1286803 of file#11.  First let's find out what file11 is:

FILE#    NAME

11    /home/oracle/app/oracle/oradata/cdb1/orcl/example01.dbf

which undoubtedly belongs to the EXAMPLE tablespace.  But which object(s) of that tablespace contain(s) block 1286803?  There are several ways to find out, but this one, if you can afford it, might be the quickest.

With my SYSTEM session (SID 129, as identified here above):

ALTER SESSION SET TRACEFILE_IDENTIFIER = mydumpedblock;

alter system dump datafile 11 block 1286803 ;

This ALTER SYSTEM DUMP command dumps the contents of datablock 1286803 into a text file, located in my "Diag Trace" folder.

select * from v$diag_info where name='Diag Trace';

INST_ID    NAME    VALUE    CON_ID

1    Diag Trace    /home/oracle/app/oracle/diag/rdbms/cdb1/cdb1/trace    0

 

Now in a terminal, I can peruse the generated file, which I can easily identify thanks to the TRACEFILE_IDENTIFIER used above:

[oracle@localhost trace]$ ls -lrtR | tail

-rw-r-----. 1 oracle oracle      81 Mar 28 18:25 cdb1_ora_6638.trm

-rw-r-----. 1 oracle oracle   41669 Mar 28 18:25 cdb1_ora_6638.trc

-rw-r-----. 1 oracle oracle     670 Mar 28 18:30 cdb1_mmon_2174.trm

-rw-r-----. 1 oracle oracle    7140 Mar 28 18:30 cdb1_mmon_2174.trc

-rw-r-----. 1 oracle oracle      70 Mar 28 18:31 cdb1_ora_6638_MYDUMPEDBLOCK.trm

-rw-r-----. 1 oracle oracle   39463 Mar 28 18:31 cdb1_ora_6638_MYDUMPEDBLOCK.trc

The header of that trace file confirms that it was generated by my SID 129 session:

*** SESSION ID:(129.13337) 2016-03-28 18:31:56.662

The data to the right-hand side of the dump file shows some of the alphanumeric data from my CHANNELS2 table:

[Direct Sales.Dir]

[ect....Channel t]

[otal...,.....Yd.]

[Tele Sales.Direc number: this

But how do you tell for sure which object this data is coming from?  Keep in mind this object could be an index.  Look for the "seg" character string in that dump file, and you wil find "seg/obj" followed by an hexadecimal: this is the object_id of the object you are looking for.

seg/obj: 0x178b5

  Grab a scientific calculator and convert to decimal this 178b5 heximal value.  That's 96 437 in decimal.

select owner, object_type ||' '||object_name " the long sought-after object" from all_objects  where object_id=96437;

OWNER     the long sought-after object

SH    TABLE CHANNELS2

And voilà!  With a few SELECTs and a block dump, I was able to determine which block of which object was causing my "buffer busy waits" wait events.



Additonal note for version 12c: the object_id appears in plain decimal in the dump file:

BH (0x883dad98) file#: 11 rdba: 0x0293a293 (10/1286803) class: 1 ba: 0x8807e000

  set: 12 pool: 3 bsz: 8192 bsi: 0 sflg: 0 pwc: 0,0

  dbwrid: 0 obj: 96437

But in version 12c, it's even useless to generate a dump file, since the object_id of the "buffer busy waits" event appears in the ROW_WAIT_OBJ# column of v$session.

SH    249    111286803 buffer busy waits                   ACTIVE   04:14:34                        0 964370
SH    131    111286803 buffer busy waits                   ACTIVE   04:14:40                        0 96437