一次数据库响应慢的问题诊断(r6笔记第39天)

今天接到开发一个同事的电话，说前端系统那边反馈有一个查询很慢，初步怀疑是有一些并发或者锁之类的问题导致的。接到问题之后，自己还是带着一些的紧迫感来处理的。首先查看资源使用情况，使用top来检查，结果发现CPU使用率也不高，都在90%以上的idle 查看数据库的DB time情况，发现数据库的负载其实不高,但是还是有所提高，需要进一步关注。查看锁等待情况，也没有任何的事务和锁等待。查看session的使用情况发现并发量其实很低，TPS的值非常低。

为了进一步验证，抓取了近几个小时的日志归档情况和redo的生成量情况，发现归档基本就是1个小时1次，所以暂时也没有发现异常的活动。这就有些奇怪了。session使用率不高，并发不高，CPU使用率也不高，没有锁等待，redo生成量也不高，到底是怎么回事呢。进一步和开发同时进行沟通，他们反馈说在前端的页面查询会触发一个表的查询，那个表其实也不大，而且在查询中还是使用索引列的，所以查询应该不会有什么问题。但是点击查询的时候就会一直卡在那儿。所以想让我们来看看到底数据库层面发生了什么。首先肯定告诉她的是，数据库的负载和使用率其实并不高，而且并发事务和session使用率也很低，可以基本排除是并发和数据库负载导致的问题。过了几分钟之后，开发给我的反馈是查询有结果了，但是又过了几分钟，又反馈说查询又没有反应了。这种情况下，再次查看资源的使用情况和原来一样，但是他们也想知道可能是什么原因导致的问题，看来常规的思路还是不够快准狠，我们来试试ash快速查询。


SELECT  /* use_hash(sess,proc,undo,tmp) use_nl(s)*/ distinct
         sess.inst_id,
        sess.sid,
        sess.serial#,
         sess.username,
        substr(osuser,1,10) osuser,
        status,
         sess.process,
        proc.spid,
        sess.machine,
         sess.program,
         regexp_substr(NUMTODSINTERVAL(nvl((SYSDATE-SQL_EXEC_START)*24*60*60,last_call_et),  'SECOND'),'+d{2} d{2}:d{2}:d{2}') running_sec,
        TEMP_MB,  UNDO_MB,
        s.sql_id ,
        TSPS.NAME TSPS,
         decode(sess.action,null,'',sess.action||', ')||replace(s.sql_text,chr(13),' ')  sql
FROM
        gv$session sess,
        gv$process proc,
         gv$sql s,
        (select ses_addr as saddr,sum(used_ublk/128) UNDO_MB from  v$transaction group by ses_addr) undo,
        (select session_addr as  saddr, SESSION_NUM serial#, sum((blocks/128)) TEMP_MB from gv$sort_usage group  by  session_addr, SESSION_NUM) tmp,
        (select  inst_id,sid,serial#,event,t.name from gv$session ls, sys.file$ f, sys.ts$ t  where status='ACTIVE' and ls.p1text in ('file number','file#') and ls.p1=f.file#   and f.ts#=t.ts#) tsps
WHERE sess.inst_id=proc.inst_id (+)  
and    sess.saddr=tmp.saddr (+) and sess.serial#=tmp.serial# (+)
AND    sess.status='ACTIVE' and sess.username is not null
and   sess.sid=tsps.sid  (+) and sess.inst_id=tsps.inst_id(+) and sess.serial#=tsps.serial#(+)
AND    sess.paddr=proc.addr (+)
and   sess.sql_id = s.sql_id (+)
and    sess.saddr=undo.saddr (+)
ORDER BY running_sec  desc,4,1,2,3

通过这个语句能够查看到当前数据库中的active session的情况，但是有些遗憾的是只发现了两个active session都在进行有些相似的多表关联查询。当然这个select语句常理是不会阻塞另外一个select语句的，所以也就没有太多的关注，但是和开发人员反反复复排查了几次，发现的规律就是那个查询完成之后，得到的反馈是前端的页面查询马上就正常了。这个时候不得不怀疑是这个查询语句的影响了。数据库负载很低，也不至于一个查询语句就会这么影响全局吧。我也这个发现和开发同事做了反馈，他们也认为应该没有关系。但是逐步的分析，我发现如果这个查询会阻塞另外一个查询，那么只有一个原因，那就是前端的触发的那个select一定是在等待这个复杂的select完成才会触发。它们应该是在一个类似事务的流程之内。如果说是一个事务还是不严谨的，如果是事务，问题就好办了，我们可以通过闪回事务来印证他们是在一个事务的，这个地方实在是无能为力。为了验证这个想法，我把复杂查询对应的用户名，os用户，客户端machine等等明细的信息进行了整理，发现和开发反馈的时间点基本是吻合的，而且它们是从同一个客户端触发的，远程的machine名都是同一个，上下文环境很相似，所以通过这个也可以佐证我的想法了，对于这个问题的进一步分析，为什么那个查询会持续那么长时间，抓取了对应的执行计划，发现相关的几个大表都走了全表扫描。

-------------------------------------------------------------------------------
|  Id  | Operation                        | Name                | Rows  |  Bytes 
-------------------------------------------------------------------------------
|    0 | SELECT STATEMENT                 |                     |       |        
|   1 |  HASH GROUP BY                   |                     |     1 |    332 
|*  2 |   HASH JOIN                      |                     |     1 |    332 
|   3 |    NESTED LOOPS OUTER            |                     |     1  |   300 
|   4 |     NESTED LOOPS                 |                     |      1 |   192 
|   5 |      NESTED LOOPS                |                     |      1 |   174 
|   6 |       TABLE ACCESS FULL          |  M_POOL_TEST         |  2420 | 67760 
|*  7 |       TABLE ACCESS BY INDEX  ROWID| TES_BASE            |     1 |   146 
|*  8 |        INDEX RANGE SCAN           | IND_TES_BASE_AK     |     1 |       
|*  9 |      TABLE ACCESS BY  INDEX ROWID | M_TEST_APP          |     1 |    18 
|* 10 |       INDEX UNIQUE  SCAN          | PK_M_TEST_APP       |     1 |       
|* 11 |     TABLE ACCESS  BY INDEX ROWID  | TES_EXTEND          |     1 |   108 
|* 12 |      INDEX  RANGE SCAN            | IND_TES_EXTEND_RID  |     1 |       
|  13 |     TABLE ACCESS FULL             | M_POOL_TEST_CHANNEL |   398  | 12736

所以后续的分析就是来看看这个查询是否是新增的需求，为什么之前没有碰到这个问题，这两个全表扫描的表都是大表，所以查询时间自然少不了。可以进一步来分析为什么走了全表扫描，怎么尝试来优化sql了。所以数据库负载低，资源使用率低，照样也可能造成响应慢的问题，都需要DBA进行关注。