ANBOB™

最近一证券客户反馈一SQL执行时间突然变长，平时执行2秒，问题时间312秒，并且发现问题时间段的temp表空间使用率耗尽, 十几分钟后问题又消失， SQL的执行计划未改变，但单次执行逻辑读大量增加，同时伴有少数据物理读变化， 几个小时后找到我帮分析一下原因，下面记录一种分析思路.

短时间内时间变化，首先查看系统级负载，可以通过AWR和ASH 报告查看当时的LOAD和Top Event,  Top Event在这半小时的粒度并无大问题,有log file parallel write和CPU，db file xx read此类，但客户反馈是每日股市开盘交易高峰期都这现象， 这半小时的粒度看这类报告可能不足以说明问题，但TOP SQL by CPU和Gets 也可以参考。

注： 因为客户数据敏感性，分析数据无法上传.

系统级粒度无法准备定位SQL效率问题，但客户有明确的SQL——ID，下面从SQL stat查看SQL情况，和问题时间执行SQL的会话执行情况。

1， 分析SQL状态

从dba_hist_sqlstat分析SQL的执行时间消耗, 使用编写的sqlhistory.sql脚本输出，内容部分如下

select	ss.plan_hash_value phv,
	to_char(s.begin_interval_time, 'DD-MON HH24:MI') snap_time,
	ss.instance_number,
	ss.executions_delta execs,
	ss.LOADS_DELTA loads,
	ss.buffer_gets_delta/decode(ss.executions_delta,0,1,ss.executions_delta) lio_per_exec,
	ss.rows_processed_delta/decode(ss.executions_delta,0,1,ss.executions_delta) rows_per_exec,
	ss.disk_reads_delta/decode(ss.executions_delta,0,1,ss.executions_delta) pio_per_exec,
	(ss.cpu_time_delta/1000000)/decode(ss.executions_delta,0,1,ss.executions_delta) cpu_per_exec,
	(ss.elapsed_time_delta/1000000)/decode(ss.executions_delta,0,1,ss.executions_delta) ela_per_exec,
		(ss.IOWAIT_DELTA/1000000)/decode(ss.executions_delta,0,1,ss.executions_delta) IOW_per_exec,
	(ss.CLWAIT_DELTA/1000000)/decode(ss.executions_delta,0,1,ss.executions_delta) CLW_per_exec,
	(ss.APWAIT_DELTA/1000000)/decode(ss.executions_delta,0,1,ss.executions_delta) AQW_per_exec,
	(ss.CCWAIT_DELTA/1000000)/decode(ss.executions_delta,0,1,ss.executions_delta) CCW_per_exec,
	(ss.IO_OFFLOAD_ELIG_BYTES_DELTA)/decode(ss.executions_delta,0,1,ss.executions_delta) off_per_exec
from 	dba_hist_snapshot	s,
	dba_hist_sqlstat	ss
where	ss.dbid = s.dbid
and	ss.instance_number = s.instance_number
and	ss.snap_id = s.snap_id
and	ss.sql_id = '&&V_SQL_ID'
and	ss.executions_delta > 0
and	s.begin_interval_time >= sysdate - :v_nbr_days
order by ss.plan_hash_value, s.snap_id;
clear breaks computes

Note:
AWR问题时间段30分钟的快照内的SQL执行计划相同，因为该客户使用RBO，所以相同的SQL文本执行计划并不会改变，该SQL执行次数为1（平时90次），lio_per_exec 问题时间71,699,426(平时低于289,133)， pio_per_exec为1,302（平时0），cpu_per_exec 为178(平时2),ela_per_exec 为312（平时4），其它像CLW_per_exec和CCW_per_exec等均为0或无差异。最近几天只有上周2的同时段出现了相同问题其它时段均正常。

2, 分析问题时间段的SESSION信息

select inst_id,to_char(SAMPLE_TIME,'yyyymmdd hh24:mi') ,count(*),event,
SQL_EXEC_ID,min(SQL_EXEC_START),max(TEMP_SPACE_ALLOCATED),SQL_PLAN_OPERATION,SQL_PLAN_LINE_ID，SQL_ID
from gv$active_session_history
where samplt_time between xxx and xxx
and sql_id='xxxxxxx'
group by inst_id,to_char(SAMPLE_TIME,'yyyymmdd hh24:mi') ,event,SQL_PLAN_OPERATION,SQL_PLAN_LINE_ID，SQL_ID
order by 2,3 desc;

Note:
注要是找到问题时间执行的该SQL的SESSION及event，SQL开始执行时间，执行计划的操作, 明确了问题时间内只有2个session，且只有一个SQL_EXEC_ID在执行过程中temp_space_allocated逐渐增长从5GB增加到30GB，并且从ASH确认执行了长到8分钟以上，event基本上是null（on cpu or on cpu queue）, SQL_PLAN_OPERATION为SORT.

3， 找到问题时的数据复现问题

create table xxx select * from xxxxx as of timestamp < 上查询的SQL_EXEC_START >

手动执行SQL 改为使用 闪回表。

Note：
客户有尝试闪回到问题时间点的数据， 但使用闪回的表和问题SQL，手动执行也是2秒的时间，所以怀疑是数据库原因导致性能变差，因为依赖的表数据是在实施变化的，且使用了一个状态列，该列有更新， 如何找到问题时的数据，复现这个问题，基本就能排除是数据库系统性能导致执行变慢，而是因为业务数据的差异。

4, SQL文本

select
       count(1) xxcnt
     , to_char(wm_concat(fund_acc**** ||'-'||****t_no)) xfafs
from
       anbob.enxxxxx
where
       record_no         =-1
       and ***_status='2'
and xxxx.

Note:
SQL只是单表的查询， 使用wm_concat做行合并，无绑定变量,所以相同的文本可以排除变量差异导致。

截止到这里我们复现了问题， 虽然总记录数据差异不大，但是***_status=’2’的值在平时和客户最开始闪回的问题时间的数据只有2位数记录， 但使用问题SQL的SESSION事务开始的时间点的数据，发现满足条件的有28万+记录，这就说明了问题的原因。 因为业务数据的变化 在短时间内存在一些问题，剩下的就是相办法去优化业务逻辑或SQL改写，如分批处理数据。

— over —

打赏

微信扫一扫，打赏作者吧～