Having Fun with ORA-00600 (qkebCreateConstantOpn1) - What is the Cause of this Error?

September 28, 2011

A friend brought an interesting Oracle Database 11.2.0.2 problem to my attention. He is in the process of upgrading to a new Oracle Database server (and Oracle Database version) and a new version of an ERP package. He has experienced an ORA-00600 error with both patch 6 and patch 9 for 11.2.0.2 on 64 bit Windows after rolling forward the database table definitions for the new version of the ERP package and then testing the ERP functionality (all in a test environment, of course).

I have not seen the most recent table modification scripts first hand, but upgrade scripts for the earlier ERP versions exercised good habits of declaring column constraints and default column values (as well as triggers to make certain that SQL script writers do not get too carried away).

So, what to do to troubleshoot this problem, call Oracle support because an ORA-00600 error is returned, or poke around a little to see if we can determine what is happening? Since I am not able to touch the database to investigate the problem freely, I asked for a 10046 trace at level 12 to be generated. Below is a portion of that trace file (the portion in bold was actually executed by the client application, while the rest is at dep=1, in this case internal SQL used for query optimization):

PARSING IN CURSOR #386947304 len=42 dep=1 uid=0 oct=3 lid=0 tim=63747639340 hv=844002283 ad='314cbd908' sqlid='ftj9uawt4wwzb'
select condition from cdef$ where rowid=:1
END OF STMT
PARSE #386947304:c=0,e=16,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=1884964958,tim=63747639340
BINDS #386947304:
 Bind#0
  oacdty=11 mxl=16(16) mxlc=00 mal=00 scl=00 pre=00
  oacflg=18 fl2=0001 frm=00 csi=00 siz=16 off=0
  kxsbbbfp=1c28c668  bln=16  avl=16  flg=05
  value=0000A680.003D.0001
EXEC #386947304:c=0,e=32,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=1884964958,tim=63747639412
FETCH #386947304:c=0,e=8,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=1884964958,tim=63747639432
STAT #386947304 id=1 cnt=1 pid=0 pos=1 obj=31 op='TABLE ACCESS BY USER ROWID CDEF$ (cr=1 pr=0 pw=0 time=4 us cost=1 size=15 card=1)'
CLOSE #386947304:c=0,e=21,dep=1,type=0,tim=63747639466
...
...
...
PARSING IN CURSOR #386943464 len=58 dep=0 uid=36 oct=6 lid=36 tim=63750497441 hv=1532843717 ad='3144ac3d8' sqlid='9m0sbg1dpupq5' 
update PART set mrp_required = :1     where id = :2       
END OF STMT 
PARSE #386943464:c=0,e=121,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=63750497440 
PARSE #386947304:c=0,e=10,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=1884964958,tim=63750497602
BINDS #386947304:
 Bind#0
  oacdty=11 mxl=16(16) mxlc=00 mal=00 scl=00 pre=00
  oacflg=18 fl2=0001 frm=00 csi=00 siz=16 off=0
  kxsbbbfp=1edffbd8  bln=16  avl=16  flg=05
  value=0000A7B3.0019.0001
EXEC #386947304:c=0,e=33,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=1884964958,tim=63750497664
FETCH #386947304:c=0,e=9,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=1884964958,tim=63750497684
CLOSE #386947304:c=0,e=8,dep=1,type=3,tim=63750497704
=====================
PARSING IN CURSOR #517995552 len=98 dep=1 uid=0 oct=3 lid=0 tim=63750497798 hv=3044436590 ad='2f0e99070' sqlid='dha5nv6urcumf'
select binaryDefVal,           lengthb(binaryDefVal) from ecol$ where tabobj# = :1 and colnum = :2
END OF STMT
PARSE #517995552:c=0,e=19,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3081038021,tim=63750497797
BINDS #517995552:
 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=1edfe758  bln=22  avl=04  flg=05
  value=18450
 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=1edfe770  bln=22  avl=03  flg=01
  value=141
EXEC #517995552:c=0,e=56,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3081038021,tim=63750497891
FETCH #517995552:c=0,e=14,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=3081038021,tim=63750497913
STAT #517995552 id=1 cnt=1 pid=0 pos=1 obj=123 op='TABLE ACCESS BY INDEX ROWID ECOL$ (cr=2 pr=0 pw=0 time=11 us cost=2 size=95 card=1)'
STAT #517995552 id=2 cnt=1 pid=1 pos=1 obj=126 op='INDEX RANGE SCAN ECOL_IX1 (cr=1 pr=0 pw=0 time=8 us cost=1 size=0 card=1)'
CLOSE #517995552:c=0,e=1,dep=1,type=3,tim=63750497955
PARSE #386947304:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=1884964958,tim=63750498060
BINDS #386947304:
 Bind#0
  oacdty=11 mxl=16(16) mxlc=00 mal=00 scl=00 pre=00
  oacflg=18 fl2=0001 frm=00 csi=00 siz=16 off=0
  kxsbbbfp=1edfe360  bln=16  avl=16  flg=05
  value=0000A7B3.0019.0001
EXEC #386947304:c=0,e=34,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=1884964958,tim=63750498120
FETCH #386947304:c=0,e=9,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=1884964958,tim=63750498140
CLOSE #386947304:c=0,e=7,dep=1,type=3,tim=63750498159
Symbol file c:\Oracle\product\11.2.0\dbhome_1\BIN\orannzsbb11.SYM does not match binary.
 Symbol TimeStamp=4cea6d1b, Module TimeStamp=4d6f3707 are different
Incident 4193 created, dump file: C:\ORACLE\diag\rdbms\test\test\incident\incdir_4193\test_ora_3796_i4193.trc
ORA-00600: internal error code, arguments: [qkebCreateConstantOpn1], [], [], [], [], [], [], [], [], [], [], []

* BLOCK CHECKING IS NOT DONE-Call Heap not initialized.
* Skip checking block dba=0x2402d02.
* BLOCK CHECKING IS NOT DONE-Call Heap not initialized.
* Skip checking block dba=0x340660f.
WAIT #386943464: nam='SQL*Net break/reset to client' ela= 2 driver id=1413697536 break?=1 p3=0 obj#=17988 tim=63752354884
WAIT #386943464: nam='SQL*Net break/reset to client' ela= 469 driver id=1413697536 break?=0 p3=0 obj#=17988 tim=63752355367
WAIT #386943464: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=17988 tim=63752355385
WAIT #386943464: nam='SQL*Net message from client' ela= 7198 driver id=1413697536 #bytes=1 p3=0 obj#=17988 tim=63752362607
WAIT #0: nam='ADR file lock' ela= 3  =0  =0  =0 obj#=17988 tim=63752362675
WAIT #0: nam='ADR file lock' ela= 67  =0  =0  =0 obj#=17988 tim=63752362763
WAIT #0: nam='ADR block file read' ela= 146  =0  =0  =0 obj#=17988 tim=63752363029
WAIT #0: nam='ADR block file write' ela= 392  =0  =0  =0 obj#=17988 tim=63752363449
XCTEND rlbk=1, rd_only=0, tim=63752364013
WAIT #0: nam='log file sync' ela= 115 buffer#=1552 sync scn=251585418 p3=0 obj#=17988 tim=63752364516
WAIT #0: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=17988 tim=63752364548

Interesting, maybe?  I ran a test in an older version of the ERP package, also using Oracle Database 11.2.0.2.  My test did not generate an ORA-00600 error, but I did notice something that was a bit interesting.  There was not a single SQL statement similar to the following in my trace file, while the SQL statement was found in the trace file that was sent to me:

select binaryDefVal, lengthb(binaryDefVal) from ecol$ where tabobj# = :1 and colnum = :2

ECOL$? Anything found by Google?  OK, two articles, I will briefly quote one of the articles for dramatic effect:

“11G introduced a fast=true feature for adding columns with default values. In 11G when you want to add a not null column with a default value, the operation completes in the blink of an eye (if there are no locks on the table of course). Now it does not have to update all the rows, it just keeps the information as meta-data in the dictionary. So adding a new column becomes just a few dictionary operations.”

I suspect that the ERP upgrade script might have added non-NULL columns with default values… so let’s take a tour through Metalink (MOS) to see if anything interesting is found:

• Doc ID 1301504.1: “ORA-00600: internal error code, arguments: [qkebCreateConstantOpn1] ON UPDATES ON TABLES WITH CONSTRAINTS”
• Bug 12316092: “ORA-600 [QKEBCREATECONSTANTOPN1] AFTER ADDING NOT NULL COLUMN WITH DEFAULT”
• Bug 12760255: “ORA-00600 INTERNAL ERROR CODE, ARGUMENTS [QKEBCREATECONSTANTOPN1] ON SELECT STAT”
• Doc ID 8501439.8, Bug 8501439:” OERI[kghfrh:ds] / [kghfrempty:ds] / [17147] ORA-7445 [memcpy] with ANALYZE in a table with added column”
• Doc ID 1106553.1: “Wrong Result For Added Column After Table Creation in 11g”
• Bug 11865621: “MERGE ON TABLE WITH COL ADDED WHEN _ADD_COL_OPTIM_ENABLED=TRUE SPINS ON CPU”
• Bug 10261680: “QUERY RETURNING WRONG RESULT WITH PARALLEL ENABLED”
• Doc ID 10080167.8, Bug 10080167: “ORA-600 [15599] / dump [kghalf] from TRIGGER with WHEN clause”

OK, so I located through Metalink a couple of potential problems that might be related to the problem that was brought to my attention, some of which might be fixed in Oracle Database 11.2.0.3 or 11.2 (the first two seem to directly pertain to this issue).  It appears that quite a few of the bugs are triggered by the optimization (the fast=true reference in the above quote) that was introduced in Oracle Database 11.1.

What might be the work-around for this particular problem (mostly rough guesses at this point – pick one):

• Wait for the release of Oracle Database 11.2.0.3 on the Windows platform… or 12.1.
• Execute “ALTER SYSTEM SET “_ADD_COL_OPTIM_ENABLED”=FALSE;” before running the scripts that add the additional columns to the tables.
• After running the ERP upgrade scripts, export the database, drop the database, create a new blank database, and then import the exported file.

Any other options?

—

If you look at the trace file output above, you might have noticed the following line:

Symbol file c:\Oracle\product\11.2.0\dbhome_1\BIN\orannzsbb11.SYM does not match binary

I wonder if that message has any relevance to the problem? It is slightly interesting to find that Oracle Database 11.2.0.1 with patch 7 installed has a file by that name with a file date of April 8, 2011 (399KB in size) while 11.2.0.2 with patch 6 apparently has an older version with a file date of November 22, 2010 (395KB in size). Probably unrelated to the problem at hand, but still interesting that a more recent release offers an older version of a file. I wonder if that file date problem could be related (requires a My Oracle Support account):

Doc ID 1272490.1: “‘Symbol file oraclsra11.SYM does not match binary’ Reported In Trace File + ORA-600 / ORA-7445″