[20120412]自治事务(AUTONOMOUS_TRANSACTION)与deadlock问题.txt

千家信息网最后更新 2024年11月15日[20120412]自治事务(AUTONOMOUS_TRANSACTION)与deadlock问题.txt[20120412]自治事务(AUTONOMOUS_TRANSACTION)与deadlock问题.txt

生产系统rac遇到一个问题，在alert*.log:
Sat Mar 17 11:43:31 2012
Global Enqueue Services Deadlock detected. More info in file
/u01/app/oracle/admin/orcl/udump/orcl2_ora_18076.trc.
Sat Mar 17 11:43:31 2012
Trace dumping is performing id=[cdmp_20120317114331]
Sat Mar 17 11:44:29 2012
System State dumped to trace file /u01/app/oracle/admin/orcl/bdump/orcl2_diag_20766.trc

在10.2.0.3以前，会转储很大的文件到进程ora_diag_orcl*对应的转储文件，查看对应cdmp*目录，发现自己
能力有限，一直没有解决这个问题。我不得不经常检查/u01的使用情况，避免磁盘空间不足。

google找了许多链接，提示大部分都是主外键的问题。另外google这个链接：
http://studycow.itpub.net/post/37461/502772

转载如下：

五．烦人的Bug
来之前就已经知道，Oracle的安装目录/opt所在盘，时常被充满，导致Oracle停止响应。由于一直忙于处理性能问题，把这个问题
放到了最后。之前的考虑是性能问题解决了，可能这个问题就自动解决了；确实有些时候Oracle的一些bug在性能差的时候，更容易被
触发。自从调整性能后，这个问题出现的频率的降低了一些，但还是在出;正在思考的时候，发现/opt的使用率又已经到90%了，检查
发现在安装目录的bdump目录又新生成了一个4g左右的核心转储文件。

正是这个核心转储文件，占用了大量的磁盘空间。检查alertSID.log文件发现如下的内容：
Sun Jun 6 18:51:35 2010
Global Enqueue Services Deadlock detected. More info in file
/opt/oracle/product/admin/orcl/udump/orcl1_ora_26649.trc.
Sun Jun 6 19:14:05 2010
System State dumped to trace file /opt/oracle/product/admin/orcl/bdump/orcl1_diag_4783.trc
....
日志显示是由于Oracle检查到了一个ges的死锁，于是做了系统级的dump操作，这种系统级的dump出来的内容很多，导致了dump文件特别大。
感觉象是遇到了bug,在metalink找到了现象类似的bug：6145177，bug中描述的现象与医院有些相似，但不完全一样，但打了补丁后，没再
出现这个问题。这个问题在10.2.0.4中已经解决了，目前医院使用的是10.2.0.3，Oracle已经提供了单独的Patch，为了避免大的版本升级，
就应用了单独的patch,整个过程比较顺利。打了这个patch,一直用到第二天上午，再也没有出现这个错误 ，看来patch已经起了作用。


根据这个建议要升级到10.2.0.4.
我自己也检查自己的alert文件，我发现大量出现是从2011/7/14号开始，估计开发人员改动程序引起，问了半天对方也不能确定是那个程序引起的问题。
看来良好的记录与文档很重要！去年7月5号也有出现，实际上个人感觉开发人员可以回忆起来。

$ grep -B 1 '^Global Enqueue Services Deadlock detected' alert_orcl2.log | egrep '2011|2012' > /tmp/a1
Thu Jun 30 09:12:56 2011
Tue Jul 5 08:37:28 2011
Tue Jul 5 08:38:25 2011
Tue Jul 5 08:38:55 2011
Tue Jul 5 08:39:09 2011
Tue Jul 5 08:39:47 2011
Tue Jul 5 08:40:02 2011
Sat Jul 9 10:50:39 2011
Sat Jul 9 10:50:52 2011
Sun Jul 10 10:11:50 2011
Thu Jul 14 13:36:10 2011
Thu Jul 14 13:36:15 2011
Thu Jul 14 13:41:34 2011
Thu Jul 14 13:41:39 2011
Thu Jul 14 16:24:29 2011
Thu Jul 14 16:24:35 2011
Thu Jul 14 16:25:00 2011
Thu Jul 14 16:25:09 2011
Thu Jul 14 16:25:16 2011
Thu Jul 14 16:25:23 2011
Thu Jul 14 17:02:01 2011
Fri Jul 15 08:45:24 2011
Fri Jul 15 08:45:30 2011
Fri Jul 15 08:49:36 2011
Fri Jul 15 14:20:11 2011
.....
Wed Apr 11 11:46:39 2012
Wed Apr 11 19:53:17 2012
Thu Apr 12 07:47:45 2012
Thu Apr 12 14:26:26 2012
Thu Apr 12 14:26:46 2012
--从以上信息可以发现,2011/6/30号前根本没有出现这个问题，编程出现问题的可能性个人认为情况很大。

2012年3月18号作了升级到10.2.0.4，我开始一直关注以前的情况是否解决。检查发现diag文件不再迅速增加，但是
Global Enqueue Services Deadlock detected依旧出现，不过这回我可以定位问题了。

Fri Apr 13 16:29:03 2012
Global Enqueue Services Deadlock detected. More info in file
/u01/app/oracle/admin/orcl/udump/orcl2_ora_3135.trc.
Fri Apr 13 16:29:03 2012
Trace dumping is performing id=[cdmp_20120413162903]

查看对用的orcl2_ora_3135.trc转储文件，发现里面有记录的sql语句结合记录里面的XID，最终确定是问题，是开发人员在一个存储过程使用了自治事务引起的。

自己做了一个测试例子来再现这个问题：


1.测试环境：
SQL> select * from v$version ;
BANNER
--------------------------------------------------------------------------------
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
PL/SQL Release 11.2.0.1.0 - Production
CORE 11.2.0.1.0 Production
TNS for Linux: Version 11.2.0.1.0 - Production
NLSRTL Version 11.2.0.1.0 - Production

create table t (id number,name varchar2(10));
CREATE UNIQUE INDEX I_T_I ON SCOTT.T(ID);

CREATE PROCEDURE test1( l_id number,l_name varchar2,flag VARCHAR2) AS
PRAGMA AUTONOMOUS_TRANSACTION;
BEGIN
commit ;
IF flag = 'INSERT' THEN
insert into t values(l_id,l_name);
END IF;
IF flag = 'UPDATE' THEN
update t set id=l_id,name=l_name where id=l_id;
END IF;
IF flag = 'DELETE' THEN
delete from t where id=l_id;
END IF;
commit;
dbms_output.put_line (flag);
END;
/


insert into t values(1,'a');
insert into t values(2,'b');
commit;


2.测试：
打开会话1,执行如下:
SQL> set SERVEROUT on
SQL> update t set name='aaa' where id=1;

SQL> exec test1(1,'A','UPDATE');
BEGIN test1(1,'A','UPDATE'); END;

*
ERROR at line 1:
ORA-00060: deadlock detected while waiting for resource
ORA-06512: at "SCOTT.TEST1", line 9
ORA-06512: at line 1

alert提示如下：
Mon Apr 16 10:37:38 2012
ORA-00060: Deadlock detected. More info in file /u01/app/oracle11g/diag/rdbms/test/test/trace/test_ora_13751.trc.

--而且11G下记录更加详细，定位更加方便。
Deadlock graph:
---------Blocker(s)-------- ---------Waiter(s)---------
Resource Name process session holds waits process session holds waits
TX-00090008-00001193 26 132 X 26 132 X

session 132: DID 0001-001A-00000007 session 132: DID 0001-001A-00000007

Rows waited on:
Session 132: obj - rowid = 00015D00 - AAAV0AAAEAAAAIMAAA
(dictionary objn - 89344, file - 4, block - 524, slot - 0)

----- Information for the OTHER waiting sessions -----
----- End of information for the OTHER waiting sessions -----

Information for THIS session:

----- Current SQL Statement for this session (sql_id=2bbypw0dj45w2) -----
UPDATE T SET ID=:B1 ,NAME=:B2 WHERE ID=:B1
----- PL/SQL Stack -----
----- PL/SQL Call Stack -----
object line object
handle number name
0x95fcdac0 9 procedure SCOTT.TEST1
0x95f2c440 1 anonymous block
===================================================

--我的测试环境是单机，如果在rac环境下，alert提示如下：
Thu Apr 12 15:56:49 2012
Global Enqueue Services Deadlock detected. More info in file
/u01/app/oracle/admin/orcl/udump/orcl1_ora_8070.trc.
Thu Apr 12 15:56:49 2012
Trace dumping is performing id=[cdmp_20120412155649]


3.再做一个另外的测试：
SQL> rollback ;
Rollback complete.

SQL> select * from t;
ID NAME
---------- ----------
1 a
2 b

SQL> insert into t values(3,'c');
1 row created.

SQL> exec test1(1,'A','UPDATE');
UPDATE

PL/SQL procedure successfully completed.

SQL> select * from t;
ID NAME
---------- ----------
1 A
2 b
3 c


--打开另外的会话，执行：
SQL> select * from t;
ID NAME
---------- ----------
1 A
2 b

--可以发现自治事务的特点，id=1的记录已经显示修改，而插入的记录却还没有提交。


如果会话1这个时候rollback, 对id=1的修改依旧有效！
SQL> rollback ;
Rollback complete.

SQL> select * from t;
ID NAME
---------- ----------
1 A
2 b