ITPub博客

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

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

原创 Linux操作系统 作者:fengjin821 时间:2009-06-20 21:10:23 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_FEE10w多条数据

T_PRODUCT_COMMISION3W多条数据

 

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

 

 

我使用的语句是

 

delete gelcdev216.T_COMMISION_INFO where COMMISION_ID>50000;

 

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

    当T_COMMISSION_FEECOMMISION_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_FEECOMMISION_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那小小的问题将会被放大很多。。。

 

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

 

       1) 不知道你说的问题是不是经典的锁等待问题,通过外键加索引解决,很
 
多时候发现,是查询影响的性能,而索引就是解决这种问题的方法,尤其是
 
数据量上W级时与很多字表关联

 

     2) 我觉得有外健的表,根据外健建立是索引是必要的,因为现在很多程

都是多线程对表进行操作的,虽然加了索引会对相对的插入,更新,删除

一点时间上的消耗,但是对于防止锁表,以及死锁的发生,和提高查询速

度,防止全表扫描是比较有好处的。
       

    虽然很多时间我们能帮研发调整大量sql的性能,不过只通过调整语句的

写法,索引调整,表的调整和分析,优化器的选择,相关参数的调整等都是

一种针对问题的补救措施,系统架构上设计的差异给我们带来大量的工作,

有时我也希望设计架构的人员自己来维护一下他自己设计的系统,感受一

下,可惜实现不了
 

 

 

 

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

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

注册时间:2009-04-29

  • 博文量
    191
  • 访问量
    508980