一条简单的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也需要在这个过程中去取舍，不断调整自己的状态，主动发现问题还相比于得到反馈来说要更加从容。