公司测试数据库发现执行DDL报错。
继续描述问题的诊断和解决。
DDL触发器设置导致DDL无法执行（一）:http://yangtingkun.itpub.net/post/468/526410
从对象定义是找不到问题的原因的，只能通过10046跟踪一下：
SQL> ALTER SESSION SET EVENTS ‘10046 TRACE NAME CONTEXT FOREVER, LEVEL 12’;
Session altered.
SQL> CREATE TABLE T_CREATE (ID NUMBER);
CREATE TABLE T_CREATE (ID NUMBER)
*
ERROR at line 1:
ORA-00604: error occurred at recursive SQL level 1
ORA-30511: invalid DDL operation in system triggers
ORA-06512: at line 24
ORA-06512: at line 24
SQL> ALTER SESSION SET EVENTS ‘10046 TRACE NAME CONTEXT OFF’;
Session altered.
查询得到的TRACE文件：
*** ACTION NAME:() 2012-01-31 12:15:24.811 *** MODULE NAME:(sqlplus@hpserver2.enmotech.com (TNS V1-V3)) 2012-01-31 12:15:24.811 *** SERVICE NAME:(SYS$USERS) 2012-01-31 12:15:24.811 *** SESSION ID:(146.138) 2012-01-31 12:15:24.811 Skipped error 604 during the execution OF DBFW_CONSOLE_ACCESS.TRIGGER_LOGIN *** 2012-01-31 12:15:24.811 ksedmp: internal OR fatal error ORA-00604: error occurred at recursive SQL level 1 ORA-30511: invalid DDL operation IN system triggers ORA-06512: at line 3 *** 2012-01-31 12:26:10.929 *** ACTION NAME:() 2012-01-31 12:26:10.929 *** MODULE NAME:(SQL*Plus) 2012-01-31 12:26:10.929 A deadlock among DDL AND parse locks IS detected. This deadlock IS usually due TO USER errors IN the design OF an application OR FROM issuing a SET OF concurrent statements which can cause a deadlock. This should NOT be reported TO Oracle Support. The following information may aid IN finding the errors which cause the deadlock: ORA-04020: deadlock detected while trying TO LOCK object EYGLE.BIN$trcEn8qthIjgQKjAEwAm+g==$0 -------------------------------------------------------- object waiting waiting blocking blocking handle SESSION LOCK mode SESSION LOCK mode -------- -------- -------- ---- -------- -------- ---- 0xb88364d8 0xb8f713c8 0xb56ca598 X 0xb8f713c8 0xb56ca7c0 X -------------------------------------------------------- ---------- DUMP OF WAITING AND BLOCKING LOCKS ---------- -------------------------------------------------------- ------------- WAITING LOCK ------------- ---------------------------------------- SO: 0xb56ca598, TYPE: 53, owner: 0xb73c2990, flag: INIT/-/-/0x00 LIBRARY OBJECT LOCK: LOCK=b56ca598 handle=b88364d8 request=X CALL pin=(nil) SESSION pin=(nil) hpc=0000 hlc=0000 htl=0xb56ca618[0xb56ca840,0xb53b1e18] htb=0xb53b1e18 ssga=0xb53b13b0 USER=b8f713c8 SESSION=b8f713c8 COUNT=0 flags=[0000] SAVEPOINT=0x1494 LIBRARY OBJECT HANDLE: handle=b88364d8 mtx=0xb8836608(0) cdp=0 name=EYGLE.BIN$trcEn8qthIjgQKjAEwAm+g==$0 hash=41d7b6fc85abfd51d2baef487c92dc95 TIMESTAMP=01-17-2012 17:33:09 namespace=TABL flags=KGHP/TIM/FUL/FUP/SML/[0e000000] kkkk-dddd-llll=0000-0701-0701 LOCK=X pin=X latch#=3 hpc=01d6 hlc=01d6 lwt=0xb8836580[0xb56ca5c8,0xb56ca5c8] ltm=0xb8836590[0xb8836590,0xb8836590] pwt=0xb8836548[0xb8836548,0xb8836548] ptm=0xb8836558[0xb8836558,0xb8836558] REF=0xb88365b0[0xb88365b0,0xb88365b0] lnd=0xb88365c8[0xb88365c8,0xb88365c8] LIBRARY OBJECT: object=b48a8d18 TYPE=TABL flags=EXS/LOC/UPD/PRG[0985] pflags=[0040] STATUS=VALD LOAD=0 DATA BLOCKS: DATA# heap pointer STATUS pins CHANGE whr ----- -------- -------- --------- ---- ------ --- 0 b8836418 b48a8e30 I/P/A/-/- 0 NONE 00 8 b48a88a8 b03cdbf8 I/P/A/-/- 1 UPDATE 00 9 b48a8978 b03cd428 I/P/A/-/- 1 NONE 00 10 b48a8a00 b03cd040 I/P/A/-/- 1 UPDATE 00 ------------- BLOCKING LOCK ------------ ---------------------------------------- SO: 0xb56ca7c0, TYPE: 53, owner: 0xb73c20f0, flag: INIT/-/-/0x00 LIBRARY OBJECT LOCK: LOCK=b56ca7c0 handle=b88364d8 mode=X CALL pin=(nil) SESSION pin=(nil) hpc=0000 hlc=0000 htl=0xb56ca840[0xb53b1e18,0xb56ca618] htb=0xb53b1e18 ssga=0xb53b13b0 USER=b8f713c8 SESSION=b8f82a10 COUNT=2 flags=[0000] SAVEPOINT=0xd70 LIBRARY OBJECT HANDLE: handle=b88364d8 mtx=0xb8836608(0) cdp=0 name=EYGLE.BIN$trcEn8qthIjgQKjAEwAm+g==$0 hash=41d7b6fc85abfd51d2baef487c92dc95 TIMESTAMP=01-17-2012 17:33:09 namespace=TABL flags=KGHP/TIM/FUL/FUP/SML/[0e000000] kkkk-dddd-llll=0000-0701-0701 LOCK=X pin=X latch#=3 hpc=01d6 hlc=01d6 lwt=0xb8836580[0xb56ca5c8,0xb56ca5c8] ltm=0xb8836590[0xb8836590,0xb8836590] pwt=0xb8836548[0xb8836548,0xb8836548] ptm=0xb8836558[0xb8836558,0xb8836558] REF=0xb88365b0[0xb88365b0,0xb88365b0] lnd=0xb88365c8[0xb88365c8,0xb88365c8] LIBRARY OBJECT: object=b48a8d18 TYPE=TABL flags=EXS/LOC/UPD/PRG[0985] pflags=[0040] STATUS=VALD LOAD=0 DATA BLOCKS: DATA# heap pointer STATUS pins CHANGE whr ----- -------- -------- --------- ---- ------ --- 0 b8836418 b48a8e30 I/P/A/-/- 0 NONE 00 8 b48a88a8 b03cdbf8 I/P/A/-/- 1 UPDATE 00 9 b48a8978 b03cd428 I/P/A/-/- 1 NONE 00 10 b48a8a00 b03cd040 I/P/A/-/- 1 UPDATE 00 -------------------------------------------------------- This LOCK request was aborted. *** 2012-01-31 17:25:14.137 A deadlock among DDL AND parse locks IS detected. This deadlock IS usually due TO USER errors IN the design OF an application OR FROM issuing a SET OF concurrent statements which can cause a deadlock. This should NOT be reported TO Oracle Support. The following information may aid IN finding the errors which cause the deadlock: ORA-04020: deadlock detected while trying TO LOCK object EYGLE.BIN$trcI7ykLAu7gQKjAEwAnkA==$0 -------------------------------------------------------- object waiting waiting blocking blocking handle SESSION LOCK mode SESSION LOCK mode -------- -------- -------- ---- -------- -------- ---- 0xb209bfc0 0xb8f713c8 0xb56c3aa0 X 0xb8f713c8 0xb56756f0 X -------------------------------------------------------- ---------- DUMP OF WAITING AND BLOCKING LOCKS ---------- -------------------------------------------------------- ------------- WAITING LOCK ------------- ---------------------------------------- SO: 0xb56c3aa0, TYPE: 53, owner: 0xb77d5078, flag: INIT/-/-/0x00 LIBRARY OBJECT LOCK: LOCK=b56c3aa0 handle=b209bfc0 request=X CALL pin=(nil) SESSION pin=(nil) hpc=0000 hlc=0000 htl=0xb56c3b20[0xb5675770,0xb53b1b08] htb=0xb53b1b08 ssga=0xb53b13b0 USER=b8f713c8 SESSION=b8f713c8 COUNT=0 flags=[0000] SAVEPOINT=0x386e LIBRARY OBJECT HANDLE: handle=b209bfc0 mtx=0xb209c0f0(0) cdp=0 name=EYGLE.BIN$trcI7ykLAu7gQKjAEwAnkA==$0 hash=f2ab522fb35d982d1fbc28237e665464 TIMESTAMP=01-17-2012 17:34:17 namespace=TABL flags=KGHP/TIM/FUP/SML/[0a000000] kkkk-dddd-llll=0000-0701-0701 LOCK=X pin=X latch#=2 hpc=0038 hlc=0038 lwt=0xb209c068[0xb56c3ad0,0xb56c3ad0] ltm=0xb209c078[0xb209c078,0xb209c078] pwt=0xb209c030[0xb209c030,0xb209c030] ptm=0xb209c040[0xb209c040,0xb209c040] REF=0xb209c098[0xb209c098,0xb209c098] lnd=0xb209c0b0[0xb209c0b0,0xb209c0b0] LIBRARY OBJECT: object=b0c49fd8 TYPE=TABL flags=EXS/LOC/UPD/PRG[0985] pflags=[0040] STATUS=VALD LOAD=0 DATA BLOCKS: DATA# heap pointer STATUS pins CHANGE whr ----- -------- -------- --------- ---- ------ --- 0 b209bf00 b0c4a0f0 I/P/A/-/- 0 NONE 00 8 b0c49b68 b0201480 I/P/A/-/- 1 UPDATE 00 9 b0c49c38 b0200cb0 I/P/A/-/- 1 NONE 00 10 b0c49cc0 b01af398 I/P/A/-/- 1 UPDATE 00 ------------- BLOCKING LOCK ------------ ---------------------------------------- SO: 0xb56756f0, TYPE: 53, owner: 0xb77d47d8, flag: INIT/-/-/0x00 LIBRARY OBJECT LOCK: LOCK=b56756f0 handle=b209bfc0 mode=X CALL pin=(nil) SESSION pin=(nil) hpc=0000 hlc=0000 htl=0xb5675770[0xb53b1b08,0xb56c3b20] htb=0xb53b1b08 ssga=0xb53b13b0 USER=b8f713c8 SESSION=b8f6fe60 COUNT=2 flags=[0000] SAVEPOINT=0x35eb LIBRARY OBJECT HANDLE: handle=b209bfc0 mtx=0xb209c0f0(0) cdp=0 name=EYGLE.BIN$trcI7ykLAu7gQKjAEwAnkA==$0 hash=f2ab522fb35d982d1fbc28237e665464 TIMESTAMP=01-17-2012 17:34:17 namespace=TABL flags=KGHP/TIM/FUP/SML/[0a000000] kkkk-dddd-llll=0000-0701-0701 LOCK=X pin=X latch#=2 hpc=0038 hlc=0038 lwt=0xb209c068[0xb56c3ad0,0xb56c3ad0] ltm=0xb209c078[0xb209c078,0xb209c078] pwt=0xb209c030[0xb209c030,0xb209c030] ptm=0xb209c040[0xb209c040,0xb209c040] REF=0xb209c098[0xb209c098,0xb209c098] lnd=0xb209c0b0[0xb209c0b0,0xb209c0b0] LIBRARY OBJECT: object=b0c49fd8 TYPE=TABL flags=EXS/LOC/UPD/PRG[0985] pflags=[0040] STATUS=VALD LOAD=0 DATA BLOCKS: DATA# heap pointer STATUS pins CHANGE whr ----- -------- -------- --------- ---- ------ --- 0 b209bf00 b0c4a0f0 I/P/A/-/- 0 NONE 00 8 b0c49b68 b0201480 I/P/A/-/- 1 UPDATE 00 9 b0c49c38 b0200cb0 I/P/A/-/- 1 NONE 00 10 b0c49cc0 b01af398 I/P/A/-/- 1 UPDATE 00 -------------------------------------------------------- This LOCK request was aborted. *** 2012-01-31 17:39:16.132 WAIT #2: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=37 tim=1296877691535577 *** 2012-01-31 17:40:12.165 WAIT #2: nam='SQL*Net message from client' ela= 54719914 driver id=1650815232 #bytes=1 p3=0 obj#=37 tim=1296877746255669 XCTEND rlbk=0, rd_only=1 ===================== PARSING IN CURSOR #10 len=33 dep=0 uid=60 oct=1 lid=60 tim=1296877746256995 hv=4051323229 ad='b2088510' CREATE TABLE T_CREATE (ID NUMBER) END OF STMT PARSE #10:c=0,e=885,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1296877746256954 BINDS #10: ===================== . . . ===================== PARSING IN CURSOR #13 len=753 dep=1 uid=58 oct=47 lid=58 tim=1296877746275168 hv=2905514213 ad='b8852970' DECLARE li ora_name_list_t; n INTEGER; cSQL CLOB; BEGIN IF dbfw_console_access.is_local THEN IF ora_dict_obj_type = 'TABLE' AND ora_dict_obj_owner = 'DBFW_CONSOLE_ACCESS' AND ora_dict_obj_name = 'EVENT' THEN NULL; ELSE n := ora_sql_txt(li); FOR i IN 1 .. n loop cSQL := cSQL || li(i); END loop; IF cSQL IS NOT NULL THEN INSERT INTO dbfw_console_access.event(id,username,sessionid,event,text) SELECT dbfw_console_access.event_seq.nextval, sys_context('USERENV','SESSION_USER'), sys_context('USERENV','SESSIONID'), 'DDL', cSQL FROM dual; END IF; END IF; END IF; END; END OF STMT PARSE #13:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1296877746275166 BINDS #13: ===================== PARSING IN CURSOR #5 len=213 dep=2 uid=58 oct=2 lid=58 tim=1296877746275611 hv=1466247469 ad='b88468c0' INSERT INTO DBFW_CONSOLE_ACCESS.EVENT(ID,USERNAME,SESSIONID,EVENT,TEXT) SELECT DBFW_CONSOLE_ACCESS.EVENT_SEQ.NEXTVAL, SYS_CONTEXT('USERENV','SESSION_USER'), SYS_CONTEXT('USERENV','SESSIONID'), 'DDL', :B1 FROM DUAL END OF STMT PARSE #5:c=0,e=17,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=1,tim=1296877746275608 BINDS #5: kkscoacd Bind#0 oacdty=112 mxl=4000(4000) mxlc=00 mal=00 scl=00 pre=00 oacflg=01 fl2=206001 frm=01 csi=873 siz=4000 off=0 kxsbbbfp=7fa2b3cf99c0 bln=4000 avl=40 flg=05 VALUE= Dump OF memory FROM 0x00007FA2B3CF99C0 TO 0x00007FA2B3CF99E8 7FA2B3CF99C0 01002600 03800802 00000200 0092008A [.&..............] 7FA2B3CF99D0 08000000 17006903 01000000 00000000 [.....i..........] 7FA2B3CF99E0 F9D69D36 5422DE81 [6....."T] ===================== . . . ===================== PARSING IN CURSOR #4 len=57 dep=3 uid=0 oct=12 lid=0 tim=1296877746278076 hv=0 ad='b40eead8' drop table "EYGLE"."BIN$trcI7ykLAu7gQKjAEwAnkA==$0" purge END OF STMT PARSE #4:c=0,e=158,p=0,cr=0,cu=0,mis=1,r=0,dep=3,og=4,tim=1296877746278074 BINDS #4: ===================== . . . ===================== PARSING IN CURSOR #7 len=753 dep=4 uid=58 oct=47 lid=58 tim=1296877746356839 hv=2905514213 ad='b8852970' declare li ora_name_list_t; n integer; cSQL clob; begin if dbfw_console_access.is_local then if ora_dict_obj_type = 'TABLE' and ora_dict_obj_owner = 'DBFW_CONSOLE_ACCESS' and ora_dict_obj_name = 'EVENT' then null; else n := ora_sql_txt(li); for i in 1 .. n loop cSQL := cSQL || li(i); end loop; if cSQL is not null then insert into dbfw_console_access.event(id,username,sessionid,event,text) select dbfw_console_access.event_seq.nextval, sys_context('USERENV','SESSION_USER'), sys_context('USERENV','SESSIONID'), 'DDL', cSQL from dual; end if; end if; end if; end; END OF STMT PARSE #7:c=0,e=26,p=0,cr=0,cu=0,mis=0,r=0,dep=4,og=1,tim=1296877746356836 BINDS #7: ===================== PARSING IN CURSOR #14 len=213 dep=5 uid=58 oct=2 lid=58 tim=1296877746357237 hv=1466247469 ad='b88468c0' INSERT INTO DBFW_CONSOLE_ACCESS.EVENT(ID,USERNAME,SESSIONID,EVENT,TEXT) SELECT DBFW_CONSOLE_ACCESS.EVENT_SEQ.NEXTVAL, SYS_CONTEXT('USERENV','SESSION_USER'), SYS_CONTEXT('USERENV','SESSIONID'), 'DDL', :B1 FROM DUAL END OF STMT PARSE #14:c=0,e=15,p=0,cr=0,cu=0,mis=0,r=0,dep=5,og=1,tim=1296877746357234 BINDS #14: kkscoacd Bind#0 oacdty=112 mxl=4000(4000) mxlc=00 mal=00 scl=00 pre=00 oacflg=01 fl2=206001 frm=01 csi=873 siz=4000 off=0 kxsbbbfp=7fa2b3d2d680 bln=4000 avl=40 flg=05 value= Dump of memory from 0x00007FA2B3D2D680 to 0x00007FA2B3D2D6A8 7FA2B3D2D680 01002600 03800802 00000200 0092008A [.&..............] 7FA2B3D2D690 0A000000 31006903 01000000 00000000 [.....i.1........] 7FA2B3D2D6A0 30937991 2DB5F5E9 [.y.0...-] ===================== . . . ===================== PARSING IN CURSOR #11 len=51 dep=7 uid=0 oct=10 lid=0 tim=1296877746421849 hv=0 ad='b40e3b50' drop index "EYGLE"."BIN$trcI7ykNAu7gQKjAEwAnkA==$0" END OF STMT PARSE #11:c=5000,e=19651,p=1,cr=66,cu=0,mis=1,r=0,dep=7,og=4,tim=1296877746421846 BINDS #11: EXEC #1:c=10999,e=55067,p=2,cr=154,cu=18,mis=0,r=0,dep=6,og=4,tim=1296877746421937 ERROR #1:err=30511 tim=793245673 STAT #12 id=1 cnt=1 pid=0 pos=1 obj=0 op='NESTED LOOPS (cr=12 pr=0 pw=0 time=184 us)' STAT #12 id=2 cnt=1 pid=1 pos=1 obj=32 op='TABLE ACCESS BY INDEX ROWID CCOL$ (cr=4 pr=0 pw=0 time=33 us)' STAT #12 id=3 cnt=1 pid=2 pos=1 obj=54 op='INDEX RANGE SCAN I_CCOL1 (cr=3 pr=0 pw=0 time=19 us)' STAT #12 id=4 cnt=1 pid=1 pos=2 obj=21 op='TABLE ACCESS BY INDEX ROWID COL$ (cr=8 pr=0 pw=0 time=149 us)' STAT #12 id=5 cnt=1 pid=4 pos=1 obj=47 op='INDEX UNIQUE SCAN I_COL3 (cr=4 pr=0 pw=0 time=79 us)' STAT #2 id=1 cnt=2 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=3 pr=0 pw=0 time=67 us)' STAT #2 id=2 cnt=3 pid=1 pos=1 obj=702 op='TABLE ACCESS FULL RECYCLEBIN$ (cr=3 pr=0 pw=0 time=40 us)' EXEC #14:c=17998,e=65066,p=2,cr=373,cu=57,mis=0,r=0,dep=5,og=1,tim=1296877746422333 ERROR #14:err=604 tim=793245673 EXEC #7:c=17998,e=65535,p=2,cr=374,cu=82,mis=0,r=0,dep=4,og=1,tim=1296877746422463 ERROR #7:err=30511 tim=793245673 XCTEND rlbk=1, rd_only=1 STAT #3 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=3 pr=0 pw=0 time=75 us)' STAT #3 id=2 cnt=3 pid=1 pos=1 obj=702 op='TABLE ACCESS FULL RECYCLEBIN$ (cr=3 pr=0 pw=0 time=48 us)' EXEC #5:c=73990,e=147097,p=5,cr=882,cu=104,mis=0,r=0,dep=2,og=1,tim=1296877746422739 ERROR #5:err=604 tim=793245673 EXEC #13:c=73990,e=147555,p=5,cr=883,cu=130,mis=0,r=0,dep=1,og=1,tim=1296877746422827 ERROR #13:err=30511 tim=793245673 WAIT #10: nam='log file sync' ela= 76283 buffer#=2642 p2=4987314 p3=0 obj#=-1 tim=1296877746499472 WAIT #10: nam='SQL*Net break/reset to client' ela= 3 driver id=1650815232 break?=1 p3=0 obj#=-1 tim=1296877746499549 WAIT #10: nam='SQL*Net break/reset to client' ela= 92 driver id=1650815232 break?=0 p3=0 obj#=-1 tim=1296877746499674 WAIT #10: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1296877746499688 *** 2012-01-31 17:40:22.304 WAIT #10: nam='SQL*Net message from client' ela= 9656896 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1296877756156629 ===================== PARSING IN CURSOR #19 len=55 dep=0 uid=60 oct=42 lid=60 tim=1296877756157111 hv=524428051 ad='0' ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF' END OF STMT PARSE #19:c=0,e=198,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1296877756157104 EXEC #19:c=0,e=83,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1296877756157288 |
不难看出，导致问题产生的原因是由于在执行了CREATE TABLE语句后，触发器引发了删除回收站中的索引和表的DDL，而这个DDL又会再次引发触发器的触发，从而在一个会话中引入了死锁。
不过为什么触发器会导致回收站中的索引和表的DROP动作呢，查询后发现，原来触发器的触发动作是一个INSERT语句，而当前表中数据已满，需要扩展新的空间，而恰好这个对象所在的表空间也没有剩余空间了，所以Oracle不得以要清除RECYCLEBIN中的对象来释放新的空间：
SQL> SELECT TABLE_NAME, tablespace_name FROM dba_tables 2 WHERE TABLE_NAME = 'EVENT' 3 AND OWNER = 'DBFW_CONSOLE_ACCESS'; TABLE_NAME TABLESPACE_NAME ------------------------------ ------------------------------ EVENT USERS SQL> SELECT SUM(BYTES)/1024/1024 FROM DBA_FREE_SPACE WHERE TABLESPACE_NAME = 'USERS'; SUM(BYTES)/1024/1024 -------------------- |
找到问题的原因解决起来就很简单了，不过由于DDL触发器会导致INSERT，因此除了PURGE之外，所有其他的尝试都会报错：
SQL> conn / AS sysdba Connected. SQL> purge TABLE eygle.t_pwd; TABLE purged. SQL> SELECT * FROM dba_recyclebin; no ROWS selected SQL> CREATE TABLE T_CREATE (ID NUMBER); TABLE created. |
好在PURGE语句没有导致触发器的触发，从而避免了错误的产生，如果PURGE同样导致触发器运行，或者RECYCLEBIN中没有对象可以清除，那么当前的问题可能就很难用常规手段解决了。
这也说明一个问题，在DDL触发器中执行的操作一定要谨慎，否则很容易导致系统的故障。