在测试环境中，可能一个测试库中会有几十上百套环境在运行，一般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 SETCL1_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 200col event format a30col sql_text format a50set pages 50select distinct s.sql_id,s.sid,se.event,se.TOTAL_WAITS,sa.sql_textfrom v$session s left join v$session_event se on s.sid=se.sidleft join v$sqlarea saon s.sql_id=sa.sql_idwhere sa.SQL_TEXT is not nulland 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“的。这个问题就能说明原因了。SID_SERIAL ORACLE_USERN OBJECT_NAME LOGON_TIM SEC_WAIT OSUSER MACHINE PROGRAM STATE STATUS LOCK_ MODE_HELD1357778 xxxxxxxx xxxxxxxx JDBC Thin Client WAITING ACTIVE DML Row-X (SX)1357778 xxxxxxxx xxxxxxxx JDBC Thin Client WAITING ACTIVE DML Row-X (SX)1357777 xxxxxxxx xxxxxxxx JDBC Thin Client WAITING ACTIVE DML Row-X (SX)1357774 xxxxxxxx xxxxxxxx JDBC Thin Client WAITING ACTIVE DML Row-X (SX)1357293 xxxxxxxx xxxxxxxx JDBC Thin Client WAITING ACTIVE DML Row-X (SX)1519 IS BLOCKING 3030,82531519 IS BLOCKING 4353,2389可以从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 Details380 IS BLOCKING 3030,8253380 IS BLOCKING 4353,2389380 IS BLOCKING 4538,221380 IS BLOCKING 4921,483380 IS BLOCKING 7375,14169做了确认，kill掉，操作完成之后发现这个问题就修复了。那几个active的session很快就处理了，这个时候结果似乎已经不重要了。这个案例带给我们的启示就是任何细小的问题都放大都可能造成很严重的影响，有些问题我们关注就会及时处理，有些问题忽略或者疏忽就会不断膨胀，成为一个大麻烦。DBA也需要在这个过程中去取舍，不断调整自己的状态，主动发现问题还相比于得到反馈来说要更加从容。