今天接到开发一个同事的电话,说前端系统那边反馈有一个查询很慢,初步怀疑是有一些并发或者锁之类的问题导致的。
接到问题之后,自己还是带着一些的紧迫感来处理的。
首先查看资源使用情况,使用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进行关注。
接到问题之后,自己还是带着一些的紧迫感来处理的。
首先查看资源使用情况,使用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进行关注。