长时间latch free等待——记一次系统异常的诊断过程

转载：http://czmmiao.iteye.com/blog/1767091

今天发现一个报表数据库中SQL运行异常，简单记录一下问题的诊断和解决过程。
问题是在检查ALERT文件时发现的，一个过程运行时间太长而出现了ORA-1555错误。
错误信息：
ORA-01555 caused by SQL statement below (Query Duration=38751 sec, SCN: 0x0000.fe5b584a):
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:SS')
AND A.CREATE_DATE < TRUNC(SYSDATE)
AND EXISTS (SELECT 1 FROM MAN_PRODUCT WHERE ID = A.PRODUCT_ID)
AND EXISTS (SELECT 1 FROM MAN_DEALER WHERE ID = A.SALER_ORGID)
AND EXISTS (SELECT 1 FROM MAN_BUYER WHERE ID = A.BUYER_ORGID)
由于这是个JOB调用，在失败后JOB会自动重试，于是从DBA_JOBS_RUNNING中查看相关的JOB和SESSION信息。
SQL> SELECT SID, JOB FROM DBA_JOBS_RUNNING;
SID JOB
---------- ----------
70 208
检查这个SESSION目录在执行什么SQL：
SQL> SELECT SQL_TEXT FROM V$SQL SQL, V$SESSION S
2 WHERE SQL.HASH_VALUE = S.SQL_HASH_VALUE
3 AND SQL.ADDRESS = S.SQL_ADDRESS
4 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> SELECT SID, EVENT, P1TEXT, P1RAW, P2TEXT, P2, SECONDS_IN_WAIT FROM V$SESSION_WAIT
2 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> SELECT SID, TYPE, ID1, ID2, LMODE, REQUEST, CTIME, BLOCK
2 FROM V$LOCK
3 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> SELECT * FROM V$LATCHHOLDER;
no rows selected
SQL> SELECT * FROM V$LATCHHOLDER;
no rows selected
SQL> SELECT * FROM V$LATCHHOLDER;
PID SID LADDR NAME
---------- ---------- ---------------- ------------------------------
15 70 0000000412564D98 cache buffers chains
SQL> SELECT * FROM V$LATCHHOLDER;
no rows selected
可以看到，并没有其他对象影响JOB进程。
由于等待事件是LATCH FREE，怀疑和系统本身的问题有关。
通过下面的脚本可以看到，目前正在等待的这个子LATCH的信息：
SQL> SELECT ADDR, LATCH#, CHILD#, NAME FROM V$LATCH_CHILDREN
2 WHERE ADDR IN (SELECT P1RAW FROM V$SESSION_WAIT WHERE SID = 70);
ADDR LATCH# CHILD# NAME
---------------- ---------- ---------- ---------------------------------------
0000000412550518 98 327 cache buffers chains
观察LATCH_MISSES的信息：
SQL> COL PARENT_NAME FORMAT A20
SQL> COL WHERE FORMAT A35
SQL> SELECT *
2 FROM
3 (
4 SELECT PARENT_NAME, "WHERE", SLEEP_COUNT, WTR_SLP_COUNT, LONGHOLD_COUNT
5 FROM V$LATCH_MISSES
6 WHERE PARENT_NAME = 'cache buffers chains'
7 ORDER BY SLEEP_COUNT + WTR_SLP_COUNT + LONGHOLD_COUNT DESC
8 )
9 WHERE ROWNUM < 20;
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> SELECT OBJ, OBJECT_NAME, TCH, TIM
2 FROM X$BH A, DBA_OBJECTS B
3 WHERE HLADDR IN (SELECT P1RAW FROM V$SESSION_WAIT WHERE SID = 70)
4 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
.
.
200403 ORD_ORDER_ITEM 6 1174381870
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.
从这些热点块的所属对象来看，大部分都是那个长时间运行的SQL访问的。难道转了一个大圈，结果是执行计划的问题？
检查该SQL的执行计划：
SQL> EXPLAIN PLAN FOR
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> 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')<TRUNC(SYSDATE@!))
13 - filter("MAN_PRODUCT"."ID"="A"."PRODUCT_ID" AND "MAN_DEALER"."ID"="A"."SALER_ORGID" AND
"MAN_BUYER"."ID"="A"."BUYER_ORGID")
15 - 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')<TRUNC(SYSDATE@!))
16 - filter("ORD_ORDER_ITEM_CEN"."BUYER_ORGID"="MAN_BUYER"."ID" AND
"ORD_ORDER_ITEM_CEN"."SALER_ORGID"="MAN_DEALER"."ID" AND
"ORD_ORDER_ITEM_CEN"."PRODUCT_ID"="MAN_PRODUCT"."ID" AND
"ORD_ORDER_ITEM_CEN"."CREATE_DATE">=TO_DATE('2004-01-01 00:00:00', 'yyyy-mm-dd hh24:mi:ss') AND
"ORD_ORDER_ITEM_CEN"."CREATE_DATE"<TRUNC(SYSDATE@!))
18 - access("ORD_ORDER_ITEM_CEN"."PRODUCT_ID"="MAN_PRODUCT"."ID")
19 - access("ORD_ORDER_ITEM_CEN"."SALER_ORGID"="MAN_DEALER"."ID")
20 - 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')<TRUNC(SYSDATE@!))
21 - filter("ORD_ORDER_ITEM_ZJ"."BUYER_ORGID"="MAN_BUYER"."ID" AND
"ORD_ORDER_ITEM_ZJ"."SALER_ORGID"="MAN_DEALER"."ID" AND
"ORD_ORDER_ITEM_ZJ"."CREATE_DATE">=TO_DATE('2004-01-01 00:00:00', 'yyyy-mm-dd hh24:mi:ss') AND
"ORD_ORDER_ITEM_ZJ"."CREATE_DATE"<TRUNC(SYSDATE@!))
22 - access("ORD_ORDER_ITEM_ZJ"."PRODUCT_ID"="MAN_PRODUCT"."ID")

Note: cpu costing is off

54 rows selected.
晕倒，怎么会产生一个这样的执行计划。不看别的，只看上面两个MERGE JOIN CARTESIAN就已经足够了。
这下总算明白系统中为什么拼命在等待LATCH FREE了。Oracle按照这个执行计划执行，不知道需要多大的内存来容纳中间结果集，所以只能不停的将中间结果装入内存，然后清空内存，一直不断的持续这个过程。
明白了系统目前的运行状况，那么Oracle为什么会产生这种恐怖的执行计划呢？从执行计划信息上看，使用的CBO，Oracle不会无缘无故采用这种执行计划的。
首先怀疑的是统计信息出现了偏差。
SQL> SELECT TABLE_NAME, NUM_ROWS FROM USER_TABLES
2 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> EXEC DBMS_STATS.GATHER_TABLE_STATS(USER, 'MAN_PRODUCT', CASCADE => TRUE)
PL/SQL procedure successfully completed.
SQL> EXPLAIN PLAN FOR
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> 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')<TRUNC(SYSDATE@!))
4 - access("MAN_PRODUCT"."ID"="A"."PRODUCT_ID")
7 - 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')<TRUNC(SYSDATE@!))
9 - access("ORD_ORDER_ITEM_CEN"."CREATE_DATE">=TO_DATE('2004-01-01 00:00:00', 'yyyy-mm-dd hh24:mi:ss') AND
"ORD_ORDER_ITEM_CEN"."CREATE_DATE"<TRUNC(SYSDATE@!))
10 - 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')<TRUNC(SYSDATE@!))
12 - access("ORD_ORDER_ITEM_ZJ"."CREATE_DATE">=TO_DATE('2004-01-01 00:00:00', 'yyyy-mm-dd hh24:mi:ss') AND
"ORD_ORDER_ITEM_ZJ"."CREATE_DATE"<TRUNC(SYSDATE@!))
14 - access("MAN_BUYER"."ID"="A"."BUYER_ORGID")
15 - access("MAN_DEALER"."ID"="A"."SALER_ORGID")

Note: cpu costing is off

40 rows selected.
SQL> 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以前过多次，都是正常的，所以没有想到执行计划会发生那么大的变化。因此，一直从第一方面着手来诊断问题。所幸殊途同归，虽然绕了一个大圈子，最终还是找到问题的所在。

参考至:http://yangtingkun.itpub.net/post/468/273340