ORA-1410 on UPDATE

Interesting topic appeared on Oracle forum @SQL.ru. In short, an issue is a PL/SQL code, which produces “ORA-01410: invalid ROWID” exception when it shouldn’t. 

 

Here is the code simplified as much as possible: 

drop table t cascade constraints purge;
create table t as select * from all_objects;
exec dbms_stats.gather_table_stats(user, 't');
create or replace procedure invalid_rowid(p_i number default 0
                                        , p_obj_name varchar2) is
    cursor c is
        select t.rowid
          from t
         where t.object_name = upper(p_obj_name)
           for update;
    l_c c%rowtype;
begin
    open c;
    loop
        fetch c into l_c;
        exit when c%notfound;
        if p_i = 0 then
            invalid_rowid(1, 'DUAL');
            update t set t.owner = 'not exists' where current of c;
        end if;
    end loop;
    close c;
end;
/
sho err 

select substr(value,1,100) from v$diag_info where name = 'Default Trace File';
--alter session set events '10046 trace name context forever, level 4'; 

exec invalid_rowid(p_obj_name => 'ALL_TABLES'); 

--exit

And it’s unexpected output: 

select substr(value,1,100) from v$diag_info where name = 'Default Trace File'; 

SUBSTR(VALUE,1,100)
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/test11g2/test11g2/trace/test11g2_ora_12256.trc 

alter session set events '10046 trace name context forever, level 4'; 

Session altered. 

SQL>
exec invalid_rowid(p_obj_name => 'ALL_TABLES');ES');
BEGIN invalid_rowid(p_obj_name => 'ALL_TABLES'); END; 

*
ERROR at line 1:
ORA-01410: invalid ROWID
ORA-06512: at "TIM.INVALID_ROWID", line 16
ORA-06512: at line 1 

The 10046 trace, when enabled, contains following: 

CLOSE #2:c=0,e=3,dep=0,type=1,tim=1260906859427056
=====================
PARSING IN CURSOR #3 len=55 dep=0 uid=60 oct=47 lid=60 tim=1260906859427447 hv=2579967490 ad='388b12c8' sqlid='0wnk6wucwfbh2'
BEGIN invalid_rowid(p_obj_name => 'ALL_TABLES'); END;
END OF STMT
PARSE #3:c=0,e=104,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=1260906859427446
=====================
PARSING IN CURSOR #2 len=66 dep=1 uid=60 oct=3 lid=60 tim=1260906859427847 hv=2737952794 ad='388b1638' sqlid='1sr17gajm3q0u'
SELECT T.ROWID FROM T WHERE T.OBJECT_NAME = UPPER(:B1 ) FOR UPDATE
END OF STMT
PARSE #2:c=1000,e=160,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=250223868,tim=1260906859427847
BINDS #2:
 Bind#0
  oacdty=01 mxl=32(30) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1206001 frm=01 csi=871 siz=32 off=0
  kxsbbbfp=009bc73c  bln=32  avl=10  flg=05
  value="ALL_TABLES"
EXEC #2:c=16998,e=32438,p=0,cr=891,cu=4,mis=0,r=0,dep=1,og=1,plh=250223868,tim=1260906859460328
FETCH #2:c=0,e=36,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,plh=250223868,tim=1260906859460515
=====================
PARSING IN CURSOR #4 len=66 dep=1 uid=60 oct=3 lid=60 tim=1260906859460583 hv=2737952794 ad='388b1638' sqlid='1sr17gajm3q0u'
SELECT T.ROWID FROM T WHERE T.OBJECT_NAME = UPPER(:B1 ) FOR UPDATE
END OF STMT
PARSE #4:c=0,e=24,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=250223868,tim=1260906859460582
BINDS #4:
 Bind#0
  oacdty=01 mxl=32(12) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1206001 frm=01 csi=871 siz=32 off=0
  kxsbbbfp=009b739c  bln=32  avl=04  flg=05
  value="DUAL"
EXEC #4:c=4999,e=4939,p=0,cr=891,cu=2,mis=0,r=0,dep=1,og=1,plh=250223868,tim=1260906859465582
FETCH #4:c=0,e=46,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,plh=250223868,tim=1260906859465705
FETCH #4:c=0,e=3,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,plh=250223868,tim=1260906859465730
FETCH #4:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=250223868,tim=1260906859465749
STAT #4 id=1 cnt=2 pid=0 pos=1 obj=0 op='FOR UPDATE  (cr=891 pr=0 pw=0 time=0 us)'
STAT #4 id=2 cnt=4 pid=1 pos=1 obj=0 op='BUFFER SORT (cr=891 pr=0 pw=0 time=2 us)'
STAT #4 id=3 cnt=2 pid=2 pos=1 obj=64761 op='TABLE ACCESS FULL T (cr=891 pr=0 pw=0 time=0 us cost=250 size=74 card=2)'
CLOSE #4:c=0,e=1,dep=1,type=3,tim=1260906859465972
CLOSE #4:c=0,e=3,dep=1,type=0,tim=1260906859466001
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='FOR UPDATE  (cr=891 pr=0 pw=0 time=0 us)'
STAT #2 id=2 cnt=3 pid=1 pos=1 obj=0 op='BUFFER SORT (cr=891 pr=0 pw=0 time=1 us)'
STAT #2 id=3 cnt=2 pid=2 pos=1 obj=64761 op='TABLE ACCESS FULL T (cr=891 pr=0 pw=0 time=1 us cost=250 size=74 card=2)'
CLOSE #2:c=0,e=75,dep=1,type=3,tim=1260906859466114
EXEC #3:c=22997,e=38644,p=0,cr=1782,cu=6,mis=0,r=0,dep=0,og=1,plh=0,tim=1260906859466144
ERROR #3:err=1410 tim=1260906859466157
XCTEND rlbk=0, rd_only=1, tim=1260906859468060

Notable peculiarities of the trace excerpt: 

  1. No EXEC call to the cursor denoting an UPDATE statement, yet it is reported as the root cause of an exception (WTF#1)
  2. Cursor #4 is being closed twice – first with type=3, and then with type=0 (WTF#2). What does parameter type mean in the context of the CLOSE cursor call is not clear. Note 39817.1 says nothing particular about it.
  3. The transaction is reported as COMMITed (WTF#3)

PS. that was 11.2.0.1; the same behavior is observed on 10.2.0.3.

Update #1

Thanks to Maxim Demenko WTF#2  seems to be resolved: here is stated that

type Type of close operation:
0: hard close; the cursor is not put into the server-side cursor cache
1: the cursor is cached in a previously empty slot of the server-side
cursor cache, since it executed at least 3 times
2: the cursor is placed in a slot of the server-side cursor cache at the
expense of aging out another cursor, since it executed at least 3 times
3: the cursor remains in the server-side cursor cache

About these ads

One Comment

  1. Posted April 4, 2012 at 12:59 | Permalink | Reply

    I’ve re-run the test on 11.2.0.3 and see that
    1. Still the case
    2. There are actually two different cursors, and one is absent in the trace
    3. Not the case
    Here is trace output:

    PARSING IN CURSOR #47923815674056 len=66 dep=1 uid=62 oct=3 lid=62 tim=1333529348733708 hv=2737952794 ad='7230a5278' sqlid='1sr17gajm3q0u'
    SELECT T.ROWID FROM T WHERE T.OBJECT_NAME = UPPER(:B1 ) FOR UPDATE
    END OF STMT
    PARSE #47923815674056:c=0,e=154,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=0,tim=1333529348733707
    =====================
    PARSING IN CURSOR #47923810949104 len=210 dep=2 uid=0 oct=3 lid=0 tim=1333529348734120 hv=864012087 ad='7376bc238' sqlid='96g93hntrzjtr'
    select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt, timestamp#, sample_size, minimum, maximum, distcnt, lowval, hival, density, col#, spare1, spare2, avgcln from hist_head$ where obj#=:1 and intcol#=:2
    END OF STMT
    BINDS #47923810949104:
     Bind#0
      oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
      oacflg=00 fl2=0001 frm=00 csi=00 siz=48 off=0
      kxsbbbfp=2b9621dff000  bln=22  avl=05  flg=05
      value=5125170
     Bind#1
      oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
      oacflg=00 fl2=0001 frm=00 csi=00 siz=0 off=24
      kxsbbbfp=2b9621dff018  bln=22  avl=03  flg=01
      value=1001
    EXEC #47923810949104:c=0,e=151,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=3,plh=2239883476,tim=1333529348734256
    FETCH #47923810949104:c=0,e=9,p=0,cr=2,cu=0,mis=0,r=0,dep=2,og=3,plh=2239883476,tim=1333529348734281
    CLOSE #47923810949104:c=0,e=2,dep=2,type=3,tim=1333529348734309
    BINDS #47923815674056:
     Bind#0
      oacdty=01 mxl=128(40) mxlc=00 mal=00 scl=00 pre=00
      oacflg=03 fl2=1206001 frm=01 csi=873 siz=128 off=0
      kxsbbbfp=2b9621903e68  bln=128  avl=10  flg=05
      value="ALL_TABLES"
    EXEC #47923815674056:c=7999,e=7478,p=0,cr=989,cu=3,mis=1,r=0,dep=1,og=1,plh=250223868,tim=1333529348741225
    FETCH #47923815674056:c=0,e=21,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,plh=250223868,tim=1333529348741314
    =====================
    PARSING IN CURSOR #47923813411920 len=66 dep=1 uid=62 oct=3 lid=62 tim=1333529348741404 hv=2737952794 ad='7230a5278' sqlid='1sr17gajm3q0u'
    SELECT T.ROWID FROM T WHERE T.OBJECT_NAME = UPPER(:B1 ) FOR UPDATE
    END OF STMT
    PARSE #47923813411920:c=0,e=39,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=250223868,tim=1333529348741403
    BINDS #47923813411920:
     Bind#0
      oacdty=01 mxl=128(16) mxlc=00 mal=00 scl=00 pre=00
      oacflg=03 fl2=1206001 frm=01 csi=873 siz=128 off=0
      kxsbbbfp=2b9622288cf0  bln=128  avl=04  flg=05
      value="DUAL"
    EXEC #47923813411920:c=4999,e=5054,p=0,cr=987,cu=2,mis=0,r=0,dep=1,og=1,plh=250223868,tim=1333529348746498
    FETCH #47923813411920:c=0,e=13,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,plh=250223868,tim=1333529348746558
    FETCH #47923813411920:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,plh=250223868,tim=1333529348746582
    FETCH #47923813411920:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=250223868,tim=1333529348746597
    STAT #47923813411920 id=1 cnt=2 pid=0 pos=1 obj=0 op='FOR UPDATE  (cr=987 pr=0 pw=0 time=4988 us)'
    STAT #47923813411920 id=2 cnt=4 pid=1 pos=1 obj=0 op='BUFFER SORT (cr=987 pr=0 pw=0 time=4958 us)'
    STAT #47923813411920 id=3 cnt=2 pid=2 pos=1 obj=5125170 op='TABLE ACCESS FULL T (cr=987 pr=0 pw=0 time=20 us cost=223 size=76 card=2)'
    CLOSE #47923813411920:c=0,e=1,dep=1,type=3,tim=1333529348746697
    CLOSE #47923816397984:c=0,e=2,dep=1,type=0,tim=1333529348746738
    STAT #47923815674056 id=1 cnt=1 pid=0 pos=1 obj=0 op='FOR UPDATE  (cr=987 pr=0 pw=0 time=6599 us)'
    STAT #47923815674056 id=2 cnt=3 pid=1 pos=1 obj=0 op='BUFFER SORT (cr=987 pr=0 pw=0 time=6537 us)'
    STAT #47923815674056 id=3 cnt=2 pid=2 pos=1 obj=5125170 op='TABLE ACCESS FULL T (cr=987 pr=0 pw=0 time=171 us cost=223 size=76 card=2)'
    CLOSE #47923815674056:c=0,e=41,dep=1,type=3,tim=1333529348746805
    EXEC #47923813819528:c=12998,e=13338,p=0,cr=1976,cu=5,mis=0,r=0,dep=0,og=1,plh=0,tim=1333529348746840
    ERROR #47923813819528:err=1410 tim=1333529348746851
    WAIT #47923813819528: nam='SQL*Net break/reset to client' ela= 17 driver id=1413697536 break?=1 p3=0 obj#=-1 tim=1333529348746998
    WAIT #47923813819528: nam='SQL*Net break/reset to client' ela= 665 driver id=1413697536 break?=0 p3=0 obj#=-1 tim=1333529348747687
    WAIT #47923813819528: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1333529348747713
    WAIT #47923813819528: nam='SQL*Net message from client' ela= 30149 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1333529348777904
    CLOSE #47923813819528:c=0,e=15,dep=0,type=0,tim=1333529348777963
    =====================
    PARSING IN CURSOR #47923813819528 len=48 dep=0 uid=62 oct=47 lid=62 tim=1333529348778944 hv=2223273708 ad='723094ca8' sqlid='4pzfk82288xrc'
    BEGIN dbms_session.session_trace_disable; END;
    END OF STMT
    PARSE #47923813819528:c=0,e=938,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1333529348778943
    EXEC #47923813819528:c=0,e=254,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=0,tim=1333529348779242
    

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

Follow

Get every new post delivered to your Inbox.

Join 287 other followers