首页 » ORACLE » Frequent generate a lot of cdmp* directories contain *bucket trace in bdump(二 ) root cause

Frequent generate a lot of cdmp* directories contain *bucket trace in bdump(二 ) root cause

之前记录过Frequent generate a lot of cdmp* directories contain *bucket trace in bdump , 当时根据现象与该bug 很相似,该bug解决的只是不生成cdump还是会生成trace 文件,所以要分析生成trace的根本原因。之前数据库在诊断问题时也启用过相关trace event(见下面) , 但是instance memroy 级别实例重启后不再生效, 在第一篇时我写使用oradebug列出过当时启用的event trace, 这里简单的记录

首先还是看db alert log

Wed Jun 01 22:00:12 2016 
Global Enqueue Services Deadlock detected. More info in file 
/oracle/app/oracle/diag/rdbms/anbob/anbob1/trace/anbob1_ora_11255.trc. 
Wed Jun 01 22:00:12 2016 
Dumping diagnostic data in directory=[cdmp_20160601220012], requested by (instance=1, osid=11255), summary=[abnormal process termination]. 
Wed Jun 01 22:01:01 2016 
Global Enqueue Services Deadlock detected. More info in file 
/oracle/app/oracle/diag/rdbms/anbob/anbob1/trace/anbob1_ora_25999.trc. 
Wed Jun 01 22:01:01 2016 
Dumping diagnostic data in directory=[cdmp_20160601220101], requested by (instance=1, osid=25999), summary=[abnormal process termination]. 
Wed Jun 01 22:02:01 2016 
Global Enqueue Services Deadlock detected. More info in file 
/oracle/app/oracle/diag/rdbms/anbob/anbob1/trace/anbob1_ora_29423.trc. 
Wed Jun 01 22:02:01 2016 
Dumping diagnostic data in directory=[cdmp_20160601220201], requested by (instance=1, osid=29423), summary=[abnormal process termination]. 
Wed Jun 01 22:03:00 2016 
Global Enqueue Services Deadlock detected. More info in file 
/oracle/app/oracle/diag/rdbms/anbob/anbob1/trace/anbob1_ora_3100.trc.

cdmp 是有实例发生了GES deadlock 后请求生成的,看具体的trace

Trace file /oracle/app/oracle/diag/rdbms/anbob/anbob1/trace/anbob1_ora_11255.trc 
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production 
With the Partitioning, Real Application Clusters, OLAP, Data Mining 
and Real Application Testing options 
ORACLE_HOME = /oracle/app/oracle/product/11.2.0.3/dbhome_1 
System name:	HP-UX 
Node name:	qdyyc1 
Release:	B.11.31 
Version:	U 
Machine:	ia64 
Instance name: anbob1 
Redo thread mounted by this instance: 1 
Oracle process number: 3219 
Unix process pid: 11255, image: oracle@qdyyc1 (TNS V1-V3) 


*** 2016-06-01 22:00:12.225 
*** SESSION ID:(1195.8589) 2016-06-01 22:00:12.225 
*** CLIENT ID:() 2016-06-01 22:00:12.225 
*** SERVICE NAME:(SYS$USERS) 2016-06-01 22:00:12.225 
*** MODULE NAME:(replx@qdyyc1 (TNS V1-V3)) 2016-06-01 22:00:12.225 
*** ACTION NAME:() 2016-06-01 22:00:12.225 



Single resource deadlock: blocked by granted enqueue, f 0    <<<<<<<<<<<<<<< Single resource deadlock. 
Granted global enqueue c0000015f9b20778 
----------enqueue c0000015f9b20778------------------------ 
lock version : 1066119 
Owner inst : 1 
grant_level : KJUSEREX                                       <<<<<<<<<<< already has exclusive lock. 
req_level : KJUSEREX                                         <<<<<<<<<<<
bast_level : KJUSERNL 
notify_func : 0000000000000000 
resp : c000001617da1f08 
procp : c000001636096a48 
pid : 11255 
proc version : 3438 
oprocp : 0000000000000000 
opid : 11255 
group lock owner : c000001603746b60 
possible pid : 11255 
xid : 10C9-0C93-0021E8C9 
dd_time : 0.0 secs 
dd_count : 0 
timeout : 0.0 secs 
On_timer_q? : N 
On_dd_q? : N 
lock_state : GRANTED 
ast_flag : 0x0 
Open Options : KJUSERDEADLOCK 
Convert options : KJUSERNOQUEUE KJUSERNODEADLOCKWAIT 
History : 0x14951495 
Msg_Seq : 0x0 
res_seq : 80 
valblk : 0x00000000000000000000000000000000 . 
user session for deadlock lock 0xc0000015f9b20778 
sid: 1195 ser: 8589 audsid: 596318785 user: 1149/COMMON        <<<<<<<<<<<<<<<  session info
flags: (0x41) USR/- flags_idl: (0x1) BSY/-/-/-/-/- 
flags2: (0x40009) -/-/INC 
pid: 3219 O/S info: user: replx35, term: UNKNOWN, ospid: 11255 
image: oracle@qdyyc1 (TNS V1-V3) 
client details: 
O/S info: user: replx35, term: , ospid: 11226 
machine: qdyyc1 program: replx@qdyyc1 (TNS V1-V3) 
application name: replx@qdyyc1 (TNS V1-V3), hash value=2173374484 
current SQL: 
UPDATE COMMON.SA_SHM_REFRESH_INFO SET MODIFYTIME=SYSDATE WHERE TABLE_NAME='PARAMETER_VALUE'     <<<<<<<<<<<<<<<<<
Requesting global enqueue c0000015f9b20948 
----------enqueue c0000015f9b20948------------------------ 
lock version : 628411 
Owner inst : 1 
grant_level : KJUSERNL 
req_level : KJUSEREX                               <<<<<<<<<<<< Also request exclusive mode lock. 
bast_level : KJUSERNL 
notify_func : 0000000000000000 
resp : c000001617da1f08 
procp : c000001636096a48 
pid : 11255 
proc version : 3438 
oprocp : 0000000000000000 
opid : 11255 
group lock owner : c000001603746b60 
possible pid : 11255 
xid : 10C9-0C93-0021E8C9 
dd_time : 0.0 secs 
dd_count : 0 
timeout : 0.0 secs 
On_timer_q? : N 
On_dd_q? : N 
lock_state : OPENING CONVERTING 
ast_flag : 0x0 
Open Options : KJUSERDEADLOCK 
Convert options : KJUSERGETVALUE 
History : 0x51495149 
Msg_Seq : 0x0 
res_seq : 80 
valblk : 0x00000000000000000000000000000000 . 
user session for deadlock lock 0xc0000015f9b20948 
sid: 1195 ser: 8589 audsid: 596318785 user: 1149/COMMON 
flags: (0x41) USR/- flags_idl: (0x1) BSY/-/-/-/-/- 
flags2: (0x40009) -/-/INC 
pid: 3219 O/S info: user: replx35, term: UNKNOWN, ospid: 11255 
image: oracle@qdyyc1 (TNS V1-V3) 
client details: 
O/S info: user: replx35, term: , ospid: 11226 
machine: qdyyc1 program: replx@qdyyc1 (TNS V1-V3) 
application name: replx@qdyyc1 (TNS V1-V3), hash value=2173374484 
current SQL: 
UPDATE COMMON.SA_SHM_REFRESH_INFO SET MODIFYTIME=SYSDATE WHERE TABLE_NAME='PARAMETER_VALUE' 
----------resource c000001617da1f08---------------------- 
resname : [0x2700009][0x125d3],[TX][ext 0x2,0x0] <<<<<<<<<<<<<<<< TX lock 
hash mask : x3 
Local inst : 1 
dir_inst : 1 
master_inst : 1 
hv idx : 59 
hv last r.inc : 0 
current inc : 4 
hv status : 0 
hv master : 0 
open options : dd 
grant_bits : KJUSERNL KJUSEREX 
grant mode : KJUSERNL KJUSERCR KJUSERCW KJUSERPR KJUSERPW KJUSEREX 
count : 1 0 0 0 0 1 
val_state : KJUSERVS_NOVALUE 
valblk : 0x9ffffffffffe84500129000000000000 .P) 
access_inst : 1 
vbreq_state : 0 
state : x0 
resp : c000001617da1f08 
On Scan_q? : N 
Total accesses: 545 
Imm. accesses: 452 
Granted_locks : 2 
Cvting_locks : 0 
value_block: 9f ff ff ff ff fe 84 50 01 29 00 00 00 00 00 00 
GRANTED_Q : 
lp c0000015f9b20778 gl KJUSEREX rp c000001617da1f08 [0x2700009][0x125d3],[TX][ext 0x2,0x0] 
master 1 gl owner c000001603746b60 possible pid 11255 xid 10C9-0C93-0021E8C9 bast 0 rseq 80 mseq 0 history 0x14951495 
open opt KJUSERDEADLOCK 
CONVERT_Q: 
------------------------------------------------------------------------------- 
Trace Bucket Dump Begin: default bucket for process 3219 (osid: 11255) 
TIME(*=approx):SEQ:COMPONENT:FILE@LINE:FUNCTION:SECT/DUMP: [EVENT#:PID:SID] DATA 

是一种Single resource deadlock类型的GES lock, 现在从MOS中Troubleshooting “Global Enqueue Services Deadlock detected” (文档 ID 1443482.1)分析,有记录诊断方向

4. Single resource deadlock for TX , TM or IV

trace shows:

Single resource deadlock: blocking enqueue which blocks itself, f 1
Granted global enqueue 0xd078cec0

resname :[0x2001f][0x1a96c3],[TX]
or
resname :[0x00001432][0x0],[TM]
or
resname : [0xbb7cc5db][0x82d0d4b5],[IV]

a. For single resource deadlock on TX enqueue, often it is caused by using autonomous transaction in stored procedure or PL/SQL. It is a known issue that the use of autonomous transactions is vulnerable to deadlocks. Please check out Oracle® Database Concepts Overview of Autonomous Transactions for detail explanation. Since AUTONOMOUS transaction has been used in the stored procedure, the system would consider any DML statement under this transaction as a separate one (commit/rollback won’t affect the parent), and this would cause conflict if the same row is involved in the parent transaction (INSERT, UPDATE or DELETE), and hence deadlock is reported rightly. Usually the SQL involved in the deadlock is called from a stored procedure or PL/SQL with the following line:
PRAGMA AUTONOMOUS_TRANSACTION;
To avoid such deadlock, please remove the autonomous transaction in the application code.

lock mode:
#define KJUSERNL 0 /* no permissions */ (Null)
#define KJUSERCR 1 /* concurrent read */ (Row-S (SS))
#define KJUSERCW 2 /* concurrent write */ (Row-X (SX))
#define KJUSERPR 3 /* protected read */ (Share)
#define KJUSERPW 4 /* protected write */ (S/Row-X (SSX))
#define KJUSEREX 5 /* exclusive access */ (Exclusive)

解决方法:
从dba_source or dba_triggers 中找出有AUTONOMOUS_TRANSACTION 关键字的对象,确实存在一个自制事务TRIGGER,中包含上面trace文件中的SQL语句,确认没有必要后去掉了自制事务行,问题得以解决,TOM 也提到过自制事务对deadlock的影响,个人觉得目前除了insert 操作日志外没有想到其它合理的应用场景。

打赏

对不起,这篇文章暂时关闭评论。