一條簡單的sql語句執行15天的原因分析
在測試環境中，可能一個測試庫中會有幾十上百套環境在執行，一般DBA不會去主動干涉測試環境中的一些使用細節，可能問題都是開發測試來反饋給DBA採取做一個被動的處理。今天也算主動了一把，在測試環境中發現了一個大案。
首先透過ash檢視了下正在執行的session情況,可以很明顯看到有幾條sql語句竟然已經執行了15天，沒錯不是15個小時，是15天。
對於這種情況，很讓人有一種立馬出手的衝動。不過先來看看問題，已經15天了，也不在這幾分鐘著急了。
> ksh getash.sh
I SID SER# USERNAME OSUSER STA RPID SPID MACHINE PROGRAM ELAP_SEC TEMP_MB UNDO_MB SQL_ID TSPS SQL
-- ------ ------ ------------ ---------- --- ------- ------ ---------- -------------------- ----------- ------- ------- ------------- ------ -------------------------------------------------
1 3030 8253 xxxx xxxxxxxx ACT 1234 19645 testser JDBC Thin Client 15 16:54:42 dch8sxwt6ujvc /* CL_ProcessController_updateProcessById_2 */ UP
1 4353 2389 xxxx xxxxxxxx ACT 1234 7945 testser JDBC Thin Client 15 16:54:42 dch8sxwt6ujvc /* CL_ProcessController_updateProcessById_2 */ UP
1 4921 483 xxxx xxxxxxxx ACT 1234 29822 testser JDBC Thin Client 15 16:54:42 dch8sxwt6ujvc /* CL_ProcessController_updateProcessById_2 */ UP
1 7375 14169 xxxx xxxxxxxx ACT 1234 4290 testser JDBC Thin Client 15 16:54:39 dch8sxwt6ujvc /* CL_ProcessController_updateProcessById_2 */ UP
1 4538 221 xxxx xxxxxxxx ACT 1234 17126 testser JDBC Thin Client 15 16:46:38 dch8sxwt6ujvc /* CL_ProcessController_updateProcessById_2 */ UP
1 957 17975 xxxx xxxxxxxx ACT 16397 18807 testser rman@xxxx (TNS V 00 00:00:11 0004568 STARTED62,
1 2277 47527 xxxx xxxxxxxx ACT 17531 17748 testser rman@xxxx (TNS V 00 00:00:02 0003367 STARTED62,
1 3790 34667 xxxx xxxxxxxx ACT 32656 32658 testser sqlplus@xxxx (TN 00 00:00:01 4k5y59ywjtuhs SELECT /* use_hash(sess,proc,undo,tmp) use_nl(s)*
首先讓我好奇的是這麼長時間的語句，是不是表裡的資料量太多了，執行計劃出現了很大的效能問題？之前碰到過幾次語句問題導致sql執行了好幾天的情況，帶著疑問來看了下對應的sql語句，是一個簡單的update操作。
SQL_ID dch8sxwt6ujvc, child number 0
-------------------------------------
/* CL_ProcessController_updateProcessById_2 */ UPDATE CL1_PROC_CTRL SET
CL1_PROC_CTRL.PROC_CTRL_ID = :1 , CL1_PROC_CTRL.HEARTBEAT = :2 ,
CL1_PROC_CTRL.STATUS = :3 , CL1_PROC_CTRL.PROC_TYPE = :4 , OPERATOR_ID
= :5 , APPLICATION_ID = :6 , DL_SERVICE_CODE = :7 , DL_UPDATE_STAMP =
:8 , SYS_UPDATE_DATE = SYSDATE WHERE PROC_CTRL_ID = :9
看來核心因素就聚集在表CL1_PROC_CTRL 上了，這是個什麼級別的表，是不是資料太多了啊。一查讓我大吃一驚，不是資料多，而是隻有5條資料。
檢視執行計劃一看也是無可挑剔的。
-----------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost |
-----------------------------------------------------------------------
| 0 | UPDATE STATEMENT | | | | 1 |
| 1 | UPDATE | CL1_PROC_CTRL | | | |
|* 2 | INDEX UNIQUE SCAN| CL1_PROC_CTRL_PK | 1 | 47 | 1 |
-----------------------------------------------------------------------
好了問題到了這，很多人已經猜出問題所在了，我就繼續賣個關子，機會難得，來先看看等待事件吧，這種情況下看等待事件還是一個很有效的方式,直接關聯v$session_event來檢視。
set linesize 200
col event format a30
col sql_text format a50
set pages 50
select distinct s.sql_id,s.sid,se.event,se.TOTAL_WAITS,sa.sql_text
from v$session s left join v$session_event se
on s.sid=se.sid
left join v$sqlarea sa
on s.sql_id=sa.sql_id
where sa.SQL_TEXT is not null
and sa.sql_id='dch8sxwt6ujvc'
order by se.total_waits desc;
SQL_ID SID EVENT TOTAL_WAITS
------------- ---------- ------------------------------ -----------
dch8sxwt6ujvc 4538 SQL*Net message from client 7371
dch8sxwt6ujvc 4538 SQL*Net message to client 7371
dch8sxwt6ujvc 3030 SQL*Net message from client 3634
dch8sxwt6ujvc 3030 SQL*Net message to client 3634
dch8sxwt6ujvc 7375 SQL*Net message from client 1398
dch8sxwt6ujvc 7375 SQL*Net message to client 1398
dch8sxwt6ujvc 4353 SQL*Net message from client 1386
dch8sxwt6ujvc 4353 SQL*Net message to client 1386
dch8sxwt6ujvc 4921 SQL*Net message to client 1318
dch8sxwt6ujvc 4921 SQL*Net message from client 1318
dch8sxwt6ujvc 4538 log file sync 1111
dch8sxwt6ujvc 3030 log file sync 908
dch8sxwt6ujvc 4538 SQL*Net more data to client 704
dch8sxwt6ujvc 4538 direct path read 661
dch8sxwt6ujvc 7375 log file sync 349
dch8sxwt6ujvc 4353 log file sync 346
dch8sxwt6ujvc 4921 log file sync 329
dch8sxwt6ujvc 4538 db file sequential read 191
dch8sxwt6ujvc 4538 Disk file operations I/O 19
dch8sxwt6ujvc 4353 db file sequential read 5
dch8sxwt6ujvc 3030 db file sequential read 5
dch8sxwt6ujvc 4353 Disk file operations I/O 4
dch8sxwt6ujvc 3030 Disk file operations I/O 4
dch8sxwt6ujvc 4921 Disk file operations I/O 4
dch8sxwt6ujvc 7375 Disk file operations I/O 4
dch8sxwt6ujvc 4921 db file sequential read 3
dch8sxwt6ujvc 7375 db file sequential read 2
dch8sxwt6ujvc 4538 db file scattered read 2
dch8sxwt6ujvc 4921 enq: TX - row lock contention 1
dch8sxwt6ujvc 4538 enq: TX - row lock contention 1
dch8sxwt6ujvc 3030 enq: TX - row lock contention 1
dch8sxwt6ujvc 7375 enq: TX - row lock contention 1
dch8sxwt6ujvc 4353 enq: TX - row lock contention 1
可以從top等待事件中看出，時間都基本在“SQL*Net message from clien”和“SQL*Net message to client"，這些等待事件對於這個問題似乎說明不了什麼細節的問題，繼續往下看，關鍵在於最後的幾個等待事件，是關於”enq: TX - row lock contention“的。這個問題就能說明原因了。
繞了一個圈子，我們來看看v$lock中的明細資訊。可以很清晰的看出，等待的時間確實是很長了。
SID_SERIAL ORACLE_USERN OBJECT_NAME LOGON_TIM SEC_WAIT OSUSER MACHINE PROGRAM STATE STATUS LOCK_ MODE_HELD
------------ ------------ ------------------------- --------- --------- ---------- ------------ -------------------- ---------- ---------- ----- ----------
4921,483 XXXXXXXX CL1_PROC_CTRL 08-APR-15 1357778 xxxxxxxx xxxxxxxx JDBC Thin Client WAITING ACTIVE DML Row-X (SX)
3030,8253 XXXXXXXX CL1_PROC_CTRL 08-APR-15 1357778 xxxxxxxx xxxxxxxx JDBC Thin Client WAITING ACTIVE DML Row-X (SX)
4353,2389 XXXXXXXX CL1_PROC_CTRL 08-APR-15 1357777 xxxxxxxx xxxxxxxx JDBC Thin Client WAITING ACTIVE DML Row-X (SX)
7375,14169 XXXXXXXX CL1_PROC_CTRL 08-APR-15 1357774 xxxxxxxx xxxxxxxx JDBC Thin Client WAITING ACTIVE DML Row-X (SX)
4538,221 XXXXXXXX CL1_PROC_CTRL 08-APR-15 1357293 xxxxxxxx xxxxxxxx JDBC Thin Client WAITING ACTIVE DML Row-X (SX)
Blocking Session Details
1519 IS BLOCKING 3030,8253
1519 IS BLOCKING 4353,2389
1519 IS BLOCKING 4538,221
1519 IS BLOCKING 4921,483
1519 IS BLOCKING 7375,14169
可以從blocking session中看出，這個罪魁禍首的session是1519的session.
我們來看看這個session,狀態是inactive的，登入時間是半個月之前了。
SID SERIAL# USERNAME OSUSER MACHINE PROCESS TERMINAL TYPE LOGIN_TIME STATUS
---------- ---------- --------------- --------------- -------------------- --------------- --------------- ---------- ------------------- --------
1519 995 XXXXXXX XXXXXXX XXXXXXX 1234 unknown USER 2015-04-08 17:19:08 INACTIVE
看來這個session是由於某種原因沒有正常終止，導致剩下的幾個session都掛在這個點上了。把這個問題放大，就是15天，從測試的反饋來看似乎這個環境也沒有用到，所以沒有得到任何反饋。
我還是和對應的team做個簡單的溝通為好，然後就開始kill掉這個session.
SQL> alter system kill session '1519,995';
System altered.
kill的過程很快，再次檢視v$lock中的等待哪些session等待就正常了，但是檢視ash的時候發現這幾個session還是存在，在blocking session的內容中，發現出現了一個新的session 380,這個session是今天建立的，看來和我kill的操作也有一定關聯。
Blocking Session Details
380 IS BLOCKING 3030,8253
380 IS BLOCKING 4353,2389
380 IS BLOCKING 4538,221
380 IS BLOCKING 4921,483
380 IS BLOCKING 7375,14169
做了確認，kill掉，操作完成之後發現這個問題就修復了。那幾個active的session很快就處理了，這個時候結果似乎已經不重要了。
這個案例帶給我們的啟示就是任何細小的問題都放大都可能造成很嚴重的影響，有些問題我們關注就會及時處理，有些問題忽略或者疏忽就會不斷膨脹，成為一個大麻煩。DBA也需要在這個過程中去取捨，不斷調整自己的狀態，主動發現問題還相比於得到反饋來說要更加從容。
首先透過ash檢視了下正在執行的session情況,可以很明顯看到有幾條sql語句竟然已經執行了15天，沒錯不是15個小時，是15天。
對於這種情況，很讓人有一種立馬出手的衝動。不過先來看看問題，已經15天了，也不在這幾分鐘著急了。
> ksh getash.sh
I SID SER# USERNAME OSUSER STA RPID SPID MACHINE PROGRAM ELAP_SEC TEMP_MB UNDO_MB SQL_ID TSPS SQL
-- ------ ------ ------------ ---------- --- ------- ------ ---------- -------------------- ----------- ------- ------- ------------- ------ -------------------------------------------------
1 3030 8253 xxxx xxxxxxxx ACT 1234 19645 testser JDBC Thin Client 15 16:54:42 dch8sxwt6ujvc /* CL_ProcessController_updateProcessById_2 */ UP
1 4353 2389 xxxx xxxxxxxx ACT 1234 7945 testser JDBC Thin Client 15 16:54:42 dch8sxwt6ujvc /* CL_ProcessController_updateProcessById_2 */ UP
1 4921 483 xxxx xxxxxxxx ACT 1234 29822 testser JDBC Thin Client 15 16:54:42 dch8sxwt6ujvc /* CL_ProcessController_updateProcessById_2 */ UP
1 7375 14169 xxxx xxxxxxxx ACT 1234 4290 testser JDBC Thin Client 15 16:54:39 dch8sxwt6ujvc /* CL_ProcessController_updateProcessById_2 */ UP
1 4538 221 xxxx xxxxxxxx ACT 1234 17126 testser JDBC Thin Client 15 16:46:38 dch8sxwt6ujvc /* CL_ProcessController_updateProcessById_2 */ UP
1 957 17975 xxxx xxxxxxxx ACT 16397 18807 testser rman@xxxx (TNS V 00 00:00:11 0004568 STARTED62,
1 2277 47527 xxxx xxxxxxxx ACT 17531 17748 testser rman@xxxx (TNS V 00 00:00:02 0003367 STARTED62,
1 3790 34667 xxxx xxxxxxxx ACT 32656 32658 testser sqlplus@xxxx (TN 00 00:00:01 4k5y59ywjtuhs SELECT /* use_hash(sess,proc,undo,tmp) use_nl(s)*
首先讓我好奇的是這麼長時間的語句，是不是表裡的資料量太多了，執行計劃出現了很大的效能問題？之前碰到過幾次語句問題導致sql執行了好幾天的情況，帶著疑問來看了下對應的sql語句，是一個簡單的update操作。
SQL_ID dch8sxwt6ujvc, child number 0
-------------------------------------
/* CL_ProcessController_updateProcessById_2 */ UPDATE CL1_PROC_CTRL SET
CL1_PROC_CTRL.PROC_CTRL_ID = :1 , CL1_PROC_CTRL.HEARTBEAT = :2 ,
CL1_PROC_CTRL.STATUS = :3 , CL1_PROC_CTRL.PROC_TYPE = :4 , OPERATOR_ID
= :5 , APPLICATION_ID = :6 , DL_SERVICE_CODE = :7 , DL_UPDATE_STAMP =
:8 , SYS_UPDATE_DATE = SYSDATE WHERE PROC_CTRL_ID = :9
看來核心因素就聚集在表CL1_PROC_CTRL 上了，這是個什麼級別的表，是不是資料太多了啊。一查讓我大吃一驚，不是資料多，而是隻有5條資料。
檢視執行計劃一看也是無可挑剔的。
-----------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost |
-----------------------------------------------------------------------
| 0 | UPDATE STATEMENT | | | | 1 |
| 1 | UPDATE | CL1_PROC_CTRL | | | |
|* 2 | INDEX UNIQUE SCAN| CL1_PROC_CTRL_PK | 1 | 47 | 1 |
-----------------------------------------------------------------------
好了問題到了這，很多人已經猜出問題所在了，我就繼續賣個關子，機會難得，來先看看等待事件吧，這種情況下看等待事件還是一個很有效的方式,直接關聯v$session_event來檢視。
set linesize 200
col event format a30
col sql_text format a50
set pages 50
select distinct s.sql_id,s.sid,se.event,se.TOTAL_WAITS,sa.sql_text
from v$session s left join v$session_event se
on s.sid=se.sid
left join v$sqlarea sa
on s.sql_id=sa.sql_id
where sa.SQL_TEXT is not null
and sa.sql_id='dch8sxwt6ujvc'
order by se.total_waits desc;
SQL_ID SID EVENT TOTAL_WAITS
------------- ---------- ------------------------------ -----------
dch8sxwt6ujvc 4538 SQL*Net message from client 7371
dch8sxwt6ujvc 4538 SQL*Net message to client 7371
dch8sxwt6ujvc 3030 SQL*Net message from client 3634
dch8sxwt6ujvc 3030 SQL*Net message to client 3634
dch8sxwt6ujvc 7375 SQL*Net message from client 1398
dch8sxwt6ujvc 7375 SQL*Net message to client 1398
dch8sxwt6ujvc 4353 SQL*Net message from client 1386
dch8sxwt6ujvc 4353 SQL*Net message to client 1386
dch8sxwt6ujvc 4921 SQL*Net message to client 1318
dch8sxwt6ujvc 4921 SQL*Net message from client 1318
dch8sxwt6ujvc 4538 log file sync 1111
dch8sxwt6ujvc 3030 log file sync 908
dch8sxwt6ujvc 4538 SQL*Net more data to client 704
dch8sxwt6ujvc 4538 direct path read 661
dch8sxwt6ujvc 7375 log file sync 349
dch8sxwt6ujvc 4353 log file sync 346
dch8sxwt6ujvc 4921 log file sync 329
dch8sxwt6ujvc 4538 db file sequential read 191
dch8sxwt6ujvc 4538 Disk file operations I/O 19
dch8sxwt6ujvc 4353 db file sequential read 5
dch8sxwt6ujvc 3030 db file sequential read 5
dch8sxwt6ujvc 4353 Disk file operations I/O 4
dch8sxwt6ujvc 3030 Disk file operations I/O 4
dch8sxwt6ujvc 4921 Disk file operations I/O 4
dch8sxwt6ujvc 7375 Disk file operations I/O 4
dch8sxwt6ujvc 4921 db file sequential read 3
dch8sxwt6ujvc 7375 db file sequential read 2
dch8sxwt6ujvc 4538 db file scattered read 2
dch8sxwt6ujvc 4921 enq: TX - row lock contention 1
dch8sxwt6ujvc 4538 enq: TX - row lock contention 1
dch8sxwt6ujvc 3030 enq: TX - row lock contention 1
dch8sxwt6ujvc 7375 enq: TX - row lock contention 1
dch8sxwt6ujvc 4353 enq: TX - row lock contention 1
可以從top等待事件中看出，時間都基本在“SQL*Net message from clien”和“SQL*Net message to client"，這些等待事件對於這個問題似乎說明不了什麼細節的問題，繼續往下看，關鍵在於最後的幾個等待事件，是關於”enq: TX - row lock contention“的。這個問題就能說明原因了。
繞了一個圈子，我們來看看v$lock中的明細資訊。可以很清晰的看出，等待的時間確實是很長了。
SID_SERIAL ORACLE_USERN OBJECT_NAME LOGON_TIM SEC_WAIT OSUSER MACHINE PROGRAM STATE STATUS LOCK_ MODE_HELD
------------ ------------ ------------------------- --------- --------- ---------- ------------ -------------------- ---------- ---------- ----- ----------
4921,483 XXXXXXXX CL1_PROC_CTRL 08-APR-15 1357778 xxxxxxxx xxxxxxxx JDBC Thin Client WAITING ACTIVE DML Row-X (SX)
3030,8253 XXXXXXXX CL1_PROC_CTRL 08-APR-15 1357778 xxxxxxxx xxxxxxxx JDBC Thin Client WAITING ACTIVE DML Row-X (SX)
4353,2389 XXXXXXXX CL1_PROC_CTRL 08-APR-15 1357777 xxxxxxxx xxxxxxxx JDBC Thin Client WAITING ACTIVE DML Row-X (SX)
7375,14169 XXXXXXXX CL1_PROC_CTRL 08-APR-15 1357774 xxxxxxxx xxxxxxxx JDBC Thin Client WAITING ACTIVE DML Row-X (SX)
4538,221 XXXXXXXX CL1_PROC_CTRL 08-APR-15 1357293 xxxxxxxx xxxxxxxx JDBC Thin Client WAITING ACTIVE DML Row-X (SX)
Blocking Session Details
1519 IS BLOCKING 3030,8253
1519 IS BLOCKING 4353,2389
1519 IS BLOCKING 4538,221
1519 IS BLOCKING 4921,483
1519 IS BLOCKING 7375,14169
可以從blocking session中看出，這個罪魁禍首的session是1519的session.
我們來看看這個session,狀態是inactive的，登入時間是半個月之前了。
SID SERIAL# USERNAME OSUSER MACHINE PROCESS TERMINAL TYPE LOGIN_TIME STATUS
---------- ---------- --------------- --------------- -------------------- --------------- --------------- ---------- ------------------- --------
1519 995 XXXXXXX XXXXXXX XXXXXXX 1234 unknown USER 2015-04-08 17:19:08 INACTIVE
看來這個session是由於某種原因沒有正常終止，導致剩下的幾個session都掛在這個點上了。把這個問題放大，就是15天，從測試的反饋來看似乎這個環境也沒有用到，所以沒有得到任何反饋。
我還是和對應的team做個簡單的溝通為好，然後就開始kill掉這個session.
SQL> alter system kill session '1519,995';
System altered.
kill的過程很快，再次檢視v$lock中的等待哪些session等待就正常了，但是檢視ash的時候發現這幾個session還是存在，在blocking session的內容中，發現出現了一個新的session 380,這個session是今天建立的，看來和我kill的操作也有一定關聯。
Blocking Session Details
380 IS BLOCKING 3030,8253
380 IS BLOCKING 4353,2389
380 IS BLOCKING 4538,221
380 IS BLOCKING 4921,483
380 IS BLOCKING 7375,14169
做了確認，kill掉，操作完成之後發現這個問題就修復了。那幾個active的session很快就處理了，這個時候結果似乎已經不重要了。
這個案例帶給我們的啟示就是任何細小的問題都放大都可能造成很嚴重的影響，有些問題我們關注就會及時處理，有些問題忽略或者疏忽就會不斷膨脹，成為一個大麻煩。DBA也需要在這個過程中去取捨，不斷調整自己的狀態，主動發現問題還相比於得到反饋來說要更加從容。
來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/23718752/viewspace-1602001/，如需轉載，請註明出處，否則將追究法律責任。
相關文章
- 一條sql語句的執行過程SQL
- 一條執行了3天的"簡單"的sqlSQL
- 一條簡單SQL語句的構成及語句解析SQL
- 一條update SQL語句是如何執行的SQL
- 一條SQL更新語句是如何執行的SQL
- 一條SQL更新語句是如何執行的？SQL
- 一條更新的SQL語句是如何執行的？SQL
- 一條 SQL 查詢語句是如何執行的？SQL
- 一條SQL語句在MySQL中如何執行的MySql
- 騰訊面試：一條SQL語句執行得很慢的原因有哪些？面試SQL
- 一條sql語句在mysql中是如何執行的MySql
- 一條SQL語句的執行計劃變化探究SQL
- 一條 SQL 語句在 MySQL 中是如何執行的？MySql
- 一條更新語句的執行流程
- 一條簡單的sql語句導致的系統問題SQL
- MyBatis 一次執行多條SQL語句MyBatisSQL
- MySQL日誌（一條sql更新語句是如何執行的）MySql
- 通過分析SQL語句的執行計劃優化SQL語句SQL優化
- 一條簡單的SQL語句優化-新年新氣象SQL優化
- 一條查詢語句的執行流程
- 一條全表掃描sql語句的分析SQL
- 一條sql語句的建議調優分析SQL
- MySQL系列之一條SQL查詢語句的執行過程MySql
- sql語句執行緩慢分析SQL
- 一條SQL語句的執行計劃變化探究（r10筆記第9天）SQL筆記
- 一條"簡單"的sql語句和小兔子買麵包的故事SQL
- sql語句如何執行的SQL
- 執行大的sql語句SQL
- 騰訊面試：一條SQL語句執行得很慢的原因有哪些？---不看後悔系列面試SQL
- 執行一條sql語句都經歷了什麼？SQL
- 執行一條 SQL 語句，期間發生了什麼？SQL
- 一文讀懂一條 SQL 查詢語句是如何執行的SQL
- MySQL：一條更新語句是如何執行的MySql
- 一條執行4秒的sql語句導致的系統問題SQL
- 一句簡單的SQL查詢語句的背後...SQL
- 02 | 日誌系統：一條SQL更新語句是如何執行的？SQL
- 一條SQL語句的書寫SQL
- 一條很 巧妙的 SQL 語句SQL