案例背景

环境：现场WAS 8.5集群+oracle 问题描述：现场反馈系统响应缓慢，业务无法开展。

分析过程

查看现场应用服务器的JVM、线程池、连接池和硬件情况，各项资源指标正常，压力不大。

查看数据库服务器的硬件资源使用率，也没有明显的异常，CPU使用率在10%以内，IO也比较低。现场数据库服务器的配置较高，有64核256G内存，理论上不会那么容易发生硬件瓶颈。

接着生成4.2号早上8点~12点的AWR报告，发现以下异常情况：

DB Time/Elapsed 比值高达30，不正常。

Parse CPU to Parse Elaped 反应了 总的Parse 时间中 CPU占的比例， 为什么 parse 使用的Cpu time占这么小的比例？

有大量的异常等待事件，包括包括表锁争用、行锁争用等等一大堆，说明这个时间段内的数据库响应极度不正常。

上图很普通的一句根据索引update表的语句，执行时间却需要1000秒，也是极不正常。

SQL如下:

update ms_ma_sale_detail set MODIFY_TIME = to_date('2016-04-02 12:28:18', 'yyyy-mm-dd hh24:mi:ss'), SEND_STATE = '0' , store_qty=store_qty+324.0 where sale_detail_id='8a48ccff53d78c780153d7cd338917d6'

但是在CPU Time统计里面，却没有这条SQL的影子，说明引起这个SQL执行速度慢的原因，并不是因为CPU忙不过来。

缓冲池读里面有句SQL存在明显的缓冲池读问题，每次查询需要读取约800万次。但是，也没有update ms_ma_sale_detail这句SQL的影子，说明这句update SQL不存在高缓冲池读的问题。

接着，检查ms_ma_sale_detail表是否缺少主键，该表大约有200万的数据量，检查结果未发现缺少主键。

再来，怀疑ms_ma_sale_detail的表和索引信息失效，于是尝试更新统计信息，发出命令：

analyze table MS_MA_SALE_DETAIL compute statistics;

发出命令后，执行了将近10分钟，仍然未更新完成。   于是中止掉，改用以下命令：

exec dbms_stats.gather_table_stats('tso',' MS_MA_SALE_DETAIL ',granularity=> 'ALL',cascade=>true);

但是，10分钟过去了，仍然未更新完成。

此时现场反馈部分业务可以操作了，不过部分业务仍处于瘫痪状态。   趁着数据库还在刷新MS_MA_SALE_DETAIL表统计信息的空档，回头想了一下TOP 5 事件，同时出现这么多的异常明显是不正常的，说明数据库可能经历了某种资源极度短缺，所有的请求都极度缓慢的状态。根据以往经验，这可能跟数据库的缓冲池或者内存有关。   于是，打开服务器的TOP 窗口，观察了1分钟左右，发现有个进程的单核CPU使用率始终达到100%，而内存占用量达到10G，跟踪该进程正在执行的SQL，发现这个进程正在执行一条非常长的统计SQL，该SQL有800行之长，而且这条SQL在AWR报告中并没有体现。

将这条SQL发给开发人员确认，告知是新加的一张报表SQL，此报表的特点是列是动态的，有多少种物资就有多少个列，这也是这个SQL为什么会这么长的原因。

跟开发和现场人员确认后，决定杀掉这个会话试试。发出以下命令：

alter system kill session '14,4820';

但是无济于事，该会话仅被标注为要被杀掉，但实际上还在运行，会话仍然存在。于是改成从os级杀掉该进程，在反复查询该进程仍然处于查询状态，并且进程不属于ORACLE后台进程的情况下，采用kill -9 pid强制结束了这个进程。   接下来，现场反馈系统恢复正常了，之前的MS_MA_SALE_DETAIL表的统计也能较快完成了。

一切似乎恢复了平静。

解决问题

接下来几天，系统运行都挺稳定的，于是决定抽点时间再来回顾这次灾难。

这次，运用了一点新式装备，dba_hist_active_sess_history，因此得以更加深入地分析上次灾难的前因后果。   注：由于过去的时间有点久了，因此V$SESSION和v$active_session_history视图可能已经不存在当时的会话信息了，因此考虑从DBA_HIST_*类的视图入手，这些视图默认保存8天左右。

首先，从TOP 5事件中的NO.1 library cache lock入手。

**查询快照区间library cache lock事件的所有会话

SELECT *
FROM dba_hist_active_sess_history x
WHERE event = 'library cache lock' AND SNAP_ID >= 2321 AND SNAP_ID <= 2325
ORDER BY SAMPLE_TIME;

查询结果显示，从上午10点开始，数据库中就有大量的会话出现了大量的library cache lock事件，执行的SQL还都是不一样的。

**查询被阻塞会话的数量

SELECT blocking_session,x.blocking_session_serial#,count(1)
FROM dba_hist_active_sess_history x
where  event = 'library cache lock' and SNAP_ID >=2321 AND SNAP_ID<=2325 
group by blocking_session,x.blocking_session_serial#;

查询结果显示有3个会话堵塞的最多。（这个视图是每秒取样一次，因此数据会有重复，实际上没这么多）。

跟踪1153会话在4.2号8点之后的会话数据**

select sample_time,sql_id,sql_opname,wait_class,wait_time,session_state,blocking_session_status 
from dba_hist_active_sess_history
where session_id = '1153' and SESSION_SERIAL#= '47653' 
AND SAMPLE_TIME BETWEEN  to_date('2016-04-02 08:00:00','yyyy-mm-dd hh24:mi:ss') and   to_date('2016-04-02 17:00:00','yyyy-mm-dd hh24:mi:ss');

结果显示1153会话从早上10:08分开发就在执行某个SQL，直到下午3点左右。并且该会话没有被阻塞，是一直在查询中的。   查询该SQL_ID对应的sql语句，发现就是当天我们强制杀掉的那条很长的查询统计SQL。

莫非是这条SQL性能有严重问题，阻塞了其他SQL的执行？

继续跟踪868会话在4.2号8点之后的会话数据**

SELECT sample_time
    , sql_id
    , sql_opname
    , wait_class
    , wait_time
    , wait_class_id
    , session_state
    , blocking_session_status
    , BLOCKING_SESSION
    , BLOCKING_SESSION_SERIAL#
FROM dba_hist_active_sess_history
WHERE session_id = '868' AND SESSION_SERIAL# = '46427' 
AND SAMPLE_TIME BETWEEN to_date ('2016-04-02 08:00:00', 'yyyy-mm-dd hh24:mi:ss') AND to_date ('2016-04-02 17:00:00', 'yyyy-mm-dd hh24:mi:ss')
ORDER BY SAMPLE_TIME;

查询结果显示这个会话从早上11:29分左右开始执行创建索引的操作，到11:45分左右完成。并且该会话是被阻塞的。

递归跟踪阻塞会话**

SELECT blocking_session,x.blocking_session_serial#,count(1)
FROM dba_hist_active_sess_history x
where  session_id = '868' and SESSION_SERIAL#= '46427' and SNAP_ID >=2321 AND SNAP_ID<=2325 
group by blocking_session,x.blocking_session_serial#;

发现阻塞868会话进行的，也是1153这个会话。 同样，追踪其它会话，最终的会话阻塞都指向1153这个会话。   同样，跟踪cursor: pin S wait on X、enq: TM – contention、enq: TX - row lock contention的异常会话，最终的会话阻塞都指向1153这个会话。   这真是一条SQL搞垮一个数据库的惨案啊。

总结

  1. 导致数据库几乎宕机的SQL，在AWR报告中不一定能看到，TOP 也是很有用的；
  2. 在追查历史问题上，DBA_HIST_*类的视图能够提供很好的帮助作用；