数据库出现大量latch: cache buffers chains等待事件的处理

原文来自yangtingkun([url]http://yangtingkun.itpub.net)，一个客户产品数据库上午出现了严重的性能问题，简单记录一下问题的诊断和解决过程。

从TOP 5看，等待事件中最明显的是latch: cache buffers chains，从当前系统的状态也可以看到这一点：

SQL> [color=#8000]SELECT EVENT, COUNT(*) FROM GV$SESSION GROUP BY EVENT HAVING COUNT(*) > 5 ORDER BY 2 DESC;
EVENT COUNT(*)
---------------------------------------------------------------- ----------
latch: cache buffers chains 1043
SQL*Net message from client 500
SQL*Net message to client 35
rdbms ipc message 29
gc cr request 25
latch free 13
gcs remote message 10
gc buffer busy 7
8 rows selected.

收集AWR报告，发现系统中部分SQL的执行时间已经长达几个小时：
SQL ordered by Elapsed Time

[td=67]Elapsed Time (s)
[td=56]CPU Time (s)
[td=48]Executions
[td=70]Elap per Exec (s)
[td=71]% Total DB Time
[td=65]SQL Id
[td=66]SQL Module
[td=130]SQL Text

[td=67]341,821
[td=56]11,917
[td=48]112
[td=70]3051.97
[td=71]32.99
[td=65]8v9mhuxam279p
[td=66]JDBC Thin Client
[td=130]SELECT count(*) total FROM ( s...

[td=67]244,752
[td=56]3,380
[td=48]147
[td=70]1664.98
[td=71]23.62
[td=65]44zutxspd664c
[td=66]JDBC Thin Client
[td=130]SELECT count(*) total FROM ( s...

[td=67]52,419
[td=56]11,331
[td=48]3
[td=70]17472.91
[td=71]5.06
[td=65]a6aqkm30u7p90
[td=66]JDBC Thin Client
[td=130]select cf.cardid, (CASE WHEN c...

[td=67]38,767
[td=56]532
[td=48]11
[td=70]3524.24
[td=71]3.74
[td=65]8b8kbrqmg7qf9
[td=66]JDBC Thin Client
[td=130]SELECT count(*) total FROM ( s...

[td=67]37,146
[td=56]2,524
[td=48]2
[td=70]18573.15
[td=71]3.58
[td=65]8fpf0vtjzb583
[td=66]JDBC Thin Client
[td=130]SELECT count(*) total FROM ( s...

[td=67]30,796
[td=56]2,331
[td=48]5
[td=70]6159.20
[td=71]2.97
[td=65]9wxzf70vub4wg
[td=66]JDBC Thin Client
[td=130]SELECT count(*) total FROM ( s...

[td=67]29,991
[td=56]2,506
[td=48]1
[td=70]29991.41
[td=71]2.89
[td=65]5vdncfn06sxz8
[td=66]JDBC Thin Client
[td=130]SELECT count(*) total FROM ( s...

[td=67]24,762
[td=56]875
[td=48]3
[td=70]8254.06
[td=71]2.39
[td=65]8vyda1jxu2nsc
[td=66]JDBC Thin Client
[td=130]SELECT count(*) total FROM (SE...

[td=67]17,845
[td=56]699
[td=48]2
[td=70]8922.50
[td=71]1.72
[td=65]99g0x7u3jv28v
[td=66]JDBC Thin Client
[td=130]SELECT count(*) total FROM (SE...

[td=67]17,470
[td=56]1,295
[td=48]0
[td=70]
[td=71]1.69
[td=65]08qmyqnjkpgru
[td=66]JDBC Thin Client
[td=130]select * from (select aa.*, ro...

我们也可以通过以下SQL来找到等待事件的SID,再根据SID来找到相应的SQL：
[color=#8000][/mw_shl_code][mw_shl_code=sql,true]col EVENT format a50
col P1TEXT format a10
col P2TEXT format a10
col P3TEXT format a10
select SID,SEQ#,EVENT from v$session_wait t
where t.EVENT not in
('SQL*Net message from client', 'rdbms ipc message',
'SQL*Net more data from client', 'SQL*Net more data to client',
'SQL*Net message to client', 'jobq slave wait');

select sql_text from v$sqlarea where (hash_value,address)=(select sql_hash_value,sql_address from v$session where sid=&sid);

col owner format a15
col object_name format a30
col osuser format a15
col username format a15
col machine format a20
col program format a25
select ls.sid,ls.serial#,ls.status status,o.owner,o.object_name,decode(ls.type,'RW','Row wait enqueue lock','TM','DML enqueue lock','TX','Transaction enqueue lock','UL','User supplied lock') type,decode(ls.lmode, 1, null, 2,'Row Share', 3,'Row Exclusive', 4,'Share', 5,'Share Row Exclusive', 6,'Exclusive', null) lmode,ls.id1,ls.id2,ls.username,ls.osuser,ls.machine,ls.program from sys.dba_objects o, ( select s.osuser, s.username, l.type, l.lmode, s.sid, s.serial#,s.status, s.machine, s.program, l.id1, l.id2 from v$session s, v$lock l where s.sid = l.sid ) ls where o.object_id = ls.id1 and o.owner<>'SYS' and username is not null order by ls.sid;
[/mw_shl_code]

其实根据这些现象，基本上可以判断问题了。肯定是SQL执行计划的改变导致了当前的性能问题。而类似绑定变量窥探之类的问题只会影响个别的SQL，而这么大面积的执行计划的改变，几乎可以断定是统计信息造成的。
询问了一下客户最近的操作，原来昨天夜里通过数据库链的方式导入了一部分数据。而今天一早问题就出现了。
其实问题已经很明显了，在通过数据库链加载数据后，并没有重新收集统计信息，且由于加载时间是在半夜，这批数据也没有赶上每天22:00的统计信息自动收集的工作。这就使得Oracle在生成执行计划时，会依赖数据加载前的统计信息，从而造成了错误的执行计划。

[color=#8000]检查该SQL的执行计划：
[color=#8000]SQL> EXPLAIN PLAN FOR[color=#8000] select * from table
[color=#8000]SQL> SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY());

[color=#8000]我们再看统计信息：

[color=#8000]SQL> SELECT TABLE_NAME, NUM_ROWS FROM USER_TABLES[color=#8000] [color=#8000]WHERE TABLE_NAME IN ('MAN_PRODUCT', 'MAN_BUYER', 'MAN_DEALER');
[color=#8000]TABLE_NAME NUM_ROWS[color=#8000]
[color=#8000]------------------------------ ----------[color=#8000]
[color=#8000]MAN_BUYER 8138[color=#8000]
[color=#8000]MAN_DEALER 14238[color=#8000]
[color=#8000]MAN_PRODUCT 0

[color=#8000]SQL> SELECT COUNT(*) FROM MAN_PRODUCT;
[color=#8000]COUNT(*)[color=#8000]
[color=#8000]----------[color=#8000]
[color=#8000]91750

已经很明显了，MAN_PRODUCT的统计信息有误。首先解决问题的根源问题，对加载过数据的表重新收集统计：

SQL> [color=#8000]SELECT 'EXEC DBMS_STATS.GATHER_TABLE_STATS(''USER1'', ''' || TABLE_NAME || ''', CASCADE => TRUE)' FROM DBA_TABLES WHERE OWNER = 'USER1' AND LAST_ANALYZED < TRUNC(SYSDATE); 'EXECDBMS_STATS.GATHER_TABLE_STATS(''USER1'','''||TABLE_NAME||''',CASCADE=>TRUE)'
-----------------------------------------------------------------------------------------
EXEC DBMS_STATS.GATHER_TABLE_STATS('USER1', 'TABLE_1', CASCADE => TRUE)
EXEC DBMS_STATS.GATHER_TABLE_STATS('USER1', 'TABLE_2', CASCADE => TRUE)
2 rows selected.

SQL> [color=#8000]EXEC DBMS_STATS.GATHER_TABLE_STATS('USER1', ' TABLE_1', CASCADE => TRUE)
PL/SQL procedure successfully completed.

SQL> [color=#8000]EXEC DBMS_STATS.GATHER_TABLE_STATS('USER1', ' TABLE_2', CASCADE => TRUE)
PL/SQL procedure successfully completed.

虽然问题的根源已经被解决，但是当前运行的SQL并不会改变执行计划，因此还需要找到问题的SQL，从后台将其结束：
SQL> [color=#8000]SELECT 'kill -9 ' || spid from v$session s, v$process p where s.username = 'USER2' and s.paddr = p.addr and event = 'latch: cache buffers chains';
'KILL-9'||SPID
--------------------
kill -9 28321
kill -9 25384
kill -9 23697
kill -9 7239
.
.
.
kill -9 9331
kill -9 13759
740 rows selected.

SQL> [color=#8000]SELECT 'kill -9 ' || spid from gv$session s, gv$process p where s.username = 'USER2' and s.paddr = p.addr and event = 'latch: cache buffers chains' and s.inst_id = p.inst_id and s.inst_id = 2;
'KILL-9'||SPID
--------------------
kill -9 23992
kill -9 5289
kill -9 21067
kill -9 16816
kill -9 16820
kill -9 26767
.
.
.
kill -9 14981
kill -9 26678
kill -9 26682
258 rows selected.

分别在两个节点杀掉这些执行计划存在问题的会话，释放被大量占用的系统资源。
由于Oracle的执行计划并非在收集统计信息后马上生效，因此还有个别的SQL仍然沿用错误的执行计划：
SQL>[color=#8000] select distinct inst_id, sql_id from gv$session where event = 'latch: cache buffers chains';
INST_ID SQL_ID
---------- -------------
1 39gvg7vbcm8jx
1 a6aqkm30u7p90
SQL> [color=#8000]select address, hash_value from v$sqlarea where sql_id = 'a6aqkm30u7p90'；
ADDRESS HASH_VALUE
---------------- ----------
C000000EB7ED3420 3248739616

SQL> [color=#8000]exec dbms_shared_pool.purge('C000000EB7ED3420,3248739616','C')
PL/SQL procedure successfully completed.

SQL> [color=#8000]select address, hash_value from v$sqlarea where sql_id ='39gvg7vbcm8jx';
ADDRESS HASH_VALUE
---------------- ----------
C000001037B8E308 3603538493

SQL> [color=#8000]exec dbms_shared_pool.purge('C000001037B8E308’,‘3603538493', 'C')
PL/SQL procedure successfully completed.

[color=#3366ff]由于当前的数据库版本是10.2.0.5，因此可以很方便的使用dbms_shared_pool将执行计划错误的SQL清除出共享池，强制其重新生成执行计划。

SQL> [color=#8000]select event, count(*) from gv$session where username like != user GROUP BY EVENT order by 2 desc;
EVENT COUNT(*)
---------------------------------------------------------------- ----------
SQL*Net message from client 370
SQL*Net message to client 15
gc cr request 10
latch free 4
Streams AQ: waiting for messages in the queue 1
5 rows selected.

[color=#8000]数据库中SQL执行计划错误除了导致大量的latch: cache buffers chains等待以外，还存在gc cr request和latch free等这些等待事件，经分析同样是由于错误的执行计划所致。将这些会话采用相同的方法清除后，系统负载恢复到正常范围[color=#8000]。