大事务回滚导致系统故障案例一则

转载

mb646da62f0d7e4 2023-05-24 14:35:37

文章标签 concurrency sql system insert iterator 文章分类 Python 后端开发

作者： eygle | English Version

最近遇到的一则案例，客户系统响应缓慢，IO Wait超高，系统体现在Log file sync上出现大量等待，磁盘没有错误信息。

我的第一印象就是，可能有大事务在回滚，通过如下查询立刻找到了数据库中存在的一个

SQL> select distinct KTUXECFL,count(*) from x$ktuxe group by KTUXECFL; 
 
 KTUXECFL                   COUNT(*) 
 
 ------------------------ ---------- 
 
 DEAD                              1 
 
 NONE                           7969

首先这个死事务是极其可以的，具体查看其信息，发现其回退的极其缓慢：

SQL> select ADDR,KTUXEUSN,KTUXESLT,KTUXESQN,KTUXESIZ 
 
   2  from x$ktuxe where KTUXECFL='DEAD'; 
 

 ADDR       KTUXEUSN   KTUXESLT   KTUXESQN   KTUXESIZ 
 
 -------- ---------- ---------- ---------- ---------- 
 
 B7FCBB98         37          1       4915     158026 
 

 SQL> / 
 

 ADDR       KTUXEUSN   KTUXESLT   KTUXESQN   KTUXESIZ 
 
 -------- ---------- ---------- ---------- ---------- 
 
 B7FCBB98         37          1       4915     158026 
 

 SQL> select ADDR,KTUXEUSN,KTUXESLT,KTUXESQN,KTUXESIZ from x$ktuxe where KTUXECFL='DEAD'; 
 

 ADDR       KTUXEUSN   KTUXESLT   KTUXESQN   KTUXESIZ 
 
 -------- ---------- ---------- ---------- ---------- 
 
 B7FCBB98         37          1       4915     157966

按照这个进度，可能需要几天去回滚这个失败的事务，最后客户选择了激活备库，放弃主库来恢复生产。

最后通过AWR数据找到了这个导致大事务的SQL，其逻辑读超高，执行未能成功完成：

Stat Name	Statement Total	Per Execution	% Snap Total
Elapsed Time (ms)	12,233,407	12,233,407.37	0.42
CPU Time (ms)	274,181	274,180.53	0.20
Executions	1
Buffer Gets	46,723,423	46,723,423.00	0.99
Disk Reads	1,223,947	1,223,947.00	1.81
Parse Calls	1	1.00	0.00
Rows	0	0.00
User I/O Wait Time (ms)	11,965,756
Cluster Wait Time (ms)	0
Application Wait Time (ms)	0
Concurrency Wait Time (ms)	0
Invalidations	0
Version Count	5
Sharable Mem(KB)	87

根据执行计划，这个INSERT操作可能访问高达13M的记录，其回滚的效率可想而知，而且Oracle的并行回退效率并不高。

Execution Plan

Id	Operation	Name	Rows	Bytes	Cost (%CPU)	Time	Pstart	Pstop
0	INSERT STATEMENT				603K(100)
1	FILTER
2	PARTITION RANGE ITERATOR		1800K	111M	603K (1)	02:00:42	KEY	KEY
3	TABLE ACCESS BY LOCAL INDEX ROWID	TAB_LOG_CB2	1800K	111M	603K (1)	02:00:42	KEY	KEY
4	INDEX RANGE SCAN	IDX_CB2_DA	13M		36095 (1)	00:07:14	KEY	KEY