Tuesday, March 6, 2018

'enq: RO - fast object reuse' and 'enq: KO - fast object checkpoint' Final Blocker

In Wait Event: 'enq: RO - fast object reuse' and 'enq: KO - fast object checkpoint', CKPT is shown as final_blocking_session when one DBWR is suspended.

V$ENQUEUE_STATISTICS gives detailed information (several rows for same enqueues with different reasons) and statistics.

select * from v$enqueue_statistics where eq_type in ('RO', 'KO');

  EQ_NAME                    EQ REQ_REASON             TOTAL_REQ# TOTAL_WAIT# SUCC_REQ# FAILED_REQ# CUM_WAIT_TIME REQ_DESCRIPTION                          
  -------------------------- -- ---------------------- ---------- ----------- --------- ----------- ------------- ---------------------------------------- 
  Multiple Object Reuse      RO fast object reuse           1,039          82     1,038           0     1,040,219 Coordinates fast object reuse            
  Multiple Object Reuse      RO contention                      0           0         0           0             0 Coordinates flushing of multiple objects 
  Multiple Object Checkpoint KO fast object checkpoint         60           6        60           0       870,104 Coordinates fast object checkpoint       
  Reuse Block Range          CR block range reuse ckpt      1,848          15     1,848           0            20 Coordinates fast block range reuse ckpt  
If (TOTAL_REQ# - SUCC_REQ# > 0 and FAILED_REQ# = 0), there exists on-going EQ requests.

Note: All tests are done in Oracle 12.1.0.2 on Solaris.


1. Test Setup



--Test DB is configured with:
--  db_writer_processes=2
   
drop table tab1;

create table tab1 as select level x, rpad('ABC', 100, 'X') y from dual connect by level < 1000000; 


2. 'enq: KO - fast object checkpoint' Test


Suspend one of DB WRITERs, for example, DBW1:

SQL> oradebug setorapid 12
Oracle pid: 12, Unix process pid: 19980, image: oracle@s5d00003 (DBW1)
SQL> oradebug suspend
Statement processed.
Run query:

SQL (543) > select /*+ parallel(t 4) */ count(*) from tab1 t where x < 100000;
Both blocker_sid and final_blocking_session are same, that is, CKPT (SID: 361):

SQL (123) > select c.chain_id, c.chain_signature, c.sid, c.blocker_sid bsid, final_blocking_session final_bsid, s.program, s.sql_id, s.event
            from v$wait_chains c, v$session s
            where c.sid = s.sid order by c.chain_id, s.program;

CHAIN_ID CHAIN_SIGNATURE                                         SID BSID FINAL_BSID PROGRAM     SQL_ID        EVENT
-------- ------------------------------------------------------- --- ---- ---------- ----------- ------------- -------------------------------
       1 'rdbms ipc message'<='enq: KO - fast object checkpoint' 361                 (CKPT)                    rdbms ipc message
       1 'rdbms ipc message'<='enq: KO - fast object checkpoint' 543 361         361 sqlplus.exe 4wwzmhypuvnc6 enq: KO - fast object checkpoint

SQL (123) > select sql_id, executions, substr(sql_text, 1, 60) sql_text from v$sql v where sql_id = '4wwzmhypuvnc6';

SQL_ID        EXECUTIONS SQL_TEXT
------------- ---------- ------------------------------------------------------------
4wwzmhypuvnc6          0 select /*+ parallel(t 4) */ count(*) from tab1 t where x < 1
After test, resume DBW1:

SQL> oradebug resume
By the way, to make above behavior repeatable, each time tab1 has to be dropped and recreated.


3. 'enq: RO - fast object reuse' Test


Again suspend DBW1 (same behaviour if suspend LGWR):

SQL> oradebug setorapid 12
Oracle pid: 12, Unix process pid: 19980, image: oracle@s5d00003 (DBW1)
SQL> oradebug suspend
Statement processed.
Run statement:

SQL (543) > truncate table tab1;
Both blocker_sid and final_blocking_session are same, that is, CKPT (SID: 361):

SQL (123) > select c.chain_id, c.chain_signature, c.sid, c.blocker_sid bsid, final_blocking_session final_bsid, s.program, s.sql_id, s.event
            from v$wait_chains c, v$session s
            where c.sid = s.sid order by c.chain_id, s.program;
            
CHAIN_ID CHAIN_SIGNATURE                                    SID BSID FINAL_BSID PROGRAM     SQL_ID        EVENT
-------- -------------------------------------------------- --- ---- ---------- ----------- ------------- ---------------------------
       1 'rdbms ipc message'<='enq: RO - fast object reuse' 361                 (CKPT)                    rdbms ipc message
       1 'rdbms ipc message'<='enq: RO - fast object reuse' 543  361        361 sqlplus.exe 83w7b0h5ug6ph enq: RO - fast object reuse  
       
SQL (123) > select sql_id, executions, substr(sql_text, 1, 60) sql_text from v$sql v where sql_id = '83w7b0h5ug6ph';         

SQL_ID        EXECUTIONS SQL_TEXT
------------- ---------- -------------------
83w7b0h5ug6ph          0 truncate table tab1     
After test, resume DBW1:

SQL> oradebug resume  
By the way, we observed: "enq: CR - block range reuse ckpt", also blocked by CKPT, when deleting many rows which are inserted by PL/SQL bulk SQL "forall insert into values" (to observe it clearnly, at first suspend DBWn).

Query to list all CKPT related Enqueues in a long running DB


select * from  V$ENQUEUE_STATISTICS 
 where (lower(req_description) like '%checkpo%' or lower(req_description) like '%ckpt%' or lower(req_description) like '%fast%reuse%' 
    or eq_type in ('CF', 'CR', 'KO', 'RO', 'TC', 'RT', 'HW'))
    and total_req# > 0;


4. FINAL_BLOCKING_SESSION


In both above tests, CKPT is shown as final_blocking_session, but in reality, that is DBW1 suspended. The reason is probably because Foreground process only communicates with CKPT, and has no direct IPC call of DB WRITER processes.

Oracle MOS documented this behavior:
    MOS Resolving Issues Where 'enq: RO - fast object reuse' Contention Seen During Drop or Truncate Operations (Doc ID 1475659.1)
The RO enqueue known as "Multiple object reuse" enqueue, is used to synchronise operations between foreground process 
and a background process such as DBWR or CKPT. It is typically used when dropping objects or truncating tables.
Following is the sequence of events When a truncate/drop occurs:
  1.Foreground process acquires the "RO" enqueue in exclusive mode
  2.Cross instance calls (or one call if it is a single object) are issued ("CI" enqueue is acquired)
  3.CKPT Processes on each of instances requests the DBWR to write the dirty buffers to the disk and invalidate all the clean buffers.
  4.After DBWR completes writing all blocks, the foreground process releases the RO enqueue.


5. Discussions


KO enqueue is triggered by SELECT table FULL scan, which requires writing all dirty buffer blocks into disk datafiles and updating Extent Bitmap in Segment Header Extent.

RO enqueue is triggered by TRUNCATE table, which requires cleaning up (write) segment header (bitmap info), that is the 2nd Block (Extent Bitmap) in Segment Header Extent for small table.

When both enqueues appear in top Wait Events, following Events can be also observed:
  free buffer waits
  buffer busy waits
  local write wait
  write complete waits
For "free buffer waits", P3 (set-id#) reveals the responsible DBWR.

Blog: ASSM Truncate demonstrated RO enqueue when truncating table with big "INITIAL", and explained that the blocks written were the space management bitmap blocks for the extent(s) that remained after the truncate (storage_clause "INITIAL" specifies the size of the first extent of the object. Oracle allocates space for this extent when you create the schema object).


6. row cache lock


In 'enq: RO - fast object reuse' Test, if we open one more Sqlplus Session (SID=726) and perform the same tab1 truncate, we observe "row cache lock" with "cache id = 8" (dc_objects/dc_object_grants).

drop table tab1;
create table tab1 as select level x, rpad('ABC', 100, 'X') y from dual connect by level < 1000000; 

SQL> oradebug setorapid 12
Oracle pid: 12, Unix process pid: 19980, image: oracle@s5d00003 (DBW1)
SQL> oradebug suspend
Statement processed.

SQL (543) > truncate table tab1;

SQL (726) > truncate table tab1;

select c.wait_event_text, c.sid, c.blocker_sid bsid, s.final_blocking_session final_bsid, 
       s.program, s.sql_id, s.p1text, s.p1, s.p2text, s.p2, s.p3text, s.p3
from v$wait_chains c, v$session s
where c.sid = s.sid order by c.chain_id, s.program;

WAIT_EVENT_TEXT             SID BSID FINAL_BSID PROGRAM      SQL_ID        P1TEXT               P1  P2TEXT      P2  P3TEXT  P3
--------------------------- --- ---- ---------- ------------ ------------- --------- -------------  ------  ------  ------  --
rdbms ipc message           361                  (CKPT)                    timeout             300              0            0
row cache lock              726  543        361  sqlplus.exe 83w7b0h5ug6ph cache id              8  mode        0   request  3
enq: RO - fast object reuse 543  361        361  sqlplus.exe 83w7b0h5ug6ph name|mode 1,380,909,062  2       65,563  0        1
If we create one second table (tab2), and let new Sqlplus Session (SID=726) truncate tab2, both sessions are on "enq: RO - fast object reuse", no more "row cache lock" observed.

drop table tab1;
create table tab1 as select level x, rpad('ABC', 100, 'X') y from dual connect by level < 1000000; 

drop table tab2;
create table tab2 as select level x, rpad('ABC', 100, 'X') y from dual connect by level < 1000000; 

SQL> oradebug setorapid 12
Oracle pid: 12, Unix process pid: 19980, image: oracle@s5d00003 (DBW1)
SQL> oradebug suspend
Statement processed.

SQL (543) > truncate table tab1;

SQL (726) > truncate table tab2;

select c.wait_event_text, c.sid, c.blocker_sid bsid, s.final_blocking_session final_bsid, 
       s.program, s.sql_id, s.p1text, s.p1, s.p2text, s.p2, s.p3text, s.p3
from v$wait_chains c, v$session s
where c.sid = s.sid order by c.chain_id, s.program;

WAIT_EVENT_TEXT             SID BSID FINAL_BSID PROGRAM      SQL_ID        P1TEXT               P1  P2TEXT      P2  P3TEXT  P3
--------------------------- --- ---- ---------- ------------ ------------- --------- -------------  ------  ------  ------  --
rdbms ipc message           361                  (CKPT)                    timeout             300              0            0
enq: RO - fast object reuse 543  361        361  sqlplus.exe 83w7b0h5ug6ph name|mode 1,380,909,062  2       65,563  0        1
enq: RO - fast object reuse 726  361        361  sqlplus.exe 2wdshw3gfd81s name|mode 1,380,909,062  2       65,564  0        1

select sql_id, executions, substr(sql_text, 1, 60) sql_text 
from v$sql v where sql_id in ('83w7b0h5ug6ph', '2wdshw3gfd81s');

SQL_ID        EXECUTIONS SQL_TEXT
------------- ---------- -------------------
2wdshw3gfd81s          0 truncate table tab2
83w7b0h5ug6ph          0 truncate table tab1