一次数据库响应慢的问题诊断(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进行关注。

原文发布于微信公众号 - 杨建荣的学习笔记(jianrong-notes)

原文发表时间:2015-08-25

本文参与腾讯云自媒体分享计划,欢迎正在阅读的你也加入,一起分享。

发表于

我来说两句

0 条评论
登录 后参与评论

相关文章

来自专栏杨建荣的学习笔记

用Oracle的眼光来学习MySQL 5.7的sys(上)(r11笔记第24天)

sys的初衷 MySQL 5.7的sys自从推出以来,整体的反响似乎没有预期的那么高,而我看到这个sys库的时候,第一感觉是越发和Oracle像了,不是...

3759
来自专栏杨建荣的学习笔记

复杂SQL性能优化的剖析(一)(r11笔记第36天)

今天本来是处理一个简单的故障,但是发现是一环套一环,花了我快一天的时间。 开始是早上收到一条报警: 报警内容: CPUutilization is too hi...

36112
来自专栏杨建荣的学习笔记

百倍性能的PL/SQL优化案例(r11笔记第13天)

我相信你是被百倍性能的字样吸引了,不过我所想侧重的是优化的思路,这个比优化技巧更重要,而结果嘛,其实我不希望说成是百倍提升,“”自黑“”一下。 有一个真...

3619
来自专栏全栈工程师成长之路

深入浅出后端开发(MySQL篇)

37718
来自专栏杨建荣的学习笔记

MySQL中的反连接(r12笔记第45天)

关于Oracle的半连接,反连接,我一直认为这是一个能讲很长时间的话题,所以在我的新书《Oracle DBA工作笔记》中讲性能优化的时候,我花了不少的笔墨做...

2695
来自专栏杨建荣的学习笔记

海量数据切分抽取的实践场景(r11笔记第43天)

如果一个大表要抽取数据导出成csv文件,我们有什么策略,如何改进。 一、问题背景 今天开发的同学找到我,他们需要做一个数据统计分析,需要我提供一些支持,把一...

3446
来自专栏数据和云

郑保卫 - 索引优化策略及实战

本文中将要介绍的索引战略方案是以尽可能少的索引来满足尽可能多的数据读取类型的索引构建方法。这个策略方案要求在构建索引时,尽可能多地搜集当前正在使用的未来将要出...

3115
来自专栏杨建荣的学习笔记

一条delete语句的调优(r4笔记第86天)

今天刚上上班,就接到客户的邮件,说生产环境中执行某一条delete sql语句的时间超过了3个小时。最后客户无奈取消了这次数据清理,准备今天在申请时间重做。所以...

3555
来自专栏文渊之博

列存储索引1:初识列存储索引

     2012以后提供了一种不同于传统B树结构的索引类型,就是内存列存储索引。这种索引应用了一种基于列的存储模式,也是一种新的查询执行的批处理模式,并且为特...

2175
来自专栏idba

死锁案例之六

死锁,其实是一个很有意思也很有挑战的技术问题,大概每个DBA和部分开发同学都会在工作过程中遇见 。关于死锁我会持续写一个系列的案例分析,希望能够对想了解死锁的朋...

852

扫码关注云+社区