長時間latch free等待——記一次系統異常的診斷過程

今天發現一個報表資料庫中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
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.

從這些熱點塊的所屬物件來看，大部分都是那個長時間執行的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以前過多次，都是正常的，所以沒有想到執行計劃會發生那麼大的變化。因此，一直從第一方面著手來診斷問題。所幸殊途同歸，雖然繞了一個大圈子，最終還是找到問題的所在。