latch: cache buffers chains等待事件

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

现象：

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、如果强制收集统计信息，表的统计信息就解锁了