案例背景
环境：现场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视图可能已经不存在当时的会话信息了，因此考虑从DBAHIST*类的视图入手，这些视图默认保存8天左右。
首先，从TOP 5事件中的NO.1 library cache lock入手。
**查询快照区间library cache lock事件的所有会话
复制
SELECT *FROM dba_hist_active_sess_history xWHERE event = 'library cache lock' AND SNAP_ID >= 2321 AND SNAP_ID <= 2325ORDER BY SAMPLE_TIME;
查询结果显示，从上午10点开始，数据库中就有大量的会话出现了大量的library cache lock事件，执行的SQL还都是不一样的。
**查询被阻塞会话的数量
复制
SELECT blocking_session,x.blocking_session_serial#,count(1)FROM dba_hist_active_sess_history xwhere 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_historywhere 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_historyWHERE 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 xwhere 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搞垮一个数据库的惨案啊。
总结
- 导致数据库几乎宕机的SQL，在AWR报告中不一定能看到，TOP 也是很有用的；
- 在追查历史问题上，DBAHIST*类的视图能够提供很好的帮助作用；
