在批判國產數據庫的時候，大家往往會提到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
/