数据库出现大量latch free等待事件的处理

原文来自yangtingkun(http://yangtingkun.itpub.net/]http://yangtingkun.itpub.net)，今天发现一个报表数据库中SQL运行异常，简单记录一下问题的诊断和解决过程。
[color=navy]问题是在检查ALERT文件时发现的，一个过程运行时间太长而出现了ORA-1555错误。错误信息：
[color=#8000]ORA-01555 caused by SQL statement below (Query Duration=38751 sec, SCN: 0x0000.fe5b584a):[color=#8000]
[color=#8000]INSERT INTO MAN_ORDER_ITEM ([color=#8000]
[color=#8000]ID,[color=#8000]
[color=#8000]REQUEST_QTY,[color=#8000]
[color=#8000]SALER_ID,[color=#8000]
[color=#8000]PRODUCT_ID,[color=#8000]
[color=#8000]UNIT_PRICE,[color=#8000]
[color=#8000]CREATE_DATE,[color=#8000]
[color=#8000]ANSWER_DATE,[color=#8000]
[color=#8000]BUYER_ID[color=#8000]
[color=#8000])[color=#8000]
[color=#8000]SELECT[color=#8000]
[color=#8000]A.RECORD_ID,[color=#8000]
[color=#8000]A.REQUEST_QTY,[color=#8000]
[color=#8000]A.SALER_ORGID,[color=#8000]
[color=#8000]A.PRODUCT_ID,[color=#8000]
[color=#8000]A.UNIT_PRICE,[color=#8000]
[color=#8000]A.CREATE_DATE,[color=#8000]
[color=#8000]NULL,[color=#8000]
[color=#8000]A.BUYER_ORGID[color=#8000]
[color=#8000]FROM ORD_ORDER_ITEM A[color=#8000]
[color=#8000]WHERE A.CREATE_DATE >= TO_DATE('2004-01-01 0:0:0', 'YYYY-MM-DD HH24:MI:SS')[color=#8000]
[color=#8000]AND A.CREATE_DATE < TRUNC(SYSDATE)[color=#8000] [color=#8000]AND EXISTS (SELECT 1 FROM MAN_PRODUCT WHERE ID = A.PRODUCT_ID)[color=#8000] [color=#8000]AND EXISTS (SELECT 1 FROM MAN_DEALER WHERE ID = A.SALER_ORGID)[color=#8000] [color=#8000]AND EXISTS (SELECT 1 FROM MAN_BUYER WHERE ID = A.BUYER_ORGID) 由于这是个JOB调用，在失败后JOB会自动重试，于是从DBA_JOBS_RUNNING中查看相关的JOB和SESSION信息。 SQL> [color=#8000]SELECT SID, JOB FROM DBA_JOBS_RUNNING;
SID JOB
---------- ----------
70 208

检查这个SESSION目录在执行什么SQL：
SQL> [color=#8000]SELECT SQL_TEXT FROM V$SQL SQL, V$SESSION S[color=#8000] [color=#8000]WHERE SQL.HASH_VALUE = S.SQL_HASH_VALUE[color=#8000] [color=#8000]AND SQL.ADDRESS = S.SQL_ADDRESS[color=#8000] [color=#8000]AND S.SID = 70;
SQL_TEXT
------------------------------------------------------------------------------
INSERT INTO MAN_ORDER_ITEM ( ID, REQUEST_QTY, SALER_ID, PRODUCT_ID, UNIT_PRICE, CREATE_DATE, ANSWER_DATE,
BUYER_ID ) SELECT A.RECORD_ID, A.REQUEST_QTY, A.SALER_ORGID, A.PRODUCT_ID, A.UNIT_PRICE, A.CREATE_DATE,
NULL, A.BUYER_ORGID FROM ORD_ORDER_ITEM A WHERE A.CREATE_DATE >= TO_DATE('2004-01-01 0:0:0', 'YYYY-MM-DD HH24:MI:S
S') AND A.CREATE_DATE < TRUNC(SYSDATE) AND EXISTS (SELECT 1 FROM MAN_PRODUCT WHERE ID = A.PRODUCT_ID) AND EXISTS (SEL ECT 1 FROM MAN_DEALER WHERE ID = A.SALER_ORGID) AND EXISTS (SELECT 1 FROM MAN_BUYER WHERE ID = A.BUYER_ORGID) 从SQL上看，就是刚才失败的那个SQL语句，那么看看SESSION在等待什么： SQL> [color=#8000]SELECT SID, EVENT, P1TEXT, P1RAW, P2TEXT, P2, SECONDS_IN_WAIT FROM V$SESSION_WAIT[color=#8000] [color=#8000]WHERE SID = 70;
SID EVENT P1TEXT P1RAW P2TEXT P2 SECONDS_IN_WAIT
------- -------------- -------- ---------------- ------- ----- ---------------
70 latch free address 00000004125AB718 number 98 330

通过观察发现，Session的等待事件一直是LATCH FREE。第一个感觉是可能和其他的进程产生了争用。查询一下Oracle等待的具体latch的类型。
SQL> SELECT LATCH#, NAME FROM V$LATCH WHERE LATCH# = 98;
LATCH# NAME
---------- ----------------------------------------------------------------
98 cache buffers chains

而查询V$LOCK和V$LATCHHOLDER视图，发现没有其他的进程对JOB运行构成影响：
SQL> [color=#8000]SELECT SID, TYPE, ID1, ID2, LMODE, REQUEST, CTIME, BLOCK[color=#8000] [color=#8000]FROM V$LOCK[color=#8000] [color=#8000]WHERE SID > 8;
SID TY ID1 ID2 LMODE REQUEST CTIME BLOCK
---------- -- ---------- ---------- ---------- ---------- ---------- ----------
70 TM 35258 0 3 0 12072 0
70 JQ 0 208 6 0 12155 0
SQL> SELECT * FROM V$LATCHHOLDER;
no rows selected
SQL> [color=#8000]SELECT * FROM V$LATCHHOLDER;
PID SID LADDR NAME
---------- ---------- ---------------- ------------------------------
15 70 0000000412564D98 cache buffers chains
SQL> [color=#8000]SELECT * FROM V$LATCHHOLDER;
no rows selected

可以看到，并没有其他对象影响JOB进程。由于等待事件是LATCH FREE，怀疑和系统本身的问题有关。通过下面的脚本可以看到，目前正在等待的这个子LATCH的信息：
SQL> [color=#8000]SELECT ADDR, LATCH#, CHILD#, NAME FROM V$LATCH_CHILDREN[color=#8000] [color=#8000]WHERE ADDR IN (SELECT P1RAW FROM V$SESSION_WAIT WHERE SID = 70);
ADDR LATCH# CHILD# NAME
---------------- ---------- ---------- ---------------------------------------
0000000412550518 98 327 cache buffers chains
观察LATCH_MISSES的信息：
[color=#8000]SQL> COL PARENT_NAME FORMAT A20[color=#8000]
[color=#8000]SQL> COL WHERE FORMAT A35[color=#8000]
[color=#8000]SQL> SELECT * FROM (SELECT PARENT_NAME, "WHERE", SLEEP_COUNT, WTR_SLP_COUNT, LONGHOLD_COUNT FROM V$LATCH_MISSES[color=#8000] [color=#8000]WHERE PARENT_NAME = 'cache buffers chains'[color=#8000] [color=#8000]ORDER BY SLEEP_COUNT + WTR_SLP_COUNT[color=#8000] [color=#8000]+ LONGHOLD_COUNT DESC ) WHERE ROWNUM < 20; [color=#8000]PARENT_NAME WHERE SLEEP_COUNT WTR_SLP_COUNT LONGHOLD_COUNT -------------------- ------------------------------- ----------- ------------- -------------- cache buffers chains kcbgtcr: kslbegin excl 1202658 884364 906374 cache buffers chains kcbrls: kslbegin 480030 852471 335799 cache buffers chains kcbzwb 95994 90482 84373 cache buffers chains kcbgtcr: kslbegin shared 89385 84911 62640 cache buffers chains kcbgtcr: fast path 69352 113120 51014 cache buffers chains kcbchg: kslbegin: bufs not pinned 86476 51934 58687 cache buffers chains kcbzsc 76224 55 75045 cache buffers chains kcbbxsv 37425 8306 35681 cache buffers chains kcbchg: kslbegin: call CR func 1337 20943 745 cache buffers chains kcbzib: finish free bufs 685 18544 432 cache buffers chains kcbcge 168 8767 107 cache buffers chains kcbgcur: kslbegin 344 4974 203 cache buffers chains kcbget: pin buffer 542 4508 383 cache buffers chains kcbgtcr 2400 395 1769 cache buffers chains kcbbic1 14 4015 11 cache buffers chains kcbzgb: scan from tail. nowait 2048 0 1896 cache buffers chains kcbbic2 38 2920 32 cache buffers chains kcbzib: multi-block read: nowait 1502 0 970 cache buffers chains kcbnew 497 331 289 19 rows selected. 感觉问题和热点块有关，那么看看到底是哪些块出现的问题： SQL> [color=#8000]SELECT OBJ, OBJECT_NAME, TCH, TIM[color=#8000] [color=#8000]FROM X$BH A, DBA_OBJECTS B WHERE HLADDR IN (SELECT P1RAW FROM V$SESSION_WAIT WHERE SID = 70) AND A.OBJ = B.DATA_OBJECT_ID;
OBJ OBJECT_NAME TCH TIM
---------- ------------------------------ ---------- ----------
109 I_OBJAUTH2 0 0
45761 STATS$SQLTEXT_PK 1 1174381376
.
.
.
62275 ORD_ORDER_ITEM_ZJ 1 1174380112
62275 ORD_ORDER_ITEM_ZJ 1 1174380085
62275 ORD_ORDER_ITEM_ZJ 1 1174380088
62275 ORD_ORDER_ITEM_ZJ 1 1174380097
62275 ORD_ORDER_ITEM_ZJ 1 1174380100
62275 ORD_ORDER_ITEM_ZJ 1 1174380103.
.

200403 ORD_ORDER_ITEM 6 1174381870
200403 ORD_ORDER_ITEM 6 1174381871
200403 ORD_ORDER_ITEM 6 1174381870
200403 ORD_ORDER_ITEM 6 1174381870
200403 ORD_ORDER_ITEM 6 1174381871
200403 ORD_ORDER_ITEM 6 1174381870
200403 ORD_ORDER_ITEM 6 1174381870
200403 ORD_ORDER_ITEM 6 1174381871
200403 ORD_ORDER_ITEM 6 1174381871
200403 ORD_ORDER_ITEM 6 1174381871
200403 ORD_ORDER_ITEM 6 1174381870
200403 ORD_ORDER_ITEM 6 1174381870
.
.
.
62275 ORD_ORDER_ITEM_ZJ 678 1174381878
62275 ORD_ORDER_ITEM_ZJ 1 1174380060
62275 ORD_ORDER_ITEM_ZJ 1 1174380091
62126 ORD_ORDER_ITEM_CEN 0 0
62126 ORD_ORDER_ITEM_CEN 0 0
62126 ORD_ORDER_ITEM_CEN 0 0
62126 ORD_ORDER_ITEM_CEN 0 0
45772 STATS$UNDOSTAT 0 0
45772 STATS$UNDOSTAT 0 0
125 rows selected.

[color=navy]我们也可以通过以下SQL来找到等待事件的SID,再根据SID来找到相应的SQL：
[color=#8000][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的执行计划：
SQL> [color=#8000]EXPLAIN PLAN FOR[color=#8000]
2 INSERT INTO MAN_ORDER_ITEM (
3 ID,
4 REQUEST_QTY,
5 SALER_ID,
6 PRODUCT_ID,
7 UNIT_PRICE,
8 CREATE_DATE,
9 ANSWER_DATE,
10 BUYER_ID
11 )
12 SELECT
13 A.RECORD_ID,
14 A.REQUEST_QTY,
15 A.SALER_ORGID,
16 A.PRODUCT_ID,
17 A.UNIT_PRICE,
18 A.CREATE_DATE,
19 NULL,
20 A.BUYER_ORGID
21 FROM ORD_ORDER_ITEM A
22 WHERE A.CREATE_DATE >= TO_DATE('2004-01-01 0:0:0', 'YYYY-MM-DD HH24:MI:SS')
23 AND A.CREATE_DATE < TRUNC(SYSDATE) 24 AND EXISTS (SELECT 1 FROM MAN_PRODUCT WHERE ID = A.PRODUCT_ID) 25 AND EXISTS (SELECT 1 FROM MAN_DEALER WHERE ID = A.SALER_ORGID) 26 AND EXISTS (SELECT 1 FROM MAN_BUYER WHERE ID = A.BUYER_ORGID) 27 ; Explained. SQL> [color=#8000]SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY());
PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost |
-------------------------------------------------------------------------------------------------
| 0 | INSERT STATEMENT | | 1 | 212 | 37 |
|* 1 | FILTER | | | | |
| 2 | NESTED LOOPS | | 1 | 212 | 37 |
| 3 | MERGE JOIN CARTESIAN | | 1 | 76 | 12 |
| 4 | MERGE JOIN CARTESIAN | | 1 | 51 | 9 |
| 5 | SORT UNIQUE | | | | |
| 6 | INDEX FAST FULL SCAN | PK_MAN_PRODUCT | 1 | 26 | 3 |
| 7 | BUFFER SORT | | 8138 | 198K| 6 |
| 8 | SORT UNIQUE | | | | |
| 9 | INDEX FAST FULL SCAN | PK_MAN_BUYER | 8138 | 198K| 3 |
| 10 | BUFFER SORT | | 14238 | 347K| 9 |
| 11 | SORT UNIQUE | | | | |
| 12 | INDEX FAST FULL SCAN | PK_MAN_DEALER | 14238 | 347K| 3 |
|* 13 | VIEW | ORD_ORDER_ITEM | 1 | 136 | 37 |
| 14 | UNION-ALL PARTITION | | | | |
|* 15 | FILTER | | | | |
|* 16 | TABLE ACCESS BY INDEX ROWID| ORD_ORDER_ITEM_CEN | 1 | 116 | 14 |
| 17 | AND-EQUAL | | | | |
|* 18 | INDEX RANGE SCAN | TU_ORD_ORD_ITEM_PRODUCT_ID | | | |
|* 19 | INDEX RANGE SCAN | TU_ORD_ORDER_ITEM_SALER | | | |
|* 20 | FILTER | | | | |
|* 21 | TABLE ACCESS BY INDEX ROWID| ORD_ORDER_ITEM_ZJ | 1 | 116 | 2 |
|* 22 | INDEX RANGE SCAN | TU_ORD_ORD_ITEM_PRODUCT_ID1 | 179 | | 1 |
-------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter(TRUNC(SYSDATE@!)>TO_DATE('2004-01-01 00:00:00', 'yyyy-mm-dd hh24:mi:ss') AND
TO_DATE('2004-01-01 00:00:00', 'yyyy-mm-dd hh24:mi:ss')TO_DATE('2004-01-01 00:00:00', 'yyyy-mm-dd hh24:mi:ss') AND
TO_DATE('2004-01-01 00:00:00', 'yyyy-mm-dd hh24:mi:ss')=TO_DATE('2004-01-01 00:00:00', 'yyyy-mm-dd hh24:mi:ss') AND
"ORD_ORDER_ITEM_CEN"."CREATE_DATE"TO_DATE('2004-01-01 00:00:00', 'yyyy-mm-dd hh24:mi:ss') AND
TO_DATE('2004-01-01 00:00:00', 'yyyy-mm-dd hh24:mi:ss')=TO_DATE('2004-01-01 00:00:00', 'yyyy-mm-dd hh24:mi:ss') AND
"ORD_ORDER_ITEM_ZJ"."CREATE_DATE" [color=#8000]SELECT TABLE_NAME, NUM_ROWS FROM USER_TABLES[color=#8000] [color=#8000]WHERE TABLE_NAME IN ('MAN_PRODUCT', 'MAN_BUYER', 'MAN_DEALER');
TABLE_NAME NUM_ROWS
------------------------------ ----------
MAN_BUYER 8138
MAN_DEALER 14238
MAN_PRODUCT 0
SQL> SELECT COUNT(*) FROM MAN_PRODUCT;
COUNT(*)
----------
91750

已经很明显了，MAN_PRODUCT的统计信息有误。正是由于Oracle认为MAN_PRODUCT的记录为0，所以选择了MERGE JOIN的方式，这样可以最迅速的得到最终的结果——0条记录。但是MAN_PRODUCT的记录数实际上并不为0，而是有将近10万的记录。这就是导致问题产生的真正原因。

其实问题到这里并没有完。Oracle产生错误的统计信息也是有原因的。首先这个脚本会首先清空相关表的数据，然后重新生成。而在前一次执行这个过程的时候，中途失败了。导致MAN_PRODUCT表中没有数据。而每周运行一次的收集统计信息的JOB把MAN_PRODUCT表的0记录的统计信息记录了下来。
再次运行脚本的时候，虽然将记录写入到MAN_PRODUCT表中，但是统计信息并没有更新，因此导致了这个问题。

了解了问题的产生原因，解决起来就十分容易了，收集MAN_PRODUCT表的统计信息并检查执行计划，杀掉运行中JOB，重新启动JOB就可以了。
SQL>[color=#8000] EXEC DBMS_STATS.GATHER_TABLE_STATS(USER, 'MAN_PRODUCT', CASCADE => TRUE)
PL/SQL procedure successfully completed.
SQL> [color=#8000]EXPLAIN PLAN FOR[color=#8000]
2 INSERT INTO MAN_ORDER_ITEM (
3 ID,
4 REQUEST_QTY,
5 SALER_ID,
6 PRODUCT_ID,
7 UNIT_PRICE,
8 CREATE_DATE,
9 ANSWER_DATE,
10 BUYER_ID
11 )
12 SELECT
13 A.RECORD_ID,
14 A.REQUEST_QTY,
15 A.SALER_ORGID,
16 A.PRODUCT_ID,
17 A.UNIT_PRICE,
18 A.CREATE_DATE,
19 NULL,
20 A.BUYER_ORGID
21 FROM ORD_ORDER_ITEM A
22 WHERE A.CREATE_DATE >= TO_DATE('2004-01-01 0:0:0', 'YYYY-MM-DD HH24:MI:SS')
23 AND A.CREATE_DATE < TRUNC(SYSDATE) 24 AND EXISTS (SELECT 1 FROM MAN_PRODUCT WHERE ID = A.PRODUCT_ID) 25 AND EXISTS (SELECT 1 FROM MAN_DEALER WHERE ID = A.SALER_ORGID) 26 AND EXISTS (SELECT 1 FROM MAN_BUYER WHERE ID = A.BUYER_ORGID) 27 ; Explained. SQL>[color=#8000] SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY());
PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
----------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes |TempSpc| Cost |
--------------------------------------------------------------------------------------------------------------
| 0 | INSERT STATEMENT | | 32977 | 6795K| | 72667 |
|* 1 | FILTER | | | | | |
| 2 | NESTED LOOPS SEMI | | 32977 | 6795K| | 72667 |
| 3 | NESTED LOOPS SEMI | | 32977 | 5989K| | 72667 |
|* 4 | HASH JOIN SEMI | | 32977 | 5184K| 4768K| 72667 |
| 5 | VIEW | ORD_ORDER_ITEM | 32977 | 4379K| | 72502 |
| 6 | UNION-ALL | | | | | |
|* 7 | FILTER | | | | | |
| 8 | TABLE ACCESS BY INDEX ROWID| ORD_ORDER_ITEM_CEN | 5797K| 641M| | 479 |
|* 9 | INDEX RANGE SCAN | TU_ORD_ORDER_ITEM_CREATE_DATE | 5797K| | | 16 |
|* 10 | FILTER | | | | | |
| 11 | TABLE ACCESS BY INDEX ROWID| ORD_ORDER_ITEM_ZJ | 2464K| 272M| | 643 |
|* 12 | INDEX RANGE SCAN | TU_ORD_ORDER_ITEM_CREATE_DATE1 | 2464K| | | 21 |
| 13 | INDEX FAST FULL SCAN | PK_MAN_PRODUCT | 91750 | 2239K| | 39 |
|* 14 | INDEX UNIQUE SCAN | PK_MAN_BUYER | 8138 | 198K| | |
|* 15 | INDEX UNIQUE SCAN | PK_MAN_DEALER | 14238 | 347K| | |
---------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter(TRUNC(SYSDATE@!)>TO_DATE('2004-01-01 00:00:00', 'yyyy-mm-dd hh24:mi:ss') AND
TO_DATE('2004-01-01 00:00:00', 'yyyy-mm-dd hh24:mi:ss')TO_DATE('2004-01-01 00:00:00', 'yyyy-mm-dd hh24:mi:ss') AND
TO_DATE('2004-01-01 00:00:00', 'yyyy-mm-dd hh24:mi:ss')=TO_DATE('2004-01-01 00:00:00', 'yyyy-mm-dd hh24:mi:ss') AND
"ORD_ORDER_ITEM_CEN"."CREATE_DATE"TO_DATE('2004-01-01 00:00:00', 'yyyy-mm-dd hh24:mi:ss') AND
TO_DATE('2004-01-01 00:00:00', 'yyyy-mm-dd hh24:mi:ss')=TO_DATE('2004-01-01 00:00:00', 'yyyy-mm-dd hh24:mi:ss') AND
"ORD_ORDER_ITEM_ZJ"."CREATE_DATE" [color=#8000]SELECT SPID FROM V$PROCESS WHERE ADDR IN (SELECT PADDR FROM V$SESSION WHERE SID = 70);
SPID
------------
27488

找到JOB运行的操作系统进程，然后通过操作系统命令kill -9来杀掉进程。JOB运行的会话很难通过ALTER SYSTEM KILL SESSION语句来杀掉，因此选择使用操作系统命令的方式。
SQL> host
$ ps -ef|grep 27488
oracle 28672 28671 0 18:07:20 pts/2 0:00 grep 27488
oracle 27488 1 13 12:46:56 ? 317:21 ora_j000_repdb01
$ kill -9 27488
$ exit
检查SESSION和JOB状态，确认JOB重新启动。
至此，问题解决。其实当时发现问题的时候，有两条路可以选择，一方面从系统运行的情况入手，也就是这篇文章中选择的方式。另一方面是直接从SQL语句入手，先检查执行计划。
由于这个SQL以前过多次，都是正常的，所以没有想到执行计划会发生那么大的变化。因此，一直从第一方面着手来诊断问题。所幸殊途同归，虽然绕了一个大圈子，最终还是找到问题的所在。