Dion Cho – Oracle Performance Storyteller

We are natural born scientists

Posts Tagged ‘read consistency

Rethinking on ORA-01555 error

with 6 comments

You might have nothing to add on ORA-01555 error. It’s just too well known issue and there are tons of documents and helps available already.

But my test case might make you rethink on this issue.

1. Case A – Undo block overwritten

I made a very simple test case of ORA-01555 by undo block overwritten.

select * from t1 where fget1 = 1
*
ERROR at line 1:
ORA-01555: snapshot too old: rollback segment number 24 with name "_SYSSMU24$" too small



The tkprof report is as following.

select * 
from
 t1 where fget1 = 1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00      10.32          0          0          0           0  
    <-- Ignore this. Due to my trick for quick 1555 error
Fetch        1      0.03       1.25        569       1000          0           0   
    <-- Look! 1000 logical reads for 0 row!
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.03      11.58        569       1000          0           0

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 61  

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  FILTER  (cr=0 pr=0 pw=0 time=10326555 us)  
      0   TABLE ACCESS FULL T1 (cr=0 pr=0 pw=0 time=27 us) 
      <-- But no actual reads on the table t1



I have no actual reads on the table t1, but tkprof report is saying that I read 1,000 blocks! Where does this number come from?

NAME                                             DIFF       VALUE1       VALUE2
---------------------------------------- ------------ ------------ ------------
...
session logical reads                           1,079           72        1,151
consistent changes                              1,049            1        1,050
consistent gets from cache                      1,013           71        1,084
consistent gets                                 1,013           71        1,084
consistent gets - examination                     997           11        1,008
data blocks consistent reads - undo reco          995            0          995
rds applied
...



Yes! I have 995 consistent reads to apply undo record! This means that Oracle read up 1000 undo blocks for read consistency. Very impressive but disappointing. :)

2. Case B – Transaction table overwritten

I made a another simple test case of ORA-01555 by transaction table overwritten.

select /*+ index(t1) */ * 
from
 t1 where fget1(c1) = 1 and c1 > 0
;

ERROR:
ORA-01555: snapshot too old: rollback segment number 44 with name "_SYSSMU44$" too small



The tkprof report is as following.

select /*+ index(t1) */ * 
from
 t1 where fget1(c1) = 1 and c1 > 0


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.04       0.04          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       34      0.21      68.05        701      42802          0          66
<-- 42,802 reads for 66 rows!
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       36      0.26      68.10        701      42802          0          66

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 61  

Rows     Row Source Operation
-------  ---------------------------------------------------
     66  TABLE ACCESS BY INDEX ROWID T1 (cr=102 pr=15 pw=0 time=66111732 us)
     67   INDEX RANGE SCAN T1_N1 (cr=67 pr=14 pw=0 time=67090640 us)(object id 82550)
   <-- But only 102 reads on the table and index!






Again, I have no actual reads on the table and index, but tkprof report is saying that I read 42,802 blocks! Holly shit! Where does this number come from?

NAME                                             DIFF       VALUE1       VALUE2
---------------------------------------- ------------ ------------ ------------
...
session logical reads                          43,043        4,720       47,763
consistent gets from cache                     43,019        2,116       45,135
consistent gets                                43,019        2,116       45,135
consistent gets - examination                  42,808          799       43,607
consistent changes                             42,749        1,730       44,479
transaction tables consistent reads - un       42,729            0       42,729
do records applied
...



Out of 42,802 reads, I read 42,729 blocks to rollback transaction table!

This is not the end. Following is latch actitvity of transaction table rollback.

LATCH_NAME                         D_GETS   D_MISSES   D_SLEEPS  D_IM_GETS
------------------------------ ---------- ---------- ---------- ----------
row cache objects                 9406163          0          0          0
cache buffers chains              2288055         94          2       2761
undo global data                  1298330         85          0          0
enqueue hash chains                920170          1          0          0
...



9.4M row cache objects latch acquistion! For what? I’ve profiled the row cache objects latch.

       SID LADDR    CALLED                  NAME                       HITS
---------- -------- -------------------------------------------- ----------
       115 2D0B4010 kqreqd                  row cache objects           123
       115 2D0B4010 kqreqd: reget           row cache objects           849
       115 2D0B4010 kqrpre: find obj        row cache objects          3895
       115 2DF245DC kqreqd                  row cache objects            13
       115 2DF245DC kqreqd: reget           row cache objects            24
       115 2DF245DC kqrpre: find obj        row cache objects            80
       115 2DFA4644 kqreqd                  row cache objects           132
       115 2DFA4644 kqreqd: reget           row cache objects           227
       115 2DFA4644 kqrpre: find obj        row cache objects           185



Hm… Looks like Oracle is very busy to find some row cache objects. Which objects?

PARAMETER                            D_GETS
-------------------------------- ----------
dc_rollback_segments                2963371
dc_tablespaces                       158642
dc_segments                           19719
dc_users                               1081
...



Makes sense. Looks like Oracle needs to read dictionary to lookup the rollback segment information to rollback transaction tables.

The most traditional way to analyze ORA-01555 is to look into the V$UNDOSTAT view. But above test cases show the importance and power of investingation with statistics, latch activity(including profiling) and even row cache activity.

More is better, isn’t it?

Written by Dion Cho

April 4, 2009 at 2:49 pm

Follow

Get every new post delivered to your Inbox.

Join 58 other followers