宕机 定位sql

running

环境 ：solaris 11  oracle 10.2.0.4 单节点
db的一些参数：

SQL> show parameter sga

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
lock_sga                             boolean     FALSE
pre_page_sga                         boolean     FALSE
sga_max_size                         big integer 20000M
sga_target                           big integer 20000M

故障现象：cpu 100% 业务前台无响应
诊断：定位直接导致故障的sql

分析：
现有两份分析，见下文
（1）
2012-7-30日下午5点左右，4A系统出现故障，是由于oracle所在主机资源耗尽导致

经过对oracle数据库检查，从AWR中发现引发资源枯竭的是一条select语句，AWR报告在附件中



SQL如下:
select * from sddtech.sdd_AUDIT_AUDITEVENT_HIST  where    BUSINESSID = 119000;

该表有1.3TB左右，且该SQL的执行计划为全表扫描，以下是执行计划:
SQL> select sum(bytes)/1024/1024/1024 from dba_segments a where

  2    a.segment_name='sdd_AUDIT_AUDITEVENT_HIST';

SUM(BYTES)/1024/1024/1024
-------------------------
               1341.99512            <=========表大小1.3约合tb

SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 881769535

-------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation            | Name                        | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |    TQ  |IN-OUT| PQ Distrib |
-------------------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |                             |    87M|    26G|  2588K  (1)| 08:37:47 |       |       |        |      |            |
|   1 |  PX COORDINATOR      |                             |       |       |            |          |       |       |        |      |            |
|   2 |   PX SEND QC (RANDOM)| :TQ10000                    |    87M|    26G|  2588K  (1)| 08:37:47 |       |       |  Q1,00 | P->S | QC (RAND)  |
|   3 |    PX BLOCK ITERATOR |                             |    87M|    26G|  2588K  (1)| 08:37:47 |     1 |   730 |  Q1,00 | PCWC |            |
|*  4 |     TABLE ACCESS FULL| sdd_AUDIT_AUDITEVENT_HIST |    87M|    26G|  2588K  (1)| 08:37:47 |     1 |   730 |  Q1,00 | PCWP |            |
-------------------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   4 - filter("BUSINESSID"=119000)

16 rows selected.


经分析，发现该表上只有一条联合索引
(TIME, ID, AUDITLEVEL, TYPE, BUSINESSID, SRCIP, DESTIP);

而select语句如果想用到该索引，则select语句后必须带有TIME字段，而引发问题的select的where条件显然并不具备走索引扫描的条件。。。
所以，这个sql就是导致 cpu 100% ,从而导致系统宕机的；

running

分析 2：
首先，定位sql的问题：
      (1)从故障时间段的awr报告中看出，当前等待的top events：为 cursor: pin S，而不是使用全表扫描的方式
          通常会导致的db file scattered read 事件。
          应该在系统中查询和等待事件cursor: pin S的会话，这样定位的sql才是准确的。
     
     另外，在高并发的情况下，类似下面的全表扫描的sql 导致cpu 使用过高，
     导致系统无响应，甚至宕机的情况，也是很通常的案例：
     select * from sddtech.sdd_AUDIT_AUDITEVENT_HIST where BUSINESSID = 119000 ；              
          但是这个长时间使用full table 方式 扫描的 sql 是和db file scattered read 事件相关的，是否与
          cursor: pin S 等待事件相关，需要在现有的系统中结合跟踪文件等信息再深入定位才能确认。
          另外，从awr报告看，系统中 执行次数较多、和解析次数较多的下面中的sql 和这次故障也是应该有关系的：
          SQL ordered by Executions
          SQL ordered by Parse Calls

          select t.userid from sdd_sys_login_user t where t.userid=:1
          update  sdd_sys_login_user t set t.lastreqtime=sysdate where t.userid=:1   
         
          系统优化的过程中，也需要关注这两个sql 相关的表 sdd_sys_login_user 的索引的使用情况；

     我的疑问就是：
   
                通过这个awr报告能断定select * from sddtech.sdd_AUDIT_AUDITEVENT_HIST where BUSINESSID = 119000；
                就是导致cpu 100% 实例无响应的sql吗？还需要其它的日志或手段辅助分析吗？

                      谢谢 盼回复。

gtlions

坐等高手出手指点学习下

KFC

把当时的后台alert文件也上传，在那个时间点的前后

realkid4

谈谈自己的几个想法：

1、两个对User登录和操作的表，虽然都是比较简单，而且我也相信执行计划还可以接受（因为每次执行速度还可以）。但是一个小时内执行了10几万和20几万，是不是值得怀疑。你的系统虽然那个Select没有执行结束，但是你的redo量是很高的，这里是不是优化的空间。

      建议你去和开发沟通一下，看看这两个SQL是做什么的。看看有没有应用层面的原因。觉得并发量是不是有点太高了，作为登录。

2、那个关键SQL，虽然查询语句出现在索引的非前缀索引位置，但是还是index skip scan操作可以用到的。而且SQL不走索引的原因很多。

     建议可以按照如下顺序考虑一下：1、统计量问题 2、那么大的表，可否有其他的处理方式，如分区或者并行处理 3、如果确定你的这个SQL是关键SQL，而且会融合到应用中（目前你是用PL/SQL Developer），可以考虑索引列顺序调整一下。

虽然我不能最后告诉你100%的原因是否这些，但是优化的过程是一个不断迭代的过程，将两个问题解了，相信有一个新的状态情况。

Maclean Liu(刘相兵

回答：

2        10,667        0                 74.86        6rv4b15qkgp8d         PL/SQL Developer        select * from sddtech.sdd_...
select * from sddtech.sdd_AUDIT_AUDITEVENT_HIST where BUSINESSID = 119000

就AWR看 以上语句消耗了 较多的物理读， 但是其消耗的逻辑读并不多：

Segments by Logical Reads
Total Logical Reads: 102,955,393
Captured Segments account for 97.4% of Total
Owner        Tablespace Name        Object Name        Subobject Name        Obj. Type        Logical Reads        %Total
sddTECH        sddTECH        sdd_ACC_MASTER                 TABLE        33,550,064        32.59
sddTECH        sddTECH        LOGIN_USER                 TABLE        33,028,768        32.08
sddTECH        sddTECH        sdd_ACC_SLAVE                 TABLE        19,780,816        19.21
sddTECH        sddTECH        sdd_AUTH_MASTERAUTH                 TABLE        7,305,840        7.10
sddTECH        AUDIT_TABLES_07        sdd_AUDIT_AUDITEVENT_HIST        P20120729        TABLE PARTITION        1,330,864        1.29


最主要的问题在于 cursor: pin S和 cursor: pin S wait on X的解析类等待事件

而非全表扫描

Event        Waits        Time(s)        Avg Wait(ms)        % Total Call Time        Wait Class
cursor: pin S         94,363,996         199,268         2         1,398.5        Other
PX Deq Credit: send blkd         5,633         10,594         1,881         74.4        Other
CPU time                  2,395                  16.8         
cursor: pin S wait on X         119,532         2,343         20         16.4        Concurrency




SGA breakdown difference
ordered by Pool, Name
N/A value for Begin MB or End MB indicates the size of that Pool/Name was insignificant, or zero in that snapshot
Pool        Name        Begin MB        End MB        % Diff
java        free memory        45.44        45.44        0.00
java        joxlod exec hp        17.34        17.34        0.00
java        joxs heap        1.22        1.22        0.00
large        PX msg pool        1.03        1.03        0.00
large        free memory        14.97        14.97        0.00
shared        CCursor        433.98        318.61        -26.58
shared        Cursor Stats        50.32        50.32        0.00
shared        KGH: NO ACCESS        117.85        117.85        0.00
shared        PCursor        337.62        298.30        -11.65
shared        free memory        1,101.54        2,049.04        86.02
shared        kglsim object batch        74.00        74.00        0.00
shared        library cache        246.27        224.44        -8.86
shared        sql area        2,388.45        1,620.50        -32.15
        buffer_cache        14,832.00        14,832.00        0.00
        fixed_sga        2.08        2.08        0.00
        log_buffer        4.13        4.13        0.00


shared pool在此过程中发生过大的抖动， 可以看到 free memory 从 1,101.54        涨到 2,049.04

建议你上传问题时段的ASH 报告 进一步分析

当可以确认的是 引发问题的直接原因不是全表扫描

chen28

应该是1.3 G吧!

yobyin

楼上的数学不太好，，等刘解释

Maclean Liu(刘相兵

sum(bytes)/1024/1024/1024   单位是  GB

   1341GB 约等于1.3TB