ITPub博客

首页 > Linux操作系统 > Linux操作系统 > 转帖eygle:利用AWR报告解决paging space被撑爆的例子

转帖eygle:利用AWR报告解决paging space被撑爆的例子

原创 Linux操作系统 作者:mengzhaoliang 时间:2011-08-03 17:00:57 0 删除 编辑
曾经在ACOUG的第一次活动中提到----AWR报告里的每一项内容都值得我们认真研究,每一项内容都值得我们仔细关注

深以为然,但有时候在实际的解决问题的过程中,我们并不需要去关注AWR报告里的每一项内容,往往AWR报告里的一到两项内容就能够帮助我们迅速定位问题

我们来看一个仅仅利用AWR报告里的两项内容来定位并解决paging space被撑爆的例子。

 

整个事情的背景是这样的:

我们的一个库连续三天,基本上是在相同的时间,alert log里都报了这样的错:

1011晚上926分:

Mon Oct 11 21:26:48 2010

Process startup failed, error stack:

Mon Oct 11 21:26:48 2010

Errors in file /caipratrc/app/oracle/admin/ipraca/bdump/ipraca_psp0_74076.trc:

ORA-27300: OS system dependent operation:fork failed with status: 12

ORA-27301: OS failure message: Not enough space

ORA-27302: failure occurred at: skgpspawn3

 

1012晚上926分:

Tue Oct 12 21:26:41 2010

Process startup failed, error stack:

Tue Oct 12 21:26:41 2010

Errors in file /caipratrc/app/oracle/admin/ipraca/bdump/ipraca_psp0_74076.trc:

ORA-27300: OS system dependent operation:fork failed with status: 12

ORA-27301: OS failure message: Not enough space

ORA-27302: failure occurred at: skgpspawn3

 

1013晚上937分:

Wed Oct 13 21:37:39 2010

Process startup failed, error stack:

Wed Oct 13 21:37:39 2010

Errors in file /caipratrc/app/oracle/admin/ipraca/bdump/ipraca_psp0_74076.trc:

ORA-27300: OS system dependent operation:fork failed with status: 12

ORA-27301: OS failure message: Not enough space

ORA-27302: failure occurred at: skgpspawn3

 

刚好13号晚上937分的时候我在现场,当时我观察到的症状就是上述库所在的database server突然失去了响应,telnet已经连不上了。大概5分钟后又重新可以telnet,且此时变得一切正常,只是alert log里多了上述的错误记录。

 

好了,背景已经交待清楚,我们现在来开始定位问题和解决问题的过程:

MOS上文档Troubleshooting ORA-27300 ORA-27301 ORA-27302 errors [ID 579365.1]明确指出,当如下内容同时出现的时候,

ORA-27300: OS system dependent operation:fork failed with status: 12
ORA-27301: OS failure message: Not enough space
ORA-27302: failure occurred at: skgpspawn3 

即表明swap space已经耗尽了,其原话是这么说的:

** All related to swap space being depleted.  Check the OS system logs.  **

 

于是我们现在来检查OS system log

1011晚上928分:

LABEL:          PGSP_KILL

IDENTIFIER:     C5C09FFA

 

Date/Time:       Mon Oct 11 21:28:32 GMT+08:00 2010

Sequence Number: 245

Machine Id:      0001DA17D600

Node Id:         P570_04_LE

Class:           S

Type:            PERM

WPAR:            Global

Resource Name:   SYSVMM         

 

Description

SOFTWARE PROGRAM ABNORMALLY TERMINATED

 

Probable Causes

SYSTEM RUNNING OUT OF PAGING SPACE

 

Failure Causes

INSUFFICIENT PAGING SPACE DEFINED FOR THE SYSTEM

PROGRAM USING EXCESSIVE AMOUNT OF PAGING SPACE

 

        Recommended Actions

        DEFINE ADDITIONAL PAGING SPACE

        REDUCE PAGING SPACE REQUIREMENTS OF PROGRAM(S)

 

Detail Data

PROGRAM

oracle

USER'S PROCESS ID:

                291178

PROGRAM'S PAGING SPACE USE IN 1KB BLOCKS

     9873556

10121013OS system log与上述内容类似,在此不再赘述。

从上面内容中我们可以看出如下几点:

1、  确实是oracle的某个进程(进程号为291178)占用了大量的paging space,这里显示291178占用了9873556Kpaging space,即接近10G(上述库所在的database serverpaging space只有12G)。

2、  这个进程最后异常退出了----SOFTWARE PROGRAM ABNORMALLY TERMINATED

 

看到这里我们已经可以解释为什么上述库所在的database server在出现问题的时间段会短暂的失去响应,随后会恢复正常----因为oracle的某个process几乎耗尽了所有的paging space,而随着这个process的异常退出,其所占用的paging space得到了释放。

 

根据上述内容,我判断:

1、  就这个库而言,SGA大量占用paging space的可能性不大,因为buffer cacheshared pool都会有LRU算法来实现age out

2、  最有可能大量占用paging space的就是PGA,上述库的pga_aggregate_target1G

SQL> show parameter pga;

 

NAME                                 TYPE        VALUE

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

pga_aggregate_target                 big integer     1000M

这样,一旦某个server processsession cursor占用的内存超过1G,就会用到paging space了。

 

现在的问题是:

1、  这个process到底在做什么?为什么其会占用接近10Gpaging space

2、  为什么每次出现paging space耗尽错误的时间点基本上都相同?

这就需要借助AWR报告了。

 

基于上述判断,我认为只需要分别采集1011日、12日、13日三天的21点至22点的AWR报告就能印证我的上述判断并且能找到这个process当时到底在做什么。

因为上述process最后异常退出了,所以我们只需关注AWR报告里所有executions0的过程;验证是否是server processsession cursor占用了大量的paging space只需关注AWR报告里PGA的使用趋势。

 

101121点至22点的AWR报告中我们看到:

Elapsed Time (s)

CPU Time (s)

Executions

Elap per Exec (s)

% Total DB Time

SQL Text

1,315

183

0

 

12.78

Begin P_MCH_DAILY_JOB(:v0, :v...

1,238

170

5

247.62

12.03

delete from mchtkc where rowid...

612

41

1

612.20

5.95

Begin P_IWB_SALNOARRIVE(:v0, ...

499

14

1

498.56

4.85

select ipdprf, ipdfrm, ipdtk...

172

3

1

172.20

1.67

Begin P_SAL_SMARTRIX_SLT(:v0, ...

124

13

1

124.39

1.21

Begin P_COMMON_WORK_COUNT(:v0,...

87

1

1

87.26

0.85

call ORACLE_OCM.MGMT_CONFIG.co...

76

0

1

76.14

0.74

Begin P_IWB_AUTOASSIGN_COR(:v0...

 

 

PGA Aggr Target(M)

Auto PGA Target(M)

PGA Mem Alloc(M)

W/A PGA Used(M)

%PGA W/A Mem

%Auto W/A Mem

%Man W/A Mem

Global Mem Bound(K)

B

1,000

63

10,977.24

0.00

0.00

0.00

0.00

102,400

E

1,000

842

170.18

0.00

0.00

0.00

0.00

102,400

上述结果显示在101121点至22点唯一没有执行完的就是P_MCH_DAILY_JOB,在21点,上述库的PGA占用量是10977.24M(即10G),但到了22点,上述库的PGA占用量就变成了170.18M

 

1012日、101321点至22点的AWR报告中我们都看到了相类似的结果,在此不再赘述。

 

上述问题时间段的AWR报告有力的验证了我们的判断,而且,现在所有的矛头都指向了存储过程P_MCH_DAILY_JOB

 

我们现在来看看P_MCH_DAILY_JOB到底做了什么事情。

实际上,P_MCH_DAILY_JOB的逻辑是非常复杂的,但是非常幸运的是,出现问题的代码在这个存储过程的最开头。

 

首先我们注意到P_MCH_DAILY_JOB的定义部分定义了一个urowid的数组rids和一个数值型的变量n_index

--------------------------Begin MCHTKT 定义------------------------------

  type typ_mtkprf is table of mchtkt.mtkprf%type index by binary_integer;

  mtkprfs typ_mtkprf;

  type typ_mtkfrm is table of mchtkt.mtkfrm%type index by binary_integer;

  mtkfrms typ_mtkfrm;

  type typ_mtktkt is table of mchtkt.mtktkt%type index by binary_integer;

  mtktkts typ_mtktkt;

  type typ_mchtkt_rid is table of urowid index by binary_integer;

  mchtkt_rids typ_mchtkt_rid;

  cur_mchtkt sys_refcursor;

  vc_mchtkt_sql varchar2(4000) :=  'select mtkprf,mtkfrm,mtktkt,rowid

                                           from  mchtkt

                                           where mtkmts = :1';

  --------------------------End   MCHTKT 定义------------------------------

 

 --------------------------Begin MCHTKC 定义------------------------------

  type typ_mchtkc_rid is table of urowid index by binary_integer;

  mchtkc_rids typ_mchtkc_rid;

  type typ_rid is table of urowid index by binary_integer;

  rids typ_rid;

  n_index number;

  cur_mchtkc sys_refcursor;

  vc_mchtkc_sql varchar2(4000) :=  'select rowid from mchtkc where mtcprf = :1 and mtcfrm = :2 and mtctkt = :3';

  --------------------------End   MCHTKC 定义------------------------------

 

接着,在P_MCH_DAILY_JOB实际代码的最开始,出现了这样的代码:

----------Begin 删除mchtktTicket配比状态为'TF'的所有ticket记录及其相关联的mchtkc中的所有coupon记录-----------

  open cur_mchtkt for vc_mchtkt_sql using 'TF';

  loop

    fetch cur_mchtkt bulk collect into mtkprfs,mtkfrms,mtktkts,mchtkt_rids limit CN_BATCH_SIZE;

    for i in 1 .. mchtkt_rids.count loop

      open cur_mchtkc for vc_mchtkc_sql using mtkprfs(i),mtkfrms(i),mtktkts(i);

      fetch cur_mchtkc bulk collect into mchtkc_rids;

      close cur_mchtkc;

      for j in 1 .. mchtkc_rids.count loop

          n_index := n_index + 1;

          rids(n_index) := mchtkc_rids(j);

      end loop;

    end loop;

    forall i in 1 .. rids.count

      execute immediate 'delete from mchtkc where rowid = :1 ' using rids(i);

    forall i in 1 .. mchtkt_rids.count

      execute immediate 'delete from mchtkt where rowid = :1 ' using mchtkt_rids(i);

    exit when mchtkt_rids.count < CN_BATCH_SIZE;

 

    commit;

  end loop;

  close cur_mchtkt;

----------End   删除mchtktTicket配比状态为'TF'的所有ticket记录及其相关联的mchtkc中的所有coupon记录-----------

 

注意到上述代码犯了两个错误,其中的第一个错误是致命的:

1、没有在内层循环执行完毕后重置n_index的值,所以n_index的值会越来越大,同时数组rids也会越来越大,rids会大到什么程度呢?我们只需将其对应cursorsql执行一下就知道结果了:

SQL> select count(*) from mchtkt where mtkmts = 'TF';

 

  COUNT(*)

----------

   4365367

所以极限情况下rids会是一个包含436item的数组----这就解释了为什么会占用接近10Gpaging space

 

2、上述代码会接着执行删除mchtktmchtkc的对应记录的操作,其初衷是好的,采用了分步commit的方式----标准的处理海量数据的方法。但是其commit语句摆的地方不对,上述commit语句在exit when mchtkt_rids.count < CN_BATCH_SIZEend loop之间,这样这个commit只会在ridsitem到了4365367后才会执行,而还没等到执行这一步,paging space就被耗尽,执行上述P_MCH_DAILY_JOBserver process就会异常退出,于是oraclerollback之前做的delete操作,所以mchtkt的满足上述cursor条件的记录的数量在101110121013始终都会是4365367,就好像从来没有对mchtkt执行过delete操作一样,我们来验证一下:

SQL> select count(*) from mchtkt as of timestamp to_timestamp('2010-10-13 18:00:00','YYYY-MM-DD HH24:MI:SS') where mtkmts = 'TF';

 

  COUNT(*)

----------

   4365367

 

SQL> select count(*) from mchtkt as of timestamp to_timestamp('2010-10-12 18:00:00','YYYY-MM-DD HH24:MI:SS') where mtkmts = 'TF';

 

  COUNT(*)

----------

   4365367

 

SQL> select count(*) from mchtkt as of timestamp to_timestamp('2010-10-11 18:00:00','YYYY-MM-DD HH24:MI:SS') where mtkmts = 'TF';

 

  COUNT(*)

----------

   4365367

同时这也就解释了为什么每次出现paging space耗尽错误的时间点基本上都相同,因为P_MCH_DAILY_JOB是在一个大的每天都会执行的定时作业里,这几天P_MCH_DAILY_JOB的开始执行时间基本上都相同,又因为mchtkt的数据量始终都是4365367且上述有问题的代码是在存储过程P_MCH_DAILY_JOB实际执行代码的最开始。

 

分析清楚了原因,解决问题就变得非常简单了,只需把上述有问题的代码改成如下所示就可以了:

open cur_mchtkt for vc_mchtkt_sql using 'TF';

  loop

    fetch cur_mchtkt bulk collect into mtkprfs,mtkfrms,mtktkts,mchtkt_rids limit CN_BATCH_SIZE;

    for i in 1 .. mchtkt_rids.count loop

      open cur_mchtkc for vc_mchtkc_sql using mtkprfs(i),mtkfrms(i),mtktkts(i);

      fetch cur_mchtkc bulk collect into mchtkc_rids;

      close cur_mchtkc;

      for j in 1 .. mchtkc_rids.count loop

          n_index := n_index + 1;

          rids(n_index) := mchtkc_rids(j);

      end loop;

    end loop;

    forall i in 1 .. n_index

      execute immediate 'delete from mchtkc where rowid = :1 ' using rids(i);

    forall i in 1 .. mchtkt_rids.count

      execute immediate 'delete from mchtkt where rowid = :1 ' using mchtkt_rids(i);

    commit;

   

    n_index := 0;   

   

    exit when mchtkt_rids.count < CN_BATCH_SIZE;

  end loop;

  close cur_mchtkt;

 

我在1014日修改完上述代码,今天早上我来看上述库的alert log,上述错误不再重现,即这个问题已经被我成功解决。

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

请登录后发表评论 登录
全部评论
暂无介绍

注册时间:2008-01-30

  • 博文量
    335
  • 访问量
    2938483