There is an interesting case in this week. A query run over hours, it take millions of buffer gets. The query is to verify if there is any data in the past 3 month for a customer, which usually completes in a minute. The case can’t be reproduced in production clone DB. The same execution path return around 10 seconds, doing 3829 buffer gets. The execution plan is as expected as below, the index skip scan will return hundreds of rows, zero or several rows return after nested loop join.
------------------------------------------------------------------------------------------------------------- | Id | Operation | Name | Starts | A-Rows | A-Time | Buffers | Reads | ------------------------------------------------------------------------------------------------------------- | 1 | HASH UNIQUE | | 1 | 0 |00:00:02.91 | 3829 | 387 | |* 2 | TABLE ACCESS BY INDEX ROWID | BBC_OR_RTY | 1 | 0 |00:00:02.91 | 3829 | 387 | | 3 | NESTED LOOPS | | 1 | 764 |00:00:04.19 | 3829 | 387 | | 4 | TABLE ACCESS BY INDEX ROWID| BBC_OR_EVER | 1 | 763 |00:00:00.01 | 777 | 0 | |* 5 | INDEX SKIP SCAN | BBC_OR_EVER_IDX4 | 1 | 763 |00:00:00.01 | 19 | 0 | |* 6 | INDEX RANGE SCAN | RC_ORPARTY_IDX01 | 763 | 0 |00:00:02.90 | 3052 | 387 | -------------------------------------------------------------------------------------------------------------
To know where comes the buffer gets, I first enabled the extended sql trace for the session. The trace file shows the session are doing lots of phsical read – “db file sequential read”. During the 45 minute tracing range, over 90% phsical read is on the data file 152. The obj# is 0, which give me a hint that the reads are for undo data. It turns out The data file with number 152 is undo datafile. Most of the undo phisical reads is following the phsical read on the object index BBC_OR_EVER_IDX4(obj#=193624), It means that undo records need to be applied for creating CR version on the index blocks.
WAIT #1: nam='db file sequential read' ela= 8999 file#=190 block#=501237 blocks=1 obj#=193624 WAIT #1: nam='db file sequential read' ela= 6331 file#=152 block#=2608161 blocks=1 obj#=0 WAIT #1: nam='db file sequential read' ela= 15672 file#=152 block#=2608160 blocks=1 obj#=0 WAIT #1: nam='db file sequential read' ela= 7966 file#=152 block#=2608155 blocks=1 obj#=0 WAIT #1: nam='db file sequential read' ela= 14522 file#=152 block#=2608159 blocks=1 obj#=0 WAIT #1: nam='db file sequential read' ela= 662 file#=152 block#=2608158 blocks=1 obj#=0 WAIT #1: nam='db file sequential read' ela= 221 file#=152 block#=2608156 blocks=1 obj#=0 WAIT #1: nam='db file sequential read' ela= 19045 file#=152 block#=2608153 blocks=1 obj#=0 WAIT #1: nam='db file sequential read' ela= 6853 file#=152 block#=2608150 blocks=1 obj#=0 WAIT #1: nam='db file sequential read' ela= 23853 file#=152 block#=2608145 blocks=1 obj#=0 WAIT #1: nam='db file sequential read' ela= 14253 file#=152 block#=2608139 blocks=1 obj#=0 WAIT #1: nam='db file sequential read' ela= 3329 file#=152 block#=2608136 blocks=1 obj#=0 WAIT #1: nam='db file sequential read' ela= 6137 file#=152 block#=2608131 blocks=1 obj#=0 WAIT #1: nam='db file sequential read' ela= 10516 file#=152 block#=2608115 blocks=1 obj#=0 WAIT #1: nam='db file sequential read' ela= 8209 file#=152 block#=2608125 blocks=1 obj#=0 oracle@appserver:~/trace$ grep "file#=152" bbcdb1_ora_29189.trc | wc -l 357935 oracle@appserver:~/trace$ grep "file#=" bbcdb1_ora_29189.trc | wc -l 389577
After capturing the session statistics, I found some interesting figure. The session have done 8764402 consistent gets, 8338399 of 8764402 gets are on undo data. The session need to rollback transaction tables 446 times, which acquire 8040580 undo records to apply. On average, 18028 undo records need to be applied to rollback a segment header block until the sesison can identify the correct SCN. The session did not fail on ORA-01555 means through great effort, it can find the proper SCN everytime.
The index blocks of BBC_OR_EVER_IDX4 is not cleanout at the moment they were written to disk. When the following sessions access the index block, it will found here is active transaction amond the intested transaction list, following the XID in ITL slot, the session will go to the corresponding undo segment header, apply undo records and rollback the transaction table, to identify when the transaction was commit;
Name Value --------------------------------------------------------- ------- session logical reads 8775885 consistent gets 8764402 consistent gets - examination 8338399 consistent changes 8041388 transaction tables consistent reads - undo records applied 8040580 transaction tables consistent read rollbacks 446 data blocks consistent reads - undo records applied 386
To fixed the problem, I need to issue a manually cleanout, that’s a fast full index scan.
select /*+index_ffs(or bbc_or_ever_idx4)*/ count(*) from bbc_or_ever or where last_mod_dt > sysdate - 91;