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

上一篇:互联网企业安全高级指南3.7.3 因地制宜的SDL实践


下一篇:OAuth2.0实战(三)-使用JWT(上)