ITPub博客

首页 > Linux操作系统 > Linux操作系统 > 生产库故障分析(主外键和DML性能分析)

生产库故障分析(主外键和DML性能分析)

原创 Linux操作系统 作者:gaopengtttt 时间:2009-06-19 15:31:10 0 删除 编辑

原创 转载请注明出处

(我的学习笔记)   

公司生产库20090618,出现批处理(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,报告截图如下

WORKLOAD REPOSITORY report for

DB Name

DB Id

Instance

Inst num

Release

RAC

Host

GELCPRO

4091276223

GELCPRO

1

10.2.0.1.0

NO

D0-LNXDB01

 

 

Snap Id

Snap Time

Sessions

Cursors/Session

Begin Snap:

26795

18-Jun-09 15:00:32

46

11.3

End Snap:

26796

18-Jun-09 16:00:56

45

6.8

Elapsed:

 

60.40 (mins)

 

 

DB Time:

 

63.25 (mins)

 

 

 

Top 5 Timed Events

Event

Waits

Time(s)

Avg Wait(ms)

% Total Call Time

Wait Class

CPU time

 

3,733

 

98.4

 

ARCH wait on SENDREQ

502

934

1,861

24.6

Network

log file parallel write

8,365

107

13

2.8

System I/O

log file sync

4,470

62

14

1.6

Commit

control file parallel write

2,717

17

6

.4

System I/O

 

可以看到数据库的负载是比较重的,而且问题出现时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

Elapsed Time (s)

CPU Time (s)

Executions

Elap per Exec (s)

% Total DB Time

SQL Id

SQL Module

SQL Text

1,788

1,785

121

14.78

47.11

0sf192fw73ds9

 

DECLARE job BINARY_INTEGER := ...

1,780

1,779

1

1779.55

46.89

7s2s60d6c6tk7

 

begin pkg_ls_chl_com.p_backgro...

1,279

1,279

1

1279.34

33.71

cw1bax526a9am

 

DELETE T_COMMISION_INFO CI WHE...

1,137

1,125

114,068

0.01

29.95

3t3c1ju68qvkc

 

select /*+ all_rows */ count(...

 

 

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

CPU Time (s)

Elapsed Time (s)

Executions

CPU per Exec (s)

% Total DB Time

SQL Id

SQL Module

SQL Text

1,785

1,788

121

14.75

47.11

0sf192fw73ds9

 

DECLARE job BINARY_INTEGER := ...

1,779

1,780

1

1778.72

46.89

7s2s60d6c6tk7

 

begin pkg_ls_chl_com.p_backgro...

1,279

1,279

1

1279.08

33.71

cw1bax526a9am

 

DELETE T_COMMISION_INFO CI WHE...

1,125

1,137

114,068

0.01

29.95

3t3c1ju68qvkc

 

select /*+ all_rows */ count(...

 

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

 

 

1DECLARE 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;

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

3DELETE T_COMMISION_INFO CI WHERE CI.AGGREGATION_ID = :B1

4select /*+ 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_INFOAWRRPT中并没有设计到,可以确定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那小小的问题将会被放大很多。。。

来自 “ ITPUB博客 ” ,链接:http://blog.itpub.net/7728585/viewspace-606955/,如需转载,请注明出处,否则将追究法律责任。

请登录后发表评论 登录
全部评论
wxh gp_22389860

注册时间:2008-10-13

  • 博文量
    650
  • 访问量
    2874374