latch: cache buffers chains导致CPU冲高的问题

今天同事分享了一个特别好的案例，所以记录到我的博客

现象：
CPU冲高，大量latch: cache buffers chains等待事件.

分析过程：
1.根据等待事件查询出SQL信息。
select t.BLOCKING_SESSION,t.BLOCKING_SESSION_STATUS,t.sql_id,t.SQL_HASH_VALUE,t.* from v$session t where t.EVENT='latch: cache buffers chains';

发现一个insert语句

2.根据SQL_ID查看历史执行信息：
-----查询sql历史执行信息（次数，时间,HASH_VALUES变化等）
select sn.snap_id,
  s.instance_number,
  to_char(sn.end_interval_time, 'YYYYMMDD HH24:MI:SS'),
  s.plan_hash_value,
  s.executions_delta,
  round(s.elapsed_time_delta / s.executions_delta)/1000 elapsed_time_ms ,
  round(s.BUFFER_GETS_delta / s.executions_delta),
  round(s.CPU_TIME_delta / s.executions_delta)/1000 CPU_TIME_ms
  from dba_hist_snapshot sn, sys.WRH$_SQLSTAT s
where s.snap_id = sn.snap_id
   and s.sql_id = '16sbfyw840rvd'
   and s.instance_number = sn.instance_number
   and s.executions_delta > 0
order by sn.end_interval_time desc
;
发现执行计划没有变化，buffer_get越来越高。可以看到执行时间从8ms/次到800ms/次。

3.根据SQL_ID查看：

select hash_value,t.CHILD_NUMBER,t.SQL_FULLTEXT from v$sql t where t.sql_id='51yrcs15tcfm1';
发现CHILD_NUMBER 有很多。怀疑是SQL硬解析有问题。buffer_get越来越高。

4.根据事件等待addr查询：
select hladdr,
                     obj,
                     (select object_name
                        from dba_objects
                       where (data_object_id is null and object_id = x.obj)
                          or data_object_id = x.obj
                         and rownum = 1) as object_name,
                     dbarfil,
                     dbablk,
                     tch
                from x$bh x
               where hladdr in (select t.P1RAW from v$session t where t.EVENT='latch: cache buffers chains')
               order by tch desc;
发现并没有索引相关的热块，只有表相关的。所以跟索引没直接关系。

7.此表有trigger，发现trigger有问题。：
从trigger内容可以看到做10046时刚好没有触发到trigger，所以做10046没有发现问题。做10046时是自己做的insert，不能代表应用发起的SQL没有问题；但应用发起的SQL虽然效率变慢了，但也只是用了0.8s/次。
所以很难用10046跟踪。
trigger里的SQL执行计划改变，有全表扫描。固化执行计划，就可以了。
  
  
总结：
这一类Insert SQL触发了trigger，
Trigger里有个查询SQL  sql_id:16sbfyw840rvd，此SQL执行计划变了，走全表扫，
昨晚这张表索引重建，这张表日变化量会增大，所以看到buffer_get就越来越大。 当日表的统计信息是空的，由于昨天有统计信息收集，触发今天早上发生硬解析，而表没有统计信息，oracle会通过动态采样获取信息。
早晨6点多的today表数据量非常小，oracle认为全表扫描优于索引扫描。

分析问题有时不能只抓住问题本身，分析思路断了可以跳出来看看关联的其它地方。从时间点看问题肯定跟索引重建有关。

这个异常的特点是简单insert语句（无子查询，所以不存在insert语句执行计划异常的问题）出现大量的cbc等待，buffer gets异常，一般是从三个方面分析的：
1、db内部系统资源的消耗，如解析等需要读数据字典信息的表，可能触发一些bug导致buffer gets过高
2、表本身的资源消耗，如索引空块过多导致的遍历等
3、关联对象的资源消耗，如表上的trigger等，这个在我们公司是最常见的，不管是update还是insert甚至有些数据的delete都有trigger，有些有比较复杂的处理逻辑

这个性能语句的特点是从26号8:40分左右开始逐渐衰退的，单次insert的buffer gets从不到100增加到50000+，并且增加的越来越快
运营确认又是核心应用，如果不及时解决的话影响会越来越严重，这种随时间性能衰减特别严重的语句，是必须要处理的，否则早晚会影响整个db

当时何工和海锋已经确认前两个没有问题，那就只剩下最后一个可能了

当时做了一个awr报告，发现将近80%的buffer gets都是insert trigger中的语句，就确认是trigger导致的了

在10g中统计信息锁定后有两个问题需要注意：
1、如果统计信息被锁定，重建或者新建索引的统计信息都是空，好像在10g中空表创建索引的时候统计信息也是空，具体大家可以在自己环境测试下
2、如果强制收集统计信息，表的统计信息就解锁了