Oracle hint ignore_row_on_dupkey_index - part 2

Last time we’ve seen that there is something really sneaky going on when we use hint ignore_row_on_dupkey_index. We have several clues for that:

1. 1.85 seconds vs 1:27.96 with hint. That’s about 50x slower.
2. 133 369 logical reads vs 1 156 645. That’s almost 9x more.

Another thing you would definitely find strange is the difference in sizes of trace files: 22 KB vs 35 MB … that’s quite huge.

So let’s open the larger one and see if we can spot anything strange:

… *** 2015-11-19 12:08:07.979 *** SESSION ID:(95.53) 2015-11-19 12:08:07.979 *** CLIENT ID:() 2015-11-19 12:08:07.979 *** SERVICE NAME:(SYS$USERS) 2015-11-19 12:08:07.979 *** MODULE NAME:(sqlplus@localhost.localdomain (TNS V1-V3)) 2015-11-19 12:08:07.979 *** ACTION NAME:() 2015-11-19 12:08:07.979 WAIT #140056955617216: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1447931287979703 *** 2015-11-19 12:08:18.806 WAIT #140056955617216: nam='SQL*Net message from client' ela= 10826864 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1447931298806851 CLOSE #140056955617216:c=0,e=11,dep=0,type=1,tim=1447931298806957 ===================== PARSING IN CURSOR #140056955763032 len=113 dep=0 uid=0 oct=2 lid=0 tim=1447931298808784 hv=688533685 ad='b89b3418' sqlid='5v0vfdcnhnc5p' insert /*+ rule ignore_row_on_dupkey_index(table1, table1_pk) */ into mydbdba.table1 select * from mydbdba.table2 END OF STMT PARSE #140056955763032:c=2000,e=1770,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=3,plh=1708808563,tim=1447931298808778 ===================== PARSING IN CURSOR #140056955737968 len=131 dep=1 uid=0 oct=3 lid=0 tim=1447931298809899 hv=1635361899 ad='b8e8eb30' sqlid='2jfqzrxhrm93b' select /*+ rule */ c.name, u.name from con$ c, cdef$ cd, user$ u  where c.con# = cd.con# and cd.enabled = :1 and c.owner# = u.user# END OF STMT PARSE #140056955737968:c=0,e=74,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=1027684349,tim=1447931298809895 EXEC #140056955737968:c=0,e=85,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=1027684349,tim=1447931298810084 FETCH #140056955737968:c=1000,e=180,p=0,cr=8,cu=0,mis=0,r=1,dep=1,og=3,plh=1027684349,tim=1447931298810294 STAT #140056955737968 id=1 cnt=1 pid=0 pos=1 obj=0 op='NESTED LOOPS  (cr=8 pr=0 pw=0 time=204 us)' STAT #140056955737968 id=2 cnt=1 pid=1 pos=1 obj=0 op='NESTED LOOPS  (cr=6 pr=0 pw=0 time=154 us)' STAT #140056955737968 id=3 cnt=1 pid=2 pos=1 obj=31 op='TABLE ACCESS BY INDEX ROWID CDEF$ (cr=3 pr=0 pw=0 time=102 us)' STAT #140056955737968 id=4 cnt=1 pid=3 pos=1 obj=56 op='INDEX RANGE SCAN I_CDEF4 (cr=2 pr=0 pw=0 time=63 us)' STAT #140056955737968 id=5 cnt=1 pid=2 pos=2 obj=28 op='TABLE ACCESS BY INDEX ROWID CON$ (cr=3 pr=0 pw=0 time=44 us)' STAT #140056955737968 id=6 cnt=1 pid=5 pos=1 obj=52 op='INDEX UNIQUE SCAN I_CON2 (cr=2 pr=0 pw=0 time=28 us)' STAT #140056955737968 id=7 cnt=1 pid=1 pos=2 obj=22 op='TABLE ACCESS CLUSTER USER$ (cr=2 pr=0 pw=0 time=34 us)' STAT #140056955737968 id=8 cnt=1 pid=7 pos=1 obj=11 op='INDEX UNIQUE SCAN I_USER# (cr=1 pr=0 pw=0 time=12 us)' CLOSE #140056955737968:c=0,e=105,dep=1,type=1,tim=1447931298810435 PARSE #140056955737968:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=1027684349,tim=1447931298810877 EXEC #140056955737968:c=0,e=43,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=1027684349,tim=1447931298810985 FETCH #140056955737968:c=0,e=73,p=0,cr=8,cu=0,mis=0,r=1,dep=1,og=3,plh=1027684349,tim=1447931298811098 CLOSE #140056955737968:c=0,e=23,dep=1,type=3,tim=1447931298811162 PARSE #140056955737968:c=0,e=21,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=1027684349,tim=1447931298811475 EXEC #140056955737968:c=0,e=70,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=1027684349,tim=1447931298811601 FETCH #140056955737968:c=0,e=93,p=0,cr=8,cu=0,mis=0,r=1,dep=1,og=3,plh=1027684349,tim=1447931298811722 CLOSE #140056955737968:c=0,e=12,dep=1,type=3,tim=1447931298811766 PARSE #140056955737968:c=0,e=22,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=1027684349,tim=1447931298812046 EXEC #140056955737968:c=0,e=40,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=1027684349,tim=1447931298812137 FETCH #140056955737968:c=0,e=80,p=0,cr=8,cu=0,mis=0,r=1,dep=1,og=3,plh=1027684349,tim=1447931298812278 CLOSE #140056955737968:c=0,e=12,dep=1,type=3,tim=1447931298812321 PARSE #140056955737968:c=0,e=19,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=1027684349,tim=1447931298812625 EXEC #140056955737968:c=0,e=31,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=1027684349,tim=1447931298812720 FETCH #140056955737968:c=0,e=72,p=0,cr=8,cu=0,mis=0,r=1,dep=1,og=3,plh=1027684349,tim=1447931298812819 CLOSE #140056955737968:c=0,e=11,dep=1,type=3,tim=1447931298812861 PARSE #140056955737968:c=0,e=34,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=1027684349,tim=1447931298813149 EXEC #140056955737968:c=0,e=41,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=1027684349,tim=1447931298813268 FETCH #140056955737968:c=0,e=82,p=0,cr=8,cu=0,mis=0,r=1,dep=1,og=3,plh=1027684349,tim=1447931298813379 CLOSE #140056955737968:c=0,e=12,dep=1,type=3,tim=1447931298813422 PARSE #140056955737968:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=1027684349,tim=1447931298813774 EXEC #140056955737968:c=0,e=28,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=1027684349,tim=1447931298813868 FETCH #140056955737968:c=0,e=71,p=0,cr=8,cu=0,mis=0,r=1,dep=1,og=3,plh=1027684349,tim=1447931298813966 CLOSE #140056955737968:c=0,e=11,dep=1,type=3,tim=1447931298814008 …

It’s cursor #140056955737968 craziness! It’s getting called again and again and ….

Ok, let’s have a look how many times it’s actually called

SQL ID: 2jfqzrxhrm93b Plan Hash: 1027684349 select /*+ rule */ c.name, u.name from  con$ c, cdef$ cd, user$ u  where c.con# = cd.con# and cd.enabled = :1 and   c.owner# = u.user# call     count       cpu    elapsed       disk      query    current        rows ------- ------  -------- ---------- ---------- ---------- ----------  ---------- Parse    99001      2.63       2.72          0          0          0           0 Execute  99001      5.44       4.02          0          0          0           0 Fetch    99001     11.73       8.65          0     792008          0       99001 ------- ------  -------- ---------- ---------- ---------- ----------  ---------- total   297003     19.81      15.40          0     792008          0       99001 Misses in library cache during parse: 0 Optimizer mode: RULE Parsing user id: SYS   (recursive depth: 1) Number of plan statistics captured: 1 Rows (1st) Rows (avg) Rows (max)  Row Source Operation ---------- ---------- ----------  ---------------------------------------------------          1          1          1  NESTED LOOPS  (cr=8 pr=0 pw=0 time=204 us)          1          1          1   NESTED LOOPS  (cr=6 pr=0 pw=0 time=154 us)          1          1          1    TABLE ACCESS BY INDEX ROWID CDEF$ (cr=3 pr=0 pw=0 time=102 us)          1          1          1     INDEX RANGE SCAN I_CDEF4 (cr=2 pr=0 pw=0 time=63 us)(object id 56)          1          1          1    TABLE ACCESS BY INDEX ROWID CON$ (cr=3 pr=0 pw=0 time=44 us)          1          1          1     INDEX UNIQUE SCAN I_CON2 (cr=2 pr=0 pw=0 time=28 us)(object id 52)          1          1          1   TABLE ACCESS CLUSTER USER$ (cr=2 pr=0 pw=0 time=34 us)<          1          1          1    INDEX UNIQUE SCAN I_USER# (cr=1 pr=0 pw=0 time=12 us)(object id 11) ********************************************************************************

Remember how many rows which table had? Let me remind you

• table1 with 100 000 rows 
• table2 with 199 001 rows from which 99 001 have same primary key value like rows in table1

So this SQL is called EXACLY as many times as there are matching keys (duplicates)!

What this query seems to do is to select names of owners and names of constraints enabled for table1. Why would you do that and why for EVERY failed row is really beyond me …