生产 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';
SQL如下:
INSERT /*+ 2 */
INTO T_PUB_SALE_HISTORY_TODAY
(SALE_HISTORY_ID,
BEGIN_TIME,
END_TIME,
CALL_DURATION,
CONTACT_PHONE,
PHONE_RESULT,
CONTACT_TYPE,
TASK_GROUP_ID,
CAMPAIGN_NAME,
CAMPAIGN_ID,
TMR_ID,
BATCH_ID,
CUSTOMER_ID,
HR_CORPORATION_ID,
HR_CORPORATION_DESC,
HR_DEPARTMENT_ID,
HR_DEPARTMENT_DESC,
HR_TEAM_ID,
HR_TEAM_DESC,
IS_FIRST)
VALUES
(:1,
:2,
…
…
:20);
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
;
SNAP_ID INSTANCE_NUMBER TO_CHAR(SN.END_INTERVAL_TIME,' PLAN_HASH_VALUE EXECUTIONS_DELTA ELAPSED_TIME_MS ROUND(S.BUFFER_GETS_DELTA/S.EX CPU_TIME_MS
195879 1 20160926 20:00:24 0 3210 769.426 67671 777.692
195878 1 20160926 19:45:20 0 5088 794.295 67254 804.265
195877 1 20160926 19:30:17 0 8366 841.222 66362 852.668
195876 1 20160926 19:15:14 0 11428 872.468 65353 885.592
195875 1 20160926 19:00:10 0 13922 882.147 63796 895.557
195874 1 20160926 18:45:07 0 15680 888.025 62105 901.859
195873 1 20160926 18:30:03 0 17718 883.977 60161 897.163
.....
.....
195845 1 20160926 11:30:29 0 15433 217.737 17110 212.698
195844 1 20160926 11:15:25 0 15071 194.194 15374 188.47
195843 1 20160926 11:00:22 0 12262 175.219 13819 168.309
.....
195835 1 20160926 09:00:55 0 5730 20.029 1110 14.438
195834 1 20160926 08:45:52 0 3074 13.728 535 8.081
195833 1 20160926 08:30:49 0 1536 10.497 263 4.036
195832 1 20160926 08:15:46 0 745 5.52 104 1.691
195556 1 20160923 11:15:55 0 15315 8.313 33 2.095
发现执行计划没有变化,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越来越高,怀疑中BUG。
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;
发现并没有索引相关的热块,只有表相关的。所以跟索引没直接关系。
5.此时思路断了,做10046。
6.做完10046,发现SQL执行没有效率问题。 证明表没有问题。
7.发现trigger问题。:
从trigger内容可以看到做10046时刚好没有触发到trigger,所以做10046没有发现问题。做10046时是自己做的insert,不能代表应用发起的SQL没有问题;但应用发起的SQL虽然效率变慢了,但也只是用了0.8s/次。
所以很难用10046跟踪。
CREATE OR REPLACE TRIGGER ....
BEFORE INSERT ON ...
FOR EACH ROW
DECLARE
...
BEGIN
...
...
IF :NEW.CUSTOMER_ID IS NOT NULL AND :NEW.CAMPAIGN_ID IS NOT NULL THEN
SELECT COUNT(*) INTO v_if_exists FROM
(SELECT T.SALE_HISTORY_ID
FROM T_PUB_SALE_HISTORY T
WHERE T.CUSTOMER_ID = :NEW.CUSTOMER_ID
AND T.CAMPAIGN_ID = :NEW.CAMPAIGN_ID AND T.UPDATED_DATE < TRUNC(SYSDATE) AND ROWNUM = 1
union all
SELECT T.SALE_HISTORY_ID
FROM T_PUB_SALE_HISTORY_TODAY T
WHERE T.CUSTOMER_ID = :NEW.CUSTOMER_ID
AND T.CAMPAIGN_ID = :NEW.CAMPAIGN_ID AND T.UPDATED_DATE < TRUNC(SYSDATE) AND ROWNUM = 1
);
...
...
...
END ...;
执行计划:
Plan hash value: 1302081189
| Id | Operation | Name | Rows | Byt
| 0 | SELECT STATEMENT | | |
| 1 | SORT AGGREGATE | | 1 |
| 2 | VIEW | | 2 |
| 3 | UNION-ALL | | |
|* 4 | COUNT STOPKEY | | |
|* 5 | TABLE ACCESS BY INDEX ROWID| T_PUB_SALE_HISTORY | 1 |
|* 6 | INDEX RANGE SCAN | IDX_CUSTOMER_ID | 15 |
|* 7 | COUNT STOPKEY | | |
|* 8 | TABLE ACCESS FULL | T_PUB_SALE_HISTORY_TODAY | 1 |
三.问题总结:
这一类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、如果强制收集统计信息,表的统计信息就解锁了