Oracle死锁(ORA-00060)导致的业务故障解决

208次阅读

共计 9812 个字符，预计需要花费 25 分钟才能阅读完成。

1、问题发现

检查客户数据库的时候发现存在大量死锁的情况

Thread 1 advanced to log sequence 257 (LGWR switch)
Current log# 16 seq# 257 mem# 0: /oradata/Oracle/online_log/redo16_01.log
Current log# 16 seq# 257 mem# 1: /oradata/oracle/online_log/redo16_02.log
Tue Jul 03 10:14:53 2018
Archived Log entry 385 added for thread 1 sequence 256 ID 0x59dc8ffa dest 1:
Tue Jul 03 10:14:53 2018
LNS: Standby redo logfile selected for thread 1 sequence 257 for destination LOG_ARCHIVE_DEST_2
Tue Jul 03 10:19:39 2018
opiodr aborting process unknown ospid (23762) as a result of ORA-609
Tue Jul 03 10:51:18 2018
ORA-00060: Deadlock detected. More info in file /u01/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_25846.trc.
Tue Jul 03 10:54:01 2018
ORA-00060: Deadlock detected. More info in file /u01/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_14067.trc.
Tue Jul 03 11:02:28 2018
ORA-00060: Deadlock detected. More info in file /u01/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_20781.trc.
Tue Jul 03 11:21:13 2018
Thread 1 cannot allocate new log, sequence 258
Private strand flush not complete

查看 trace 文件 orcl_ora_25846.trc 结果如下

Deadlock graph:
———Blocker(s)——– ———Waiter(s)———
Resource Name process session holds waits process session holds waits
TX-026e0020-000001a5 147 4468 X 385 241 S
TM-0007fd6c-00000000 385 241 X 147 4468 SX

session 4468: DID 0001-0093-000001FEsession 241: DID 0001-0181-00000014
session 241: DID 0001-0181-00000014session 4468: DID 0001-0093-000001FE

Rows waited on:
Session 4468: obj – rowid = 0007FD6C – AAAAAAAAAAAAAAAAAA
(dictionary objn – 523628, file – 0, block – 0, slot – 0)
Session 241: no row

—– Information for the OTHER waiting sessions —–
Session 241:
sid: 241 ser: 425 audsid: 24705000 user: 160/FD14
flags: (0x45) USR/- flags_idl: (0x1) BSY/-/-/-/-/-
flags2: (0x40009) -/-/INC
pid: 385 O/S info: user: oracle, term: UNKNOWN, ospid: 20781
image: oracle@dbserver1
client details:
O/S info: user: TL3050, term: TL3050-WZ, ospid: 5300:5348
machine: WORKGROUP\TL3050-WZ program: CWV4.2.8.337_20131204.exe
application name: CWV4.2.8.337_20131204.exe, hash value=580982453
current SQL:
insert into pzd2018
(UNI_NO,ORD,STYPE,STYPE2,SNO,SYEAR,SMONTH,RMONTH,SDAY,SABSTRACT,OPERATOR,J_AMOUNT,D_AMOUNT,SUBJ,SUBJNAME,
OPP_SUBJ,SRC_CODE,ECO_CODE,SRC_PAYTYPE,SRC_BUTYPE,ECO_TYPE,ECO_WARRANT,PRJ_ORDER,PRJ_NAME,OPP_PRJ,CLR_ORDER,
UNIT_CODE,SPECCODE,CONTRACT_NO,CAR_NO,OLPAY_SNO,schedule_date,WB_TYPE,WB_JNUM,WB_DNUM,WB_FACT,NUM_TYPE,
NUM_JNUM,NUM_DNUM,NUM_PRICE,CAP_NO,CAP_ORD,JSFS_CODE,ZPH,BUSS_DATE,OTHER_UNIT,ACNT,BANKNO,ADDRESS1,ADDRESS2,
TNO,ACT_NO,BU_CODE,T_CODE,RESBU_CODE,RESBU_AMT,SPECCODE1,SPECCODE2,SPECCODE3,SPECCODE4,RES_S1,
RES_S2,RES_S3,RES_S4,ASSET_SUBJ,TAX_NO,SRC_NAME,ADDITION,UNI_PRJ_ORDER,Clr_Bu_Code,
Source_Type,Source,SrKey,SMark,Uni_Prj_Name,clrsno,input_name,check_name,attach_act,
attach_act_no,pz_attr,src_type,zj_type,ref_uni_no,charge_sno,charge_name,src_lkx,order_type,c

—– End of information for the OTHER waiting sessions —–

Information for THIS session:

—– Current SQL Statement for this session (sql_id=9ktt36bsngnyx) —–
insert into pz2018
(UNI_NO,STYPE,STYPE2,SNO,SYEAR,SMONTH,RMONTH,SDAY,INPUT_NAME,CHECK_NAME,COMP_NAME,COMP_NAME2,
ADDITION,CHILDNUM,J_AMOUNT,D_AMOUNT,SSTATE,REMARK,PZ_ATTR)
values(:1,:2,:3,:4,:5,:6,:7,:8,:9,:10,:11,:12,:13,:14,:15,:16,:17,:18,:19)
===================================================

2、问题分析

可以看出来 241 号会话持有一个 TM 锁，在执行 insert into pzd2018 语句在等待 S 锁

4468 号会话持有一个 TX 锁，在执行 insert into pz2018 语句，在等待 SX 锁

通过与业务沟通与数据库查询发现了以下的锁表操作，并和业务确定了属于业务 SQL

lock table pz2018 in exclusive mode

到这里问题已经清楚了，整个逻辑是这样的

241 号会话将 pz2018 全表排他模式进行了锁定，导致 4468 会话无法对 pz2018 表进行 insert 操作，原因是无法在表上获取共享排它锁即 SX 锁，导致 4468 号会话进入等待模式

而 4468 号会话在等待前进行了 insert into pzd2018 操作，而 241 号会话在插入时存在唯一约束，导致 241 会话进行 TX 锁等待，等待 4468 号 session 数据提交或者回滚

这样一个环状等待就形成了即死锁

等待发生时会话的等待情况

SQL> select a.sample_time,
2 a.session_id,
3 a.session_serial#,
4 a.blocking_session bsession,
5 a.blocking_session_serial# bserial#,
6 a.event,
7 a.machine,
8 a.module,
9 a.sql_opname
10 from dba_hist_active_sess_history a
11 where a.session_id in (241, 4468, 6819, 10817)
12 and a.sample_time > to_date(‘2018070310’, ‘yyyymmddhh24’)
13 and a.sample_time < to_date(‘2018070312’, ‘yyyymmddhh24’)
14 and a.event is not null
15 order by a.sample_time
16 ;
SAMPLE_TIME SESSION_ID SESSION_SERIAL# BSESSION BSERIAL# EVENT MACHINE MODULE SQL_OPNAME
—————————— ———- ————— ———- ———- —————————— —————————— —————————— —————————————————————-
03- 7 月 -18 10.00.40.857 上午 241 425 6587 7875 enq: TM – contention WORKGROUP\TL3050-WZ CWV4.2.8.337_20131204.exe LOCK TABLE
03- 7 月 -18 10.49.45.384 上午 10817 97 12929 7665 read by other session webserver JDBC Thin Client SELECT
03- 7 月 -18 10.51.16.143 上午 241 425 4468 2029 enq: TX – row lock contention WORKGROUP\TL3050-WZ CWV4.2.8.337_20131204.exe INSERT
03- 7 月 -18 10.51.16.143 上午 4468 2029 241 425 enq: TM – contention ZDCW\WANGH88208561 XCV5（新 5.24）.exe INSERT
03- 7 月 -18 10.52.46.903 上午 10817 121 null event dbserver1 SELECT
03- 7 月 -18 10.53.57.464 上午 6819 99 10817 133 enq: TX – row lock contention ZDCW\WANGWD88981612 CWV4.exe INSERT
03- 7 月 -18 10.53.57.464 上午 10817 133 6819 99 enq: TM – contention ZDCW\WANGH88208561 XCV5（新 5.24）.exe INSERT
03- 7 月 -18 10.54.07.554 上午 10817 133 db file parallel read ZDCW\WANGH88208561 XCV5（新 5.24）.exe INSERT
8 rows selected

3、锁等待的模拟，问题复现

—session1
SQL> lock table pz2018 in exclusive mode;
Table(s) Locked.
—-session2
SQL> insert into pzd2018(OBJECT_ID,OBJECT_NAME) values(100000000,’PZD_Yong’);
1 row created.
SQL> insert into pz2018(OBJECT_ID,OBJECT_NAME) values(100000000,’PZ_Yong’);
—-session2 执行直接 hang 住无法完成，在等待 TM 锁
SQL> select s.SID,s.BLOCKING_SESSION bsid,s.EVENT,s.MACHINE,s.MODULE,s.STATUS,s.STATE from v$session s where s.EVENT is not null and s.STATUS=’ACTIVE’ and s.WAIT_CLASS<>’Idle’;
SID BSID EVENT MACHINE MODULE STATUS STATE
———- ———- —————————— —————————— —————————————- ——– ——————-
17 143 enq: TM – contention 172-16-8-110 SQL*Plus ACTIVE WAITING
—-session1 执行
SQL> insert into pzd2018(OBJECT_ID,OBJECT_NAME) values(100000000,’PZD_Yong’);
–session1 直接 hang 住，session2 抛出错误发现死锁
SQL> insert into pz2018(OBJECT_ID,OBJECT_NAME) values(100000000,’PZ_Yong’);
insert into pz2018(OBJECT_ID,OBJECT_NAME) values(100000000,’PZ_Yong’)
*
ERROR at line 1:
ORA-00060: deadlock detected while waiting for resource
—- 检查数据库等待
SQL> set linesize 1000 pagesize 5000
SQL> col EVENT for a30
SQL> col MACHINE for a30
SQL> col MODULE for a40
SQL> select s.SID,s.BLOCKING_SESSION bsid,s.EVENT,s.MACHINE,s.MODULE,s.STATUS,s.STATE from v$session s where s.EVENT is not null and s.STATUS=’ACTIVE’ and s.WAIT_CLASS<>’Idle’;
SID BSID EVENT MACHINE MODULE STATUS STATE
———- ———- —————————— —————————— —————————————- ——– ——————-
143 17 enq: TX – row lock contention 172-16-8-110 SQL*Plus

查看数据库 alert 日志发现

Thu Jul 05 11:40:40 2018
ORA-00060: Deadlock detected. More info in file /u01/app/oracle/diag/rdbms/dtstack1/dtstack1/trace/dtstack1_ora_29840.trc.

查看死锁 trace

Deadlock graph:
———Blocker(s)——– ———Waiter(s)———
Resource Name process session holds waits process session holds waits
TM-0001554c-00000000 28 17 X 27 143 SX
TX-00040008-000002d9 27 143 X 28 17 S

session 17: DID 0001-001C-00000024 session 143: DID 0001-001B-00000155
session 143: DID 0001-001B-00000155 session 17: DID 0001-001C-00000024

Rows waited on:
Session 17: no row
Session 143: obj – rowid = 0001554C – AAAAAAAAAAAAAAAAAA
(dictionary objn – 87372, file – 0, block – 0, slot – 0)

—– Information for the OTHER waiting sessions —–
Session 143:
sid: 143 ser: 905 audsid: 610017 user: 85/DTYONG
flags: (0x45) USR/- flags_idl: (0x1) BSY/-/-/-/-/-
flags2: (0x40009) -/-/INC
pid: 27 O/S info: user: oracle, term: UNKNOWN, ospid: 29846
image: oracle@172-16-8-110 (TNS V1-V3)
client details:
O/S info: user: oracle, term: pts/1, ospid: 29845
machine: 172-16-8-110 program: sqlplus@172-16-8-110 (TNS V1-V3)
application name: SQL*Plus, hash value=3669949024
current SQL:
insert into pz2018(OBJECT_ID,OBJECT_NAME) values(100000000,’PZ_Yong’)

—– End of information for the OTHER waiting sessions —–

Information for THIS session:

—– Current SQL Statement for this session (sql_id=7jbgf8fc4cac0) —–
insert into pzd2018(OBJECT_ID,OBJECT_NAME) values(100000000,’PZD_Yong’)
===================================================
PROCESS STATE
————-
Process global information:
process: 0x914c4ed0, call: 0x910d2008, xact: 0x90390710, curses: 0x916aa020, usrses: 0x916aa020
in_exception_handler: no
—————————————-
SO: 0x914c4ed0, type: 2, owner: (nil), flag: INIT/-/-/0x00 if: 0x3 c: 0x3
proc=0x914c4ed0, name=process, file=ksu.h LINE:12721, pg=0
(process) Oracle pid:28, ser:23, calls cur/top: 0x910d2008/0x910d2008
flags : (0x0) –
flags2: (0x0), flags3: (0x10)
intr error: 0, call error: 0, sess error: 0, txn error 0
intr queue: empty
ksudlp FALSE at location: 0
(post info) last post received: 138 0 2
last post received-location: ksl2.h LINE:2374 ID:kslpsr
last process to post me: 0x914b3298 1 6
last post sent: 0 0 26
last post sent-location: ksa2.h LINE:285 ID:ksasnd
last process posted by me: 0x914b3298 1 6
(latch info) wait_event=0 bits=0x0
Process Group: DEFAULT, pseudo proc: 0x915515e8
O/S info: user: oracle, term: UNKNOWN, ospid: 29840
OSD pid info: Unix process pid: 29840, image: oracle@172-16-8-110 (TNS V1-V3)
—————————————-
SO: 0x916aa020, type: 4, owner: 0x914c4ed0, flag: INIT/-/-/0x00 if: 0x3 c: 0x3
proc=0x914c4ed0, name=session, file=ksu.h LINE:12729, pg=0
(session) sid: 17 ser: 683 trans: 0x90390710, creator: 0x914c4ed0
flags: (0x45) USR/- flags_idl: (0x1) BSY/-/-/-/-/-
flags2: (0x40009) -/-/INC