生产库故障分析（主外键和DML性能分析）

原创 转载请注明出处

（我的学习笔记）   

公司生产库2009年06月18日，出现批处理(JOB)阻塞了大量的用户操作，具体表现就是大量的表备锁做，并且CPU资源消耗达到了60%，让整个系统变慢，此时间长达30分钟。

出现问题后，我首先查看了系统使用有大事物的存在：

select username,opname,

round(((totalwork-sofar)/totalwork),4)*100 "pct_remaining"

from V$session_Longops

WHERE TIME_REMAINING >0;

看到有大的的FULL SCAN 也就是全表扫描存在，当然这样也看不出来问题的所在，然后进行了4点到5点的AWRRPT，报告截图如下

Top 5 Timed Events

可以看到数据库的负载是比较重的，而且问题出现时CPU大量消耗，感觉有CPU密集型的语句正在运行

然后查看TOP CPU SQL，和TOP time sql

SQL ordered by Elapsed Time

• Resources reported for PL/SQL code includes the resources used by all SQL statements called by the code.
• % Total DB Time is the Elapsed Time of the SQL statement divided into the Total Database Time multiplied by 100

SQL ordered by CPU Time

• Resources reported for PL/SQL code includes the resources used by all SQL statements called by the code.
• % Total DB Time is the Elapsed Time of the SQL statement divided into the Total Database Time multiplied by 100

根据报告可以确定问题语句的大概范围。

1、DECLARE job BINARY_INTEGER := :job; next_date DATE := :mydate; broken BOOLEAN := FALSE; BEGIN pkg_life_public_back_process.p_run(2, 2); :mydate := next_date; IF broken THEN :b := 1; ELSE :b := 0; END IF; END;

2、begin pkg_ls_chl_com.p_background_cal_commision(:1, :2, :3); end;

3、DELETE T_COMMISION_INFO CI WHERE CI.AGGREGATION_ID = :B1

4、select /*+ all_rows */ count(1) from "GELC_PROD"."T_COMMISSION_FEE" where "COMMISION_ID" = :1

其实前面两个语句也许不是问题的重点，然后通过日志挖掘挖掘日志4点到5点的时候日志切换最频繁的时候时间大概在5分钟以内切换的3个日志，发现出现了大量的DML语句，主要集中在两个表上

select seg_name,count(seg_name) count from v$logmnr_contents group by seg_name order by  count;

SEG_NAME                         COUNT

---------------------------------------

T_STAND_PREM_DETAIL              2028

T_SESSION_TRACE                  2096

SEQ$                             11245

T_PERFORMANCE_INFO               109267

T_COMMISION_INFO                 157757

AUD$                             249216

这里给出了最后6行，而AUD$是审计表，T_PERFORMANCE_INFO在AWRRPT中并没有设计到，可以确定T_PERFORMANCE_INFO虽然DML次数多但是没有引起性能问题，剩下的就是T_COMMISION_INFO了，进一步查看：

SQL> select substrb(sql_redo,1,50) su,count(substrb(sql_redo,1,50)) te from v$logmnr_contents where SEG_NAME='T_COMMISION_INFO'

  2  group by substrb(sql_redo,1,50) order by te ;

SU                                                         TE

-------------------------------------------------- ----------

update "GELC_PROD"."T_COMMISION_INFO" set "COMM_ST       4609

delete from "GELC_PROD"."T_COMMISION_INFO" where "         14503

update "GELC_PROD"."T_COMMISION_INFO" set "MONEY"       23081

Unsupported                                                 25651

insert into "GELC_PROD"."T_COMMISION_INFO"("COMMIS      89913

这里出现了AWRRPT中指出的语句delete from "GELC_PROD"."T_COMMISION_INFO" where "，所以我确定真正的性能问题出在这里，因为日志挖掘和AWRRPT同时出现这样的语句。

进一步分析发现T_COMMISION_INFO表的数据量是比较大了10W以上，当然这里我觉得也不是问题所在，单一的一张表进行DELETE也不会出现如此的等待，然后我想可能是此表中的主键关联了大量的子表，在进行删除的时候，每一条记录中的主键都会去匹配子表，如果主表中的记录在子表中有引用，就会报错，如果没有引用才能被删除，这样如果子表的外键中不存在相应的索引就会进行全表扫描，引起大量的等待，而且会锁住子表，最初看到的多个表被锁住，也许就是这样引起的，当然如果一切成立最初看到的大事物的全表扫描，也是因为子表的全表扫描引起的。

通过语句

select CONSTRAINT_NAME,TABLE_NAME from dba_constraints where CONSTRAINT_TYPE='R' AND R_CONSTRAINT_NAME='PK_T_COMMISION_INFO';

发现了确实有6张表都引用了此表中的主键，这样没删除一条数据就会去全表扫描这6张表，

T_COMMISSION_FEE   

T_COUNT_DEPT_AWARD

T_PRODUCT_COMMISION

T_COMMISION_DETAIL

T_ADJUST_AWARD

T_REMAIN_COMM   

其中T_COMMISSION_FEE 有10w多条数据

T_PRODUCT_COMMISION 有3W多条数据

为了证明问题确实出在这里，在开发环境中我也做了试验，在T_COMMISSION_FEE插入了4W多条数据，然后开启SQL_TRACE后，用TKPROF进行格式化查看，

我使用的语句是

delete gelcdev216.T_COMMISION_INFO where COMMISION_ID>50000;

虽然这条语句报错了但是丝毫没有引向结果。

当T_COMMISSION_FEE 中 COMMISION_ID没有加索引的情况下，这条语句重启动到失败共耗时8秒，

并且TKPROF报告看到了这样的情况

select /*+ all_rows */ count(1)

from

 "GELCDEV216"."T_COMMISSION_FEE" where "COMMISION_ID" = :1

call     count       cpu    elapsed       disk      query    current        rows

------- ------  -------- ---------- ---------- ---------- ----------  ----------

Parse        1      0.00       0.00          0          0          0           0

Execute   1274      0.02       0.03          0          0          0           0

Fetch     1274      7.91       7.75          0     718536          0        1274

------- ------  -------- ---------- ---------- ---------- ----------  ----------

total     2549      7.94       7.79          0     718536          0        1274

这个消耗是比较严重的，而且我只是做的其中很小的一部分，而且

select /*+ all_rows */ count(1)  from "GELCDEV216"."T_COMMISSION_FEE" where "COMMISION_ID" = :1

正是在AWRRPT中出现的

select /*+ all_rows */ count(1) from "GELC_PROD"."T_COMMISSION_FEE" where "COMMISION_ID" = :1

就是因为大量的进行一致性验证而导致的语句，当然起初看到的全表扫描也是对子表的全表扫描，况且大量的锁出现部分也是由于这里的问题。

当我在T_COMMISSION_FEE 中 COMMISION_ID建立索引过后运行同样的语句

delete gelcdev216.T_COMMISION_INFO where COMMISION_ID>50000;

时间只是0.5秒，而且在TKPROF中也不会出现相应扫描子表的语句，因为现在会去扫描新建的索引。

所以我觉得解决这个问题的方法就是在相应的数据较大的子表中建立索引，避免出现全表扫描，也不会去锁表，因为现在扫描的仅仅是索引中的块而已。方法及如下：

CREATE  INDEX  ****  ON T_COMMISSION_FEE(COMMISION_ID);

CREATE  INDEX  ****  ON T_PRODUCT_COMMISION(COMMISION_ID);

也许一条DELETE不会引起性能问题，但是如果进行批量的DELETE那小小的问题将会被放大很多。。。