在批判国产数据库的时候，大家往往会提到SQL执行不稳定，同一条SQL，相同的数据，相同的执行计划，有时候10毫米，有时候几百毫秒。实际上这是所有数据库的通病，在MySQL上，这种情况是很常见的，甚至在Oracle上也很难避免此类问题的发生。只不过在Oracle数据库上，出现SQL执行毛刺的比例比其他数据库低一些而已。在一般的业务系统上，偶发性的SQL执行效率下降影响不大，因此大家也很少去关注。前些年发现这个问题的主要行业是券商，因为某条原本很快的SQL偶然执行变慢，可能引发一笔交易延时过大。这些年券商的核心交易都已经和关系型数据库解耦，此类问题对券商交易的影响已经微乎其微了，因此这些问题也没人关注了。随着银联、网联等对银行服务质量的监管越来越严格，最近两年，银行关注这方面的问题更多一些。
前几天一个客户说他们有套核心业务系统，某条INSERT语句，单行插入一张60多个字段的表，经常会出现单次执行超过1秒钟的情况。听到这个消息，我第一觉得是不大可能，这套核心系统运维得还是不错的，存储也升级为全闪了，负载并不高，每秒钟高峰期也不过1000笔交易。数据库监控是通过普通的TOP SQL采集手段，看到的都是平均值，很难发现某条SQL单次执行异常的情况。他们是通过核心业务超时的应用日志发现问题后，才排查到这个问题的。于是他们通过对ASH的内存采用数据进行分析，发现了这个问题。分析的脚本如下，大家有兴趣可以去自己的系统中做个检查。
select SAMPLE_TIME,
SAMPLE_TIME-SQL_EXEC_START,
SESSION_ID,
IS_SQLID_CURRENT,
SQL_EXEC_ID,
TIME_MODEL,
SESSION_STATE
from v$active_session_history
where
sample_time between
to_date('2024-07-02 14:20:00','yyyy-mm-dd hh24:mi:ss')
and
to_date('2024-07-02 14:50:00','yyyy-mm-dd hh24:mi:ss')
and SQL_ID='bhdvtsvjhgvrh'
and IS_SQLID_CURRENT=’Y’
and (SAMPLE_TIME-SQL_EXEC_START) is not null
and (SAMPLE_TIME-SQL_EXEC_START)> interval '1' second
order by SQL_EXEC_ID,SAMPLE_TIME ASC;采用v$active_session_history的sample_time和SQL_EXEC_START的时间差来粗略估算某条SQL在某个时间段内每次执行的时间，是一种用来分析SQL执行时长偶发性过大的一种常用方法。其原理是如果采样时IS_SQLID_CURRENT=’Y’，说明采样时该SQL还在执行，而如果SQL_EXEC_START的时间比采样时间早X秒以上，那么我们可以怀疑这条SQL的执行时间超过X秒。
图片
我在自己的测试环境中测试了一下脚本，我自己的环境中，一条比较简单的SQL语句居然也出现了类似的情况，执行时长可能超过1秒。这让我感到不可思议，这条SQL的平均执行时长也就是100毫秒左右。后来经过仔细研究才发现，原来是SQL_EXEC_START和SAMPLE_TIME之间存在精度的差异，SQL_EXEC_START是DATE类型的，精度只到秒，实际的执行时间并没有1秒+那么离谱。Oracle的这个SQL_EXEC_START精度问题，实际上以前也有用户给O记建言过希望能优化，不过因为这个指标存在的历史太悠久了，动起来对内核代码影响较大，另外有此需求的用户不多，O记也没有采纳用户的建议。
这让我想起了前阵子遇到过的另外一个案例，一个客户主从机房切换后，从他们的ZABBIX监控系统上看，LOG FILE SYNC从1毫米增加到2毫秒，居然翻了一倍。后来我们在D-SMART里分析了这个指标，发现原来切换前是1.4毫秒，切换后变成1.6毫秒了。在ZABBIX中被四舍五入，就出现了这种情况了。
实际上抛掉精度误差，某些SQL执行的毛刺还是存在的，而且毛刺也并不小，对于某条SQL而言，偶尔的执行时间可能是平均值的数倍甚至数十倍。这种毛刺可能对于一般的系统问题不大，而对于一些关键的交易系统来说，是必须尽可能避免的。从这个案例上，我也看到了传统的TOP SQL监控的缺陷，被平均的TOP SQL统计信息只能发现那些明显存在问题的情况，无法发现执行毛刺的问题。
对于等待事件，其实也存在类似的问题，某个等待事件可能偶尔会比较高，甚至高于平均值的上百倍。Oracle为了能让运维人员了解到这种毛刺情况，在OWI接口中提供了等待事件直方图的信息。不过出于性能考虑，Oracle无法对SQL也提供类似的直方图数据，这让需要关注SQL执行毛刺的用户缺乏监控的手段。
今天我们讨论的这个方法，因为对减的字段的精度不同，对于执行时间很短的SQL实际上监控误差是很大的，以前我们主要是用这种方法来分析一些执行时间为几秒钟到几百秒钟的SQL毛刺问题。
确认SQL执行确实存在毛刺问题后，我们在生产环境中对这条SQL进行了更细致的排查，想通过分析其等待事件来分析出现毛刺的原因，不过我们发现大多数超时的SQL都没有等待事件，是ON CPU的，这种情况后续的排查工作会更加复杂了。需要通过大量的指标数据去做对应分析。如果客户已经部署了D-SMART，那么我们还可以通过关联性分析等工具去对系统采集到的近600个指标做自动分析，从而发现一些蛛丝马迹。客户日常并没有采集这些数据，仅仅依靠AWR报告和ASH报告可能还不一定能够定位异常。这个CASE我会继续跟踪，如果到时候有所发现，会和大家分享。如果大家遇到过类似的案例，也可以留言给我一些建议。
在本文的最后，我给大家分享一个多年前收集来的一个分析脚本。用来做单SQL执行毛刺的分析，还是挺不错的。
图片
上面是执行结果的一个例子，输入SQL_ID就可以获得分析结果。有兴趣的朋友可以把后面的SQL记录一下。
set lines 300
SET PAGES 1000
col sql_exec_start format a30
col run_time_timestamp format a30
col sql_id format a20 trunc
select sql_id,
sql_exec_id,
sql_plan_hash_value,
CAST(sql_exec_start AS TIMESTAMP) sql_exec_start,
run_time run_time_timestamp,
(EXTRACT(HOUR FROM run_time) * 3600
+ EXTRACT(MINUTE FROM run_time) * 60
+ EXTRACT(SECOND FROM run_time)) run_time_sec,
round(temp/1024/1024,2) temp_mb,
round(pga/1024/1024,2) pga_mb,
round(rbytes/1024/1024,2) read_mb,
round(wbytes/1024/1024,2) write_mb,
riops,
wiops
from (
select
sql_id,
sql_exec_id,
sql_plan_hash_value,
max(sql_exec_start) sql_exec_start,
max(sample_time - sql_exec_start) run_time,
max(TEMP_SPACE_ALLOCATED) temp,
max(PGA_ALLOCATED) pga,
max(DELTA_READ_IO_BYTES) rbytes,
max(DELTA_READ_IO_REQUESTS) riops,
max(DELTA_WRITE_IO_BYTES) wbytes,
max(DELTA_WRITE_IO_REQUESTS) wiops
from
v$active_session_history
where sql_id = '&&sql_id.'
and sql_exec_start is not null
group by sql_id,sql_exec_id,sql_plan_hash_value
order by sql_exec_start desc
)
where rownum < 50
order by 1, sql_exec_start asc
/
