When the Oracle recycle bin slows down inserts

I was asked to assist in troubleshooting an interesting problem recently, and I thought it would be good to share my methodology in resolving it. There seemed to be a gradual performance degradation on one of our 12.1.0.2 systems, starting with ORA-01013 errors being reported, seeing lots of “resmgr:cpu quantum” wait events and finally bouncing the database.

All of this happened after hours and the following morning all the previous “issues” were no longer present. Now, however, there was a backlog of data and the database just wasn’t loading it quickly enough. And this is where I joined the fray.

Since boilers were being setup, I decided to wipe the proverbial slate clean and consider the database in its (Then) present state. Looking at the OEM Top Activity page as below, it was quick to identify the process where the “backlog” was prominent.

Next step was to try and figure out why an INSERT statement was requiring so much CPU time. I was quite astonished with what I found when I drilled into the statistics of that SQL_ID

#confused

2.3 million logical I/O’s for an INSERT????? That surely can’t be right. I did an ASH report as well, but unfortunately that lead me no closer to finding the problem.

I needed slightly more detail and decided to turn to my trusty old friend (Shout out to @CaryMillsap), the extended SQL trace file! I had heard about a trick to trace only specific SQL_ID’s, and was finally able to put that to use as below.

ALTER SYSTEM SET EVENTS 'sql_trace [sql: sql_id=9uztkxt954ngy] bind=true , wait=true' ;
ALTER SYSTEM SET EVENTS 'sql_trace off' ;

After about 2 minutes, it was turned off and we found a tracefile by grepping for the SQL_ID. TKPROF was called into action, and things started making more sense.

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk     query   current      rows
------- ------  -------- ---------- ---------- --------- ---------  --------
Parse        0      0.00       0.00          0         0         0         0
Execute      1      1.05       8.83          3     31805       176         0
Fetch        0      0.00       0.00          0         0         0         0
------- ------  -------- ---------- ---------- --------- ---------  --------
total        1      1.05       8.83          3     31805       176         0

Misses in library cache during parse: 0

Elapsed times include waiting on following events:
  Event waited on                         Times   Max. Wait  Total Waited
  ------------------------------------   Waited  ----------  ------------
  latch: row cache objects                    1        0.00          0.00
  row cache lock                              1        0.12          0.12


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk     query   current      rows
------- ------  -------- ---------- ---------- --------- ---------  --------
Parse       71      0.00       0.00          0         0         0         0
Execute     77      3.57      26.62          6    839016        57        11
Fetch       54      3.40      25.29          0    196009         0        28
------- ------  -------- ---------- ---------- --------- ---------  --------
total      202      6.97      51.92          6   1035025        57        39

It turned out that most of the logical I/O’s were being executed as part of recursive SQL related to the recyclebin!

SQL ID: b52m6vduutr8j Plan Hash: 4234963248

delete from RecycleBin$
where
 bo=:1


call     count       cpu    elapsed       disk     query   current      rows
------- ------  -------- ---------- ---------- --------- ---------  --------
Parse        9      0.00       0.00          0         0         0         0
Execute      9      2.50      18.78          0    580835        10         1
Fetch        0      0.00       0.00          0         0         0         0
------- ------  -------- ---------- ---------- --------- ---------  --------
total       18      2.50      18.78          0    580835        10         1

Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS   (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  DELETE  RECYCLEBIN$ (cr=64537 pr=0 pw=0 time=2445801 us)
         0          0          0   TABLE ACCESS FULL RECYCLEBIN$ (cr=64537 pr=0 pw=0 time=2445785 us cost=1488 size=34 card=2)

****************************************************************************

SQL ID: 0k8h617b8guhf Plan Hash: 4234963248

delete from RecycleBin$
where
 purgeobj=:1


call     count       cpu    elapsed       disk     query   current       rows
------- ------  -------- ---------- ---------- --------- ---------  ---------
Parse        4      0.00       0.00          0         0         0          0
Execute      4      1.05       7.77          0    258151         0          0
Fetch        0      0.00       0.00          0         0         0          0
------- ------  -------- ---------- ---------- --------- ---------  ---------
total        8      1.05       7.77          0    258151         0          0

Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS   (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  DELETE  RECYCLEBIN$ (cr=64537 pr=0 pw=0 time=2137032 us)
         0          0          0   TABLE ACCESS FULL RECYCLEBIN$ (cr=64537 pr=0 pw=0 time=2137026 us cost=1489 size=17 card=1)

****************************************************************************

In order to appease the awaiting masses in the impending boiler, we decided to purge the recyclebin. Within about 30 minutes, we started seeing significant improvements on the response time of the INSERT statement, and the backlog was gradually depleted over the next few hours.

Having said that though, the PURGE DBA_RECYCLEBIN command is still running (As of 14 December 2017), even though we also uncovered MOS note Purging RECYCLEBIN Running Forever (Doc ID 2284986.1) and implemented the suggested workaround. As a matter of interest, the original count in the recyclebin was over 4.5 million (At the time of writing this it’s down to 2.3 million)

My best guess is that there was an attempt(s) to reclaim space from the recyclebin, and because the cleanup thereof wasn’t completing very quickly, the performance of the INSERT suffered.

Leave a Comment