在批判國產(chǎn)數(shù)據(jù)庫的時(shí)候，大家往往會(huì)提到SQL執(zhí)行不穩(wěn)定，同一條SQL，相同的數(shù)據(jù)，相同的執(zhí)行計(jì)劃，有時(shí)候10毫米，有時(shí)候幾百毫秒。實(shí)際上這是所有數(shù)據(jù)庫的通病，在MySQL上，這種情況是很常見的，甚至在Oracle上也很難避免此類問題的發(fā)生。只不過在Oracle數(shù)據(jù)庫上，出現(xiàn)SQL執(zhí)行毛刺的比例比其他數(shù)據(jù)庫低一些而已。在一般的業(yè)務(wù)系統(tǒng)上，偶發(fā)性的SQL執(zhí)行效率下降影響不大，因此大家也很少去關(guān)注。前些年發(fā)現(xiàn)這個(gè)問題的主要行業(yè)是券商，因?yàn)槟硹l原本很快的SQL偶然執(zhí)行變慢，可能引發(fā)一筆交易延時(shí)過大。這些年券商的核心交易都已經(jīng)和關(guān)系型數(shù)據(jù)庫解耦，此類問題對(duì)券商交易的影響已經(jīng)微乎其微了，因此這些問題也沒人關(guān)注了。隨著銀聯(lián)、網(wǎng)聯(lián)等對(duì)銀行服務(wù)質(zhì)量的監(jiān)管越來越嚴(yán)格，最近兩年，銀行關(guān)注這方面的問題更多一些。

前幾天一個(gè)客戶說他們有套核心業(yè)務(wù)系統(tǒng)，某條INSERT語句，單行插入一張60多個(gè)字段的表，經(jīng)常會(huì)出現(xiàn)單次執(zhí)行超過1秒鐘的情況。聽到這個(gè)消息，我第一覺得是不大可能，這套核心系統(tǒng)運(yùn)維得還是不錯(cuò)的，存儲(chǔ)也升級(jí)為全閃了，負(fù)載并不高，每秒鐘高峰期也不過1000筆交易。數(shù)據(jù)庫監(jiān)控是通過普通的TOP SQL采集手段，看到的都是平均值，很難發(fā)現(xiàn)某條SQL單次執(zhí)行異常的情況。他們是通過核心業(yè)務(wù)超時(shí)的應(yīng)用日志發(fā)現(xiàn)問題后，才排查到這個(gè)問題的。于是他們通過對(duì)ASH的內(nèi)存采用數(shù)據(jù)進(jìn)行分析，發(fā)現(xiàn)了這個(gè)問題。分析的腳本如下，大家有興趣可以去自己的系統(tǒng)中做個(gè)檢查。

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的時(shí)間差來粗略估算某條SQL在某個(gè)時(shí)間段內(nèi)每次執(zhí)行的時(shí)間，是一種用來分析SQL執(zhí)行時(shí)長偶發(fā)性過大的一種常用方法。其原理是如果采樣時(shí)IS_SQLID_CURRENT=’Y’，說明采樣時(shí)該SQL還在執(zhí)行，而如果SQL_EXEC_START的時(shí)間比采樣時(shí)間早X秒以上，那么我們可以懷疑這條SQL的執(zhí)行時(shí)間超過X秒。

圖片

我在自己的測試環(huán)境中測試了一下腳本，我自己的環(huán)境中，一條比較簡單的SQL語句居然也出現(xiàn)了類似的情況，執(zhí)行時(shí)長可能超過1秒。這讓我感到不可思議，這條SQL的平均執(zhí)行時(shí)長也就是100毫秒左右。后來經(jīng)過仔細(xì)研究才發(fā)現(xiàn)，原來是SQL_EXEC_START和SAMPLE_TIME之間存在精度的差異，SQL_EXEC_START是DATE類型的，精度只到秒，實(shí)際的執(zhí)行時(shí)間并沒有1秒+那么離譜。Oracle的這個(gè)SQL_EXEC_START精度問題，實(shí)際上以前也有用戶給O記建言過希望能優(yōu)化，不過因?yàn)檫@個(gè)指標(biāo)存在的歷史太悠久了，動(dòng)起來對(duì)內(nèi)核代碼影響較大，另外有此需求的用戶不多，O記也沒有采納用戶的建議。

這讓我想起了前陣子遇到過的另外一個(gè)案例，一個(gè)客戶主從機(jī)房切換后，從他們的ZABBIX監(jiān)控系統(tǒng)上看，LOG FILE SYNC從1毫米增加到2毫秒，居然翻了一倍。后來我們?cè)贒-SMART里分析了這個(gè)指標(biāo)，發(fā)現(xiàn)原來切換前是1.4毫秒，切換后變成1.6毫秒了。在ZABBIX中被四舍五入，就出現(xiàn)了這種情況了。

實(shí)際上拋掉精度誤差，某些SQL執(zhí)行的毛刺還是存在的，而且毛刺也并不小，對(duì)于某條SQL而言，偶爾的執(zhí)行時(shí)間可能是平均值的數(shù)倍甚至數(shù)十倍。這種毛刺可能對(duì)于一般的系統(tǒng)問題不大，而對(duì)于一些關(guān)鍵的交易系統(tǒng)來說，是必須盡可能避免的。從這個(gè)案例上，我也看到了傳統(tǒng)的TOP SQL監(jiān)控的缺陷，被平均的TOP SQL統(tǒng)計(jì)信息只能發(fā)現(xiàn)那些明顯存在問題的情況，無法發(fā)現(xiàn)執(zhí)行毛刺的問題。

對(duì)于等待事件，其實(shí)也存在類似的問題，某個(gè)等待事件可能偶爾會(huì)比較高，甚至高于平均值的上百倍。Oracle為了能讓運(yùn)維人員了解到這種毛刺情況，在OWI接口中提供了等待事件直方圖的信息。不過出于性能考慮，Oracle無法對(duì)SQL也提供類似的直方圖數(shù)據(jù)，這讓需要關(guān)注SQL執(zhí)行毛刺的用戶缺乏監(jiān)控的手段。

今天我們討論的這個(gè)方法，因?yàn)閷?duì)減的字段的精度不同，對(duì)于執(zhí)行時(shí)間很短的SQL實(shí)際上監(jiān)控誤差是很大的，以前我們主要是用這種方法來分析一些執(zhí)行時(shí)間為幾秒鐘到幾百秒鐘的SQL毛刺問題。

確認(rèn)SQL執(zhí)行確實(shí)存在毛刺問題后，我們?cè)谏a(chǎn)環(huán)境中對(duì)這條SQL進(jìn)行了更細(xì)致的排查，想通過分析其等待事件來分析出現(xiàn)毛刺的原因，不過我們發(fā)現(xiàn)大多數(shù)超時(shí)的SQL都沒有等待事件，是ON CPU的，這種情況后續(xù)的排查工作會(huì)更加復(fù)雜了。需要通過大量的指標(biāo)數(shù)據(jù)去做對(duì)應(yīng)分析。如果客戶已經(jīng)部署了D-SMART，那么我們還可以通過關(guān)聯(lián)性分析等工具去對(duì)系統(tǒng)采集到的近600個(gè)指標(biāo)做自動(dòng)分析，從而發(fā)現(xiàn)一些蛛絲馬跡?？蛻羧粘２]有采集這些數(shù)據(jù)，僅僅依靠AWR報(bào)告和ASH報(bào)告可能還不一定能夠定位異常。這個(gè)CASE我會(huì)繼續(xù)跟蹤，如果到時(shí)候有所發(fā)現(xiàn)，會(huì)和大家分享。如果大家遇到過類似的案例，也可以留言給我一些建議。

在本文的最后，我給大家分享一個(gè)多年前收集來的一個(gè)分析腳本。用來做單SQL執(zhí)行毛刺的分析，還是挺不錯(cuò)的。

圖片

上面是執(zhí)行結(jié)果的一個(gè)例子，輸入SQL_ID就可以獲得分析結(jié)果。有興趣的朋友可以把后面的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
/