oracle bucket trace,Frequent generate a lot of cdmp* directories contain *bucket trace in bdump(二 ) ...

之前记录过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 操作日志外没有想到其它合理的应用场景。