首页 » ORACLE 9i-23ai » Troubleshooting Performance Oracle SQL high buffer_gets and large temp usage分析思路

Troubleshooting Performance Oracle SQL high buffer_gets and large temp usage分析思路

最近一证券客户反馈一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 —

打赏

, ,

对不起,这篇文章暂时关闭评论。