Dion Cho – Oracle Performance Storyteller

We are natural born scientists

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

6 Responses

Subscribe to comments with RSS.

  1. Very impressive…this is kind of new thing i had seen

    Taral Desai

    April 5, 2009 at 2:08 am

  2. interesting finding. Keep on the good work Dion.

    coskan

    April 6, 2009 at 7:05 am

  3. can you provide the complete secnario of the test case A?

    Thanks

    Kwanyoung

    June 10, 2009 at 12:34 pm

  4. Hi Dion,

    How did you identify “Following is latch actitity of transaction table rollback.”?

    We have been plagued by these (transaction table consistent reads – undo records applied”) for some time, and don’t know what the source is.

    Thanks,

    Steve

    Steve

    May 7, 2010 at 11:45 pm

    • Hi, Steve.

      The source of the latch activity is V$LATCH. Note that the V$LATCH view contains instance-level statistics.

      Querying on V$LATCHHOLDER( or its parent view x$ksuprlat) would give session-level latch activity. But this views is not cumulative, so you need to query it aggressively to get meaningful statistics from it.

      Dion Cho

      May 12, 2010 at 12:43 am


Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: