ORA-21500 Bug for 11gR1 Client Using XMLTYPE

Recently one of the user got ORA-21500 and this was due to bug in 11gr1 client. User has 11gr1 client version which connects to 11gr2 DB and this bug is related to securefile handling in 11gr1 client. But, this post it not about going into much deeper details but  just wanted to document what i learned.

CREATE TABLE TARAL.BUG_TEST1(ID NUMBER(38,0) NOT NULL, XCOL1 SYS.XMLTYPE)
 XMLTYPE COLUMN XCOL1 STORE AS SECUREFILE BINARY XML(TABLESPACE USERS ENABLE STORAGE IN ROW CHUNK 8192);

CREATE TABLE TARAL.BUG_TEST2(ID NUMBER(38,0) NOT NULL, XCOL1 SYS.XMLTYPE)
 XMLTYPE COLUMN XCOL1 STORE AS BASICFILE CLOB(TABLESPACE USERS ENABLE STORAGE IN ROW CHUNK 8192);

SQL> select * from bug_test1;
ERROR:
ORA-21500: internal error code, arguments: [%s], [%s], [%s], [%s], [%s], [%s],[%s], [%s]

we are using windows client here,but if you use UNIX then it throws more specific error.

SQL> select * from bug_test1;
Errors in file :
OCI-21500: internal error code, arguments: [qmcxdEvtNextPPP], [], [], [], [], [], [], []
Ð@ø0Ð@ø0Ð@ø0ERROR:
ORA-21500: internal error code, arguments: [%s], [%s], [%s], [%s], [%s], [%s],[%s], [%s]

This indeed tells us it’s an OCI error. But, how to trace this in windows. Well, this is what i learned from this error.


No OCI Trace Generated With 10.2 Oracle Client Using Oracle Data Provider for .Net [ID 1371240.1]

set ORA_CLIENTTRACE_DIR=c:\temp
set EVENT_10842=server=all;user=all;stmt=all;level=15

The following levels are supported:
1 - Trace all server attach and server detach calls for servers listed in "server" attribute of the environment variable.
2 - Trace all session begin, logon, session end, logoff calls for the users listed in "user" attribute of the environment variable.
3 - Trace all prepare, execute, fetch calls for the specified statement types listed in "stmt" attribute of environment variable.
4 - Trace all Bind, Define, Describe calls.
5 - Trace all OCI LOB calls
7 - Get statistical info on all connection pooling /connection related calls
8 - Get statistical info on all session info
9 - Get statistical info on all handle info
10 - Get statistical info on time taken in execute and fetch calls
11 - Get statistical info on transaction related calls
15 - Trace all calls with statistical info.

Advertisements

ORA-00600 [kksgaGetNoAlloc_Int0]

We received this error for Interval/List partition. Here is the sample test case


drop table part_test purge;
CREATE TABLE PART_TEST (
 ID NUMBER,ST_CODE VARCHAR2(1),ST_DESC VARCHAR2(4000),
 CR_DATE date, INFO VARCHAR2(200)
 ) partition by range(ID) interval(1)
 SUBPARTITION BY LIST(ST_CODE)
 SUBPARTITION TEMPLATE
 (SUBPARTITION ST_CODE_a VALUES ('A'),
 SUBPARTITION ST_CODE_s VALUES ('S'),
 SUBPARTITION ST_CODE_v VALUES ('V'),
 SUBPARTITION ST_CODE_e VALUES ('E'),
 SUBPARTITION ST_CODE_oth VALUES (DEFAULT))
 (partition ID_1 values less than (111000));

TARAL.ORALINUX>select * from part_test where id=321000 and st_code='A';
select * from part_test where id=321000 and st_code='A'
 *
ERROR at line 1:
ORA-00600: internal error code, arguments: [kksgaGetNoAlloc_Int0], [1050005], [1048575], [], [], [], [], [], [], [], [], []

Now getting into details found that 1048575 number in that error is nothing but MAX number of allowed partitions in oracle. By the way test was done in 11.2.0.3. So, when we start partition with 111000 and add any partition it should consider one 1 list and 5 sub-partition. But, it’s considering a lot’s more and actually it’s a BUG. It calculate holes in that partition and not the  actual partitions. Here is little more details about that first argument in that error.


TARAL.ORALINUX>select ((321000-111000)*5)+5 from dual;

((321000-111000)*5)+5
---------------------
 1050005

So, it’s calculated partition value and which exceeds partition limit. That means it won’t track lowest created partition.

</pre>
TARAL.ORALINUX>select (1048570/5) + 111000 from dual;

(1048570/5)+111000
------------------
 320714

1 row selected.

TARAL.ORALINUX>select * from part_test where id=320714 and st_code='A';
select * from part_test where id=320714 and st_code='A'
 *
ERROR at line 1:
ORA-00600: internal error code, arguments: [kksgaGetNoAlloc_Int0], [1048575], [1048575], [], [], [], [], [], [], [], [], []

TARAL.ORALINUX>select * from part_test where id=320713 and st_code='A';

no rows selected
<pre>

By the way this is coming from CURSOR compilation itself i believe but not sure.  And here is the BUG

Bug 13722697  ORA-600 [kksgaGetNoAlloc_Int0] on select against composite interval partitioned table

ORA-03137 TTC protocol internal error

Recently received this error on one of our 11.1.0.7 Database. Here is the description from alert log


Errors in file /...../1.trc:
ORA-03137: TTC protocol internal error : [12333] [5] [196] [2] [] [] [] []
----- Error Stack Dump -----
ORA-03137: TTC protocol internal error : [12333] [5] [196] [2] [] [] [] []
----- Current SQL Statement for this session (sql_id=xyzxxxxxxxxxxx) -----
UPDATE test stage_table SET ..... :BIND1 ... :BIND2 ... :BIND3 ........

Well, so what does it mean. After further investigation it’s a bug regarding bind peeking.

Here is what oracle workaround for same.

Bug 8625762 ORA-3137 [12333] due to bind data not read from wire

eg: Typically the trace file will show a PROTOCOL VIOLATION with Page before data showing a SQL statement (or request to execute a statement), the last 3 bytes of which are a bind length and the start of bind data, and then will show “Current Page” with the rest of thebind data.

Workaround
Setting “_optim_peek_user_binds”=false avoids this problem but use this with caution as it can affect execution plans chosen by CBO.

Not so clear. Let’s look into some details. First part of trace


--- PROTOCOL VIOLATION DETECTED ---
----- Dump Cursor sql_id=xyzxxxxxxxxxxx xsc=0x2b99f42bc148 cur=0x2b99f3d01d40 -----
Dump Parent Cursor sql_id=xyzxxxxxxxxxxx phd=0xcccccccc plk=0xyyyyyyyyy
 sqltxt(0xcccccccc)=UPDATE test stage_table SET ..... :BIND1 ... :BIND2 ... :BIND3 ........
  hash=xxxxxxxxxxxxx
  parent=0xYYYYYY maxchild=07 plk=0xyyyyyyyyy ppn=n
.......................
.......................
.......................

  sharing failure(s)=800000040000
----- Bind Info (kkscoacd) -----
 Bind#0
  oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=2096 off=0
  kxsbbbfp=2b99f4241e10  bln=22  avl=00  flg=05
 Bind#1
  oacdty=01 mxl=2000(132) mxlc=33 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000010 frm=01 csi=873 siz=0 off=24
  kxsbbbfp=2b99f4241e28  bln=2000  avl=00  flg=01
 Bind#2
  oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=2024
  kxsbbbfp=2b99f42425f8  bln=22  avl=00  flg=01
 Bind#3
  oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=2048
  kxsbbbfp=2b99f4242610  bln=22  avl=00  flg=01
 Bind#4
  oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=2072
  kxsbbbfp=2b99f4242628  bln=22  avl=00  flg=01
 Frames pfr 0x2b99f40af0b0 siz=20744 efr 0x2b99f40aefd8 siz=20720
 kxscphp=0x2b99f4633808 siz=1992 inu=1616 nps=1504
 kxscbhp=0x2b99f4633e98 siz=3104 inu=2368 nps=2120
Starting SQL statement dump

As, you can see from this avl=00 so bind length is Zero and sharing failure(s)=800000040000 which corrospond to USER_BIND_PEEK_MISMATCH + BIND_EQUIV_FAILURE. So, this is related to bind peeking.

Further there is an another section in trace that is


-----Page before-----
XXXXXXXXX 03 5E 19 29 80 00 00 00 00 00 00 01 CC 03 00 00  [.^.)............]
XXXXXXXXX 01 0D 00 00 00 01 01 00 00 00 00 01 00 00 00 00  [................]
..................................
..................................
..................................
..................................
..................................
XXXXXXXXX 00 00 00 00 00 00 00 00 00 00 02 03 00 00 15 00  [................]
XXXXXXXXX 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  [................]
XXXXXXXXX 00 00 00 00 00 00 00 07 05 C4 02                 [...........]
-----Current Page-----
nsbfdbpt 0x1b74mmmm
ifccrcp = 0x1b74mmm, ifccrcl = 0x1b74emmm
buffer length = 56
XXXXXXXXX                                  01 02 1C 21 54             [...!T]
..................................
..................................
XXXXXXXXX 04 C3 47 51 57 06 C5 04 41 64 58 51 06 C5 04 42  [..GQW...AdXQ...B]
XXXXXXXXX 01 58 51                                         [.XQ]

03 5E – The Page before shows we have an OALL8 packet and it looks like bind data has been left on the wire. As you can see last three bytes of bind data is left and read as new packet also they matches our error.

Also, in that last three bytes length of first bind data is 5 second is 21 and so on.

I have change some names of files and other stuff but data which i want to show are same from trace.

Initrans

I was looking at Anand Blog and thought to mention one thing.

I am using 11.2.0.2 Version and here default initrans is 1. Also, the thing i want to mention is when you increase this parameters older blocks are not affected only newly created blocks after this change would be affected.


Taral@Taral1> drop table test1 purge;

Table dropped.

Taral@Taral1> create table test1(col1 number);

Table created.

Taral@Taral1> select owner,table_name,INI_TRANS,MAX_TRANS from dba_tables where owner='TARAL';

OWNER                          TABLE_NAME                      INI_TRANS  MAX_TRANS
------------------------------ ------------------------------ ---------- ----------
TARAL                          TEST1                                   1        255

Taral@Taral1> insert into test1 select rownum r from dual connect by level<=10000; 10000 rows created. Taral@Taral1> commit;

Commit complete.

Taral@Taral1> select segment_name,tablespace_name,header_file, header_block from dba_segments where segment_name='TEST1';

SEGMENT_NAME                                                                      TABLESPACE_NAME                HEADER_FILE HEADER_BLOCK
--------------------------------------------------------------------------------- ------------------------------ ----------- ------------
TEST1                                                                             USERS                                    4          522

Taral@Taral1> select SEGMENT_NAME,BLOCK_ID,FILE_ID,TABLESPACE_NAME from dba_extents where SEGMENT_NAME='TEST1';

SEGMENT_NAME                                                                        BLOCK_ID    FILE_ID TABLESPACE_NAME
--------------------------------------------------------------------------------- ---------- ---------- ------------------------------
TEST1                                                                                    520          4 USERS
TEST1                                                                                    528          4 USERS
TEST1                                                                                    536          4 USERS

Taral@Taral1>
Taral@Taral1> alter system dump datafile 4 block 528;

System altered.

Block header dump:  0x01000210
 Object id on Block? Y
 seg/obj: 0x127c1  csc: 0x00.d0319  itc: 2  flg: E  typ: 1 - DATA
     brn: 1  bdba: 0x1000208 ver: 0x01 opc: 0
     inc: 0  exflg: 0

 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x0001.002.000002ee  0x00c02ec2.008d.02  --U-  660  fsc 0x0000.000d037d
0x02   0x0000.000.00000000  0x00000000.0000.00  ----    0  fsc 0x0000.00000000
bdba: 0x01000210
data_block_dump,data header at 0xf298264

Taral@Taral1> alter table test1 initrans 5;

Table altered.

Taral@Taral1> insert into test1 select rownum r from dual connect by level<=10000; 10000 rows created. Taral@Taral1> commit;

Commit complete.

Taral@Taral1> select SEGMENT_NAME,BLOCK_ID,FILE_ID,TABLESPACE_NAME from dba_extents where SEGMENT_NAME='TEST1';

SEGMENT_NAME                                                                        BLOCK_ID    FILE_ID TABLESPACE_NAME
--------------------------------------------------------------------------------- ---------- ---------- ------------------------------
TEST1                                                                                    520          4 USERS
TEST1                                                                                    528          4 USERS
TEST1                                                                                    536          4 USERS
TEST1                                                                                    544          4 USERS
TEST1                                                                                    552          4 USERS

Taral@Taral1> alter system dump datafile 4 block 544;

System altered.

Block header dump:  0x01000220
 Object id on Block? Y
 seg/obj: 0x127c2  csc: 0x00.db29d  itc: 5  flg: E  typ: 1 - DATA
     brn: 1  bdba: 0x1000218 ver: 0x01 opc: 0
     inc: 0  exflg: 0

 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x0007.00b.00000306  0x00c00861.009a.05  --U-  654  fsc 0x0000.000db2a5
0x02   0x0000.000.00000000  0x00000000.0000.00  ----    0  fsc 0x0000.00000000
0x03   0x0000.000.00000000  0x00000000.0000.00  ----    0  fsc 0x0000.00000000
0x04   0x0000.000.00000000  0x00000000.0000.00  ----    0  fsc 0x0000.00000000
0x05   0x0000.000.00000000  0x00000000.0000.00  ----    0  fsc 0x0000.00000000
bdba: 0x01000220
data_block_dump,data header at 0xf2982ac

Taral@Taral1> alter system dump datafile 4 block 528;

System altered.

Block header dump:  0x01000210
 Object id on Block? Y
 seg/obj: 0x127c2  csc: 0x00.d03e4  itc: 2  flg: E  typ: 1 - DATA
     brn: 1  bdba: 0x1000208 ver: 0x01 opc: 0
     inc: 0  exflg: 0

 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x000a.015.000002fd  0x00c00112.00a4.0c  --U-  660  fsc 0x0000.000d03ec
0x02   0x0000.000.00000000  0x00000000.0000.00  ----    0  fsc 0x0000.00000000
bdba: 0x01000210
data_block_dump,data header at 0xf298264

Blocks already allocated are not affected but newly created blocks will take new settings.

DDL Parsing

Normally most DML/Select Statements are processed in like create cursor,parse,execute and fetch.

So, how about DDL statements ,how do they execute ? Answer is they execute in only two pass. creating cursor and parsing. Parse phase itself execute it. Let’s see example and put tracing on.

 


create table taral.test1(col1 number);

PARSING IN CURSOR #33 len=37 dep=0 uid=0 oct=1 lid=0 tim=1663011419048 hv=2791204537 ad='30c534d4' sqlid='ad60h5qm5wtpt'
create table taral.test1(col1 number)
END OF STMT
PARSE #33:c=0,e=3415,p=0,cr=2,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1663011419047

EXEC #33:c=890625,e=2330367,p=855,cr=3343,cu=52,mis=0,r=0,dep=0,og=1,plh=0,tim=1663013749499
WAIT #33: nam='log file sync' ela= 95 buffer#=558 sync scn=7375981 p3=0 obj#=528 tim=1663013749698
WAIT #33: nam='SQL*Net message to client' ela= 2 driver id=1111838976 #bytes=1 p3=0 obj#=528 tim=1663013750627

*** 2010-11-29 15:29:04.822
WAIT #33: nam='SQL*Net message from client' ela= 3531454 driver id=1111838976 #bytes=1 p3=0 obj#=528 tim=1663017282121
CLOSE #33:c=0,e=23,dep=0,type=0,tim=1663017282280

This was the only cursor in trace file. But it did say that it got executed. Let’s see what happend here using another example.


SYS@taral AS SYSDBA> variable x1 number
SYS@taral AS SYSDBA> exec dbms_sql.parse ( : x1 ,'create table taral.test2(col1 number)',dbms_sql.native);
BEGIN dbms_sql.parse ( : x1 ,'create table taral.test2(col1 number)',dbms_sql.native); END;

*
ERROR at line 1:
ORA-29471: DBMS_SQL access denied
ORA-06512: at "SYS.DBMS_SQL", line 1053
ORA-06512: at line 1

Because, we have to open a cursor first.

SYS@taral AS SYSDBA> variable x1 number
SYS@taral AS SYSDBA> exec : x1:=dbms_sql.open_cursor;

PL/SQL procedure successfully completed.
----- Session Cursor Dump -----
Current cursor: 0, pgadep=0

Open cursors(pls, sys, hwm, max): 2(0, 2, 64, 300)
 NULL=1 SYNTAX=0 PARSE=0 BOUND=1 FETCH=0 ROW=0
Cached frame pages(total, free):
 4k(5, 5), 8k(0, 0), 16k(0, 0), 32k(0, 0)
----- Session Open Cursors -----

Lets parse DDL Statement

SYS@taral AS SYSDBA> exec dbms_sql.parse ( : x1 ,'create table taral.test2(col1 number)',dbms_sql.native);

PL/SQL procedure successfully completed.

SYS@taral AS SYSDBA> desc taral.test2;
 Name
 --------------------------------------
 COL1

So, it has created table in parse phase itself.


Cursor#3(0x0D1E0E1C) state=NULL curiob=0x0D6D5970
 curflg=4d fl2=0 par=0x00000000 ses=0x35A25B5C
----- Dump Cursor sql_id=bmv42n748kx2r xsc=0x0D6D5970 cur=0x0D1E0E1C -----

LibraryHandle:  Address=35d2fe4c Hash=c8897457 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD
  ObjectName:  Name=create table taral.test2(col1 number)

    FullHashValue=8eef83d6a3fe2933b9ec82a1c8897457 Namespace=SQL AREA(00) Type=CURSOR(00) Identifier=3364451415 OwnerIdn=0
  Statistics:  InvalidationCount=1 ExecutionCount=1 LoadCount=2 ActiveLocks=1 TotalLockCount=1 TotalPinCount=1
  ...
  ...
  ...
 cursor instantiation=0x0D6D5970 used=1291067219 exec_id=0 exec=1
 child#0(0x00000000) pcs=0x2FCBD450
  clk=0x00000000 ci=0x00000000 pn=0x00000000 ctx=0x00000000
 kgsccflg=0 llk[0x0D6D5974,0x0D6D5974] idx=0
 xscflg=80002036 fl2=4060000 fl3=2042008 fl4=8000
 Frames pfr 0x0D6D5114 siz=0 efr 0x0D6D50C4 siz=0
 Cursor frame dump
 kxscphp=0x0D6D0034 siz=1000 inu=140 nps=140

We can see that executioncount is 1 here. Let’s check for select statement what happen


SYS@taral AS SYSDBA> variable y1 number

SYS@taral AS SYSDBA> exec : y1 := dbms_sql.open_cursor;
PL/SQL procedure successfully completed.

SYS@taral AS SYSDBA> exec dbms_sql.parse ( : y1 ,'select * from scott.emp where ename in(7369,7499,7521)',dbms_sql.native);
PL/SQL procedure successfully completed.

Cursor#6(0x0D1E0F3C) state=BOUND curiob=0x0D2819C8
 curflg=4d fl2=0 par=0x00000000 ses=0x35A25B5C
----- Dump Cursor sql_id=6mbszcqzu6wzp xsc=0x0D2819C8 cur=0x0D1E0F3C -----

LibraryHandle:  Address=2f55bbf4 Hash=bfa373f5 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD
  ObjectName:  Name=select * from scott.emp where ename in(7369,7499,7521)

    FullHashValue=b636966355abdb0569af1f65bfa373f5 Namespace=SQL AREA(00) Type=CURSOR(00) Identifier=3215160309 OwnerIdn=0
  Statistics:  InvalidationCount=0 ExecutionCount=0 LoadCount=2 ActiveLocks=1 TotalLockCount=1 TotalPinCount=1
  Counters:  BrokenCount=1 RevocablePointer=1 KeepDependency=1 KeepHandle=1 BucketInUse=0
....
....
cursor instantiation=0x0D2819C8 used=1291068865 exec_id=0 exec=0
 child#0(0x2F55BABC) pcs=0x2E35E450
  clk=0x30C819B4 ci=0x2E35D0E4 pn=0x35DF458C ctx=0x2DFDDCF0
 kgsccflg=0 llk[0x0D2819CC,0x0D2819CC] idx=0
 xscflg=100076 fl2=40000 fl3=2062000 fl4=100
 Frames pfr 0x00000000 siz=3044 efr 0x00000000 siz=3036
 Cursor frame dump
  enxt: 2.0x00000100  enxt: 1.0x00000adc
  pnxt: 1.0x00000008

Now, lets execute it

SYS@taral AS SYSDBA> variable z number
SYS@taral AS SYSDBA> execute : z := dbms_sql.execute (:y1);

----- Dump Cursor sql_id=6mbszcqzu6wzp xsc=0x0D2819C8 cur=0x0D1E0F3C -----

LibraryHandle:  Address=2f55bbf4 Hash=bfa373f5 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD
  ObjectName:  Name=select * from scott.emp where ename in(7369,7499,7521)

    FullHashValue=b636966355abdb0569af1f65bfa373f5 Namespace=SQL AREA(00) Type=CURSOR(00) Identifier=3215160309 OwnerIdn=0
  Statistics:  InvalidationCount=0 ExecutionCount=1 LoadCount=2 ActiveLocks=1 TotalLockCount=1 TotalPinCount=1
  Counters:  BrokenCount=1 RevocablePointer=1 KeepDependency=1 KeepHandle=1 BucketInUse=0 HandleInUse=0
  Concurrency:  DependencyMutex=2f55bc5c(0, 0, 0, 0) Mutex=2f55bcac(9, 19, 0, 6)
  Flags=RON/PIN/TIM/PN0/DBN/[10012841]
  WaitersLists:
    Lock=2f55bc4c[2f55bc4c,2f55bc4c]
    Pin=2f55bc54[2f55bc3c,2f55bc3c]
  Timestamp:  Current=11-29-2010 16:14:25
  LibraryObject:  Address=2e35e060 HeapMask=0000-0001-0001 Flags=EXS[0000] Flags2=[0000] PublicFlags=[0000]
    ChildTable:  size='16'
      Child:  id='0' Table=2e35efb0 Reference=2e35e66c Handle=2f55babc
    Children:
      Child:  childNum='0'
        LibraryHandle:  Address=2f55babc Hash=0 LockMode=N PinMode=S LoadLockMode=0 Status=VALD
          Name:  Namespace=SQL AREA(00) Type=CURSOR(00)
          Statistics:  InvalidationCount=0 ExecutionCount=1 LoadCount=1 ActiveLocks=1 TotalLockCount=1 TotalPinCount=2
          Counters:  BrokenCount=1 RevocablePointer=1 KeepDependency=0 KeepHandle=0 BucketInUse=0 HandleInUse=0
          Concurrency:  DependencyMutex=2f55bb24(0, 0, 0, 0) Mutex=2f55bcac(9, 19, 0, 6)
          Flags=RON/PIN/PN0/EXP/[10012111]
....
....
....
 cursor instantiation=0x0D2819C8 used=1291069118 exec_id=16777216 exec=1
 child#0(0x2F55BABC) pcs=0x2E35E450
  clk=0x30C819B4 ci=0x2E35D0E4 pn=0x35DF458C ctx=0x2DFDDCF0
 kgsccflg=0 llk[0x0D2819CC,0x0D2819CC] idx=0
 xscflg=c0100076 fl2=4040400 fl3=2262008 fl4=100
 Frames pfr 0x0E0F0610 siz=3044 efr 0x0E0F05B4 siz=3036
 Cursor frame dump
  enxt: 2.0x00000100  enxt: 1.0x00000adc
  pnxt: 1.0x00000008
 kxscphp=0x0DFA10B4 siz=1000 inu=152 nps=152

So, DDL is executed in two pass.