避坑：一次離奇性能故障的排查與反思
錯(cuò)亂的系統(tǒng)
某客戶(hù)反饋生產(chǎn)庫(kù)ETL及報(bào)表類(lèi)SQL全部運(yùn)行不出來(lái)，監(jiān)控告警近期大量SQL語(yǔ)句執(zhí)行計(jì)劃發(fā)生變更。客戶(hù)DBA通過(guò)對(duì)比新舊執(zhí)行計(jì)劃發(fā)現(xiàn)執(zhí)行計(jì)劃變更的SQL大部分都變成了走索引加上NL的方式，而且不止一個(gè)SQL出現(xiàn)這種問(wèn)題，該生產(chǎn)庫(kù)上幾乎所有的AP類(lèi)型SQL都出現(xiàn)了該問(wèn)題。問(wèn)題到我們這邊前，客戶(hù)已經(jīng)花了數(shù)周時(shí)間做了好幾輪排查，均沒(méi)有效果。
歷史的診斷
全庫(kù)統(tǒng)計(jì)信息排查
DBA排查過(guò)歷史的統(tǒng)計(jì)信息，并重新收集了對(duì)應(yīng)schema的統(tǒng)計(jì)信息，重新收集相關(guān)表、索引的直方圖統(tǒng)計(jì)信息，部分SQL增加了多列統(tǒng)計(jì)信息。每次操作完成后的驗(yàn)證均無(wú)效果，之后回退了以上無(wú)效操作。
綁定部分SQL執(zhí)行計(jì)劃
部分業(yè)務(wù)過(guò)于緊急，約10條SQL臨時(shí)使用SQLPROFILE綁定了執(zhí)行計(jì)劃，針對(duì)綁定的SQL有效，然而執(zhí)行計(jì)劃發(fā)生變更SQL語(yǔ)句數(shù)量過(guò)多，針對(duì)每個(gè)SQL分析執(zhí)行計(jì)劃并綁定，這完全不現(xiàn)實(shí)。
參數(shù)排查
排查了系統(tǒng)參數(shù)optimizer_index_*相關(guān)參數(shù)，均為默認(rèn)值，優(yōu)化器模式為默認(rèn)ALL_ROWS，db_file_multiblock_read_count參數(shù)設(shè)置128，參數(shù)無(wú)異常變更，后檢查包括觸發(fā)器層面、進(jìn)程級(jí)別，均為無(wú)異常參數(shù)調(diào)整。
故障重現(xiàn)
由于客戶(hù)生產(chǎn)上的案例文章中不方便使用真實(shí)數(shù)據(jù)，模擬了以下數(shù)據(jù)：
- create user test identified by test;
- grant dba to test;
- conn test/test
- create table t1 as select * from dba_objects;
- create index test.idx1 on test.t1(OBJECT_ID);
- execute dbms_stats.gather_table_stats(ownname => 'TEST',tabname => 'T1' ,cascade => true,method_opt => 'for all columns size auto');
- update test.t1 set OBJECT_ID=1 where rownum <40000;
- commit;
查詢(xún)數(shù)據(jù)如下，T1表上有8.7W數(shù)據(jù)：
- SQL>
- select count(*) from test.t1 SQL> ;
- COUNT(*)
- ----------
- 87629
簡(jiǎn)單模擬的SQL如下，查詢(xún)OBJECT_ID=1的數(shù)據(jù)，數(shù)據(jù)量有4W，差不多一半的數(shù)據(jù)量，正常情況肯定走全表了，實(shí)際情況卻走索引。
- SQL> set autot trace
- alter system flush shared_pool;
- select * from test.t1 t where OBJECT_ID=1;SQL>
- System altered.
- SQL>
- 39999 rows selected.
- Execution Plan
- ----------------------------------------------------------
- Plan hash value: 1483979983
- --------------------------------------------------------------------------------
- ----
- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time
- |
- --------------------------------------------------------------------------------
- ----
- | 0 | SELECT STATEMENT | | 38294 | 3627K| 747 (2)| 00:00:
- 01 |
- | 1 | TABLE ACCESS BY INDEX ROWID| T1 | 38294 | 3627K| 747 (2)| 00:00:
- 01 |
- |* 2 | INDEX RANGE SCAN | IDX1 | 38294 | | 112 (4)| 00:00:
- 01 |
- --------------------------------------------------------------------------------
- ----
- Predicate Information (identified by operation id):
- ---------------------------------------------------
- 2 - access("OBJECT_ID"=1)
- Statistics
- ----------------------------------------------------------
- 133 recursive calls
- 0 db block gets
- 6227 consistent gets
- 0 physical reads
- 0 redo size
- 4468586 bytes sent via SQL*Net to client
- 29845 bytes received via SQL*Net from client
- 2668 SQL*Net roundtrips to/from client
- 27 sorts (memory)
- 0 sorts (disk)
- 39999 rows processed
逐層分析
真實(shí)情況中，客戶(hù)發(fā)來(lái)了監(jiān)視報(bào)告，10053trace文件，SQLT報(bào)告。因?yàn)楸O(jiān)視報(bào)告這里用處不大，沒(méi)做模擬。
10053trace信息
參數(shù)方面確認(rèn)沒(méi)什么問(wèn)題跳過(guò)，快速定位到單表訪問(wèn)路徑那部分，如下所示，單表路徑選擇的時(shí)候?qū)Ρ攘嗽L問(wèn)索引（cost ：746.93），以及訪問(wèn)全表的方式（cost ：10050.77），（注：這里人為造出來(lái)的數(shù)據(jù)cost值差異較大，真實(shí)場(chǎng)景中相差不是特別大）那么問(wèn)題在于為什么會(huì)有這么大的差異，Card: 38294.13，即預(yù)估返回結(jié)果集38294，對(duì)比實(shí)際值39999，可以發(fā)現(xiàn)統(tǒng)計(jì)信息這塊兒，基本準(zhǔn)確。
- SINGLE TABLE ACCESS PATH
- Single Table Cardinality Estimation for T1[T]
- Column (#4):
- NewDensity:0.000012, OldDensity:0.000012 BktCnt:254, PopBktCnt:111, PopValCnt:1, NDV:47788
- Column (#4): OBJECT_ID(
- AvgLen: 5 NDV: 47788 Nulls: 1 Density: 0.000012 Min: 1 Max: 190751
- Histogram: HtBal #Bkts: 254 UncompBkts: 254 EndPtVals: 144
- Table: T1 Alias: T
- Card: Original: 87629.000000 Rounded: 38294 Computed: 38294.13 Non Adjusted: 38294.13
- Access Path: TableScan
- Cost: 10050.77 Resp: 10050.77 Degree: 0
- Cost_io: 10033.00 Cost_cpu: 40345028
- Resp_io: 10033.00 Resp_cpu: 40345028
- Access Path: index (AllEqRange)
- Index: IDX1
- resc_io: 734.00 resc_cpu: 29353837
- ix_sel: 0.437008 ix_sel_with_filters: 0.437008
- Cost: 746.93 Resp: 746.93 Degree: 1
- Best:: AccessPath: IndexRange
- Index: IDX1
- Cost: 746.93 Degree: 1 Resp: 746.93 Card: 38294.13 Bytes: 0
線索到這里時(shí)，同事考慮到全表掃描COST值基本來(lái)源于IO，冒出一個(gè)大膽的想法：是否可能數(shù)據(jù)塊兒碎片嚴(yán)重化，極端情況下比如所有不需要的數(shù)據(jù)分布為每條數(shù)據(jù)均存于不同的塊兒中，而需要的數(shù)據(jù)則集中于幾個(gè)需要的塊兒。這個(gè)腦洞大開(kāi)的想法馬上被他自己的查詢(xún)證偽了。
- SQL> select BLOCKS from dba_segments where segment_name='T1' and owner='TEST';
- BLOCKS
- ----------
- 1281
SQLT中發(fā)現(xiàn)關(guān)鍵信息
基于以往故障經(jīng)驗(yàn)的猜想都不成立，而現(xiàn)象看上去是Oracle CBO計(jì)算執(zhí)行計(jì)劃時(shí)出了問(wèn)題，有DBA已經(jīng)開(kāi)始認(rèn)為是Oracle BUG了（當(dāng)然沒(méi)找到對(duì)應(yīng)的BUG編號(hào)）。在看客戶(hù)DBA發(fā)來(lái)的SQLT的報(bào)告時(shí)，終于在報(bào)告中找到了問(wèn)題的突破口。
上圖可以發(fā)現(xiàn)客戶(hù)的系統(tǒng)是收集過(guò)系統(tǒng)統(tǒng)計(jì)信息的（報(bào)告為測(cè)試環(huán)境抓取的），再看單塊讀、多塊讀，MBRC（注測(cè)試環(huán)境模擬時(shí)，單塊讀、多塊讀數(shù)值差別較大，真實(shí)環(huán)境差別為十多倍，MBRC為3）均有統(tǒng)計(jì)信息，這點(diǎn)很是異常，畢竟看過(guò)的絕大部分系統(tǒng)都是沒(méi)收集過(guò)系統(tǒng)統(tǒng)計(jì)信息的。
當(dāng)然其實(shí)10053 trace文件中也有系統(tǒng)統(tǒng)計(jì)信息，只是這塊兒相對(duì)關(guān)注較少。
問(wèn)題分析
詳細(xì)分析前，先回顧下COST算法，參考support oracle文檔：How To Calculate CPU Cost（文檔 ID 457228.1）。
- Cost = (
- #SRds * sreadtim +
- #MRds * mreadtim +
- #CPUCycles / cpuspeed
- ) / sreadtim
- #SRDs - number of single block reads
- #MRDs - number of multi block reads
- #CPUCycles - number of CPU Cycles
- sreadtim - single block read time
- mreadtim - multi block read time
- cpuspeed - CPU cycles per second
公式總結(jié)起來(lái)可以歸結(jié)為cost本質(zhì)為單塊讀，獲取數(shù)據(jù)途徑為磁盤(pán)或內(nèi)存，內(nèi)存中的邏輯讀取消耗CPU時(shí)間除以單塊讀后，折算成以單位讀為單位，磁盤(pán)中獲取分為單塊讀（大部分索引訪問(wèn)）或多塊讀（全表或部分索引訪問(wèn)），多塊讀時(shí)間折算成單塊讀時(shí)間時(shí)，需要考慮每次讀取塊數(shù)（優(yōu)先參考參數(shù)_db_file_optimizer_read_count，該隱含參數(shù)未設(shè)置情況下取db_file_multiblock_read_count，默認(rèn)配置為8）。
可以驗(yàn)算一下，全表掃描時(shí)COST值10033粗略計(jì)算方式：1281/128*1000。
而sreadtim，mreadtim在沒(méi)收集過(guò)系統(tǒng)統(tǒng)計(jì)信息時(shí)是通過(guò)公式計(jì)算得來(lái)的。
- SREADTIM = IOSEEKTIM + db_block_size / IOTFRSPEED
- MREADTIM = IOSEEKTIM + db_block_size * MBRC / IOTFRSPEED
IOSEEKTIM默認(rèn)10ms，IOTFRSPEED默認(rèn)4096字節(jié)/ms，推算可得默認(rèn)值：SREADTIM 12ms， MREADTIM 26ms
回顧過(guò)COST相關(guān)的知識(shí)后，再來(lái)看當(dāng)前的系統(tǒng)信息SREADTIM 1ms， MREADTIM 1000ms MBRC 128，即：通過(guò)單塊讀的方式讀取128個(gè)塊也只需要128ms，遠(yuǎn)遠(yuǎn)小于直接多塊讀128個(gè)塊的成本（1000ms），CBO當(dāng)然會(huì)選錯(cuò)。
故障處理
故障處理起來(lái)很簡(jiǎn)單，運(yùn)行以下語(yǔ)句，清除掉收集的系統(tǒng)統(tǒng)計(jì)信息就可以了。
exec dbms_stats.delete_system_stats;
清除完統(tǒng)計(jì)信息后，再清除下shared pool中的執(zhí)行計(jì)劃，再次解析時(shí)，系統(tǒng)正常運(yùn)行，至此困擾許久的問(wèn)題終于解決。
追根溯源
- 為什么收集系統(tǒng)統(tǒng)計(jì)信息會(huì)產(chǎn)生錯(cuò)誤的單塊讀、多塊讀值？
這個(gè)主要是由于部分物理IO命中存儲(chǔ)/操作系統(tǒng)文件緩存引起，如果收集時(shí)間短，或是系統(tǒng)空閑可能導(dǎo)致信息非常不準(zhǔn)確。
- 為什么會(huì)收集系統(tǒng)統(tǒng)計(jì)信息？
默認(rèn)收集全庫(kù)統(tǒng)計(jì)信息并不會(huì)收集系統(tǒng)統(tǒng)計(jì)信息，只能運(yùn)行DBMS_STATS.gather_system_stats手工觸發(fā)，最終客戶(hù)DBA通過(guò)堡壘機(jī)排查發(fā)現(xiàn)運(yùn)維人員存在違規(guī)操作，問(wèn)題源頭得以查清。
- 是否應(yīng)該收集系統(tǒng)統(tǒng)計(jì)信息？
這是一個(gè)非常有爭(zhēng)議的話題，甚至官方文檔的建議隨著不同的Oracle版本也在變化。無(wú)論參考Oracle的官方文檔，還是對(duì)比實(shí)際值（ 實(shí)際awr報(bào)告中db file sequential read db file scattered read等待事件，大部分值都小于5ms的真實(shí)情景），或是參考Exadata以及各種國(guó)產(chǎn)一體機(jī)出色I(xiàn)O性能的大背景，單塊讀12ms，多塊讀26ms這個(gè)系統(tǒng)默認(rèn)值都似乎過(guò)時(shí)了，應(yīng)該調(diào)整。
事實(shí)上影響Oracle優(yōu)化器的因素非常多，搜集統(tǒng)計(jì)信息會(huì)引入一個(gè)額外的因素，導(dǎo)致系統(tǒng)性能波動(dòng)。系統(tǒng)性能和擴(kuò)展性問(wèn)題更多是因?yàn)樵愀獾膕chema設(shè)計(jì)和schema統(tǒng)計(jì)信息沒(méi)有維護(hù)好導(dǎo)致的。在現(xiàn)實(shí)情況中，我們沒(méi)有遇到過(guò)通過(guò)搜集系統(tǒng)統(tǒng)計(jì)信息解決SQL性能問(wèn)題，倒是遇到過(guò)多個(gè)案例因?yàn)樗鸭到y(tǒng)統(tǒng)計(jì)信息，替換了默認(rèn)的系統(tǒng)統(tǒng)計(jì)信息，從而導(dǎo)致執(zhí)行計(jì)劃變差的案例。建議生產(chǎn)中不更新系統(tǒng)統(tǒng)計(jì)信息，使用默認(rèn)的系統(tǒng)統(tǒng)計(jì)信息。
- 性能故障時(shí)的排查思路：
決定SQL性能的主要因素為以下四條，SQL性能問(wèn)題時(shí)的排查可做參考：
- 統(tǒng)計(jì)信息；
- schema訪問(wèn)路徑；
- SQL寫(xiě)法；
- Oracle版本補(bǔ)丁情況。
- 能否直接調(diào)整系統(tǒng)信息？
附上測(cè)試腳本，開(kāi)始測(cè)試時(shí)，直接調(diào)整SREADTIM、MREADTIM、MBRC值，并不能達(dá)到效果，必須有個(gè)收集的過(guò)程，哪怕如腳本所示實(shí)際沒(méi)采集到數(shù)據(jù)（注：flush shared pool為危險(xiǎn)操作，測(cè)試腳本內(nèi)容不要在生產(chǎn)庫(kù)使用）。
- 為什么收集系統(tǒng)統(tǒng)計(jì)信息不生效？
收集系統(tǒng)統(tǒng)計(jì)信息分為NOWORKLOAD及WORKLOAD兩種模式，腳本中g(shù)ather_system_stats('start')方式為workload模式，該模式下大表讀取如果使用直接路徑讀方式，則無(wú)法采集到MBRC值。因?yàn)镸BRC值必須讀進(jìn)buffer cache中，才會(huì)被統(tǒng)計(jì)（alter session set “_serial_direct_read”=never; 關(guān)閉后測(cè)試可獲取）。SREADTIM、MREADTIM、MBRC值三個(gè)缺少任意一個(gè)，收集的系統(tǒng)統(tǒng)計(jì)信息均不會(huì)生效。
- SQL> exec dbms_stats.delete_system_stats;
- EXEC DBMS_STATS.gather_system_stats('start');
- EXEC DBMS_STATS.gather_system_stats('stop');
- EXEC DBMS_STATS.set_system_stats('SREADTIM', 1);
- EXEC DBMS_STATS.set_system_stats('MREADTIM', 1000);
- --exec dbms_stats.set_system_stats('MBRC',128);
- SELECT pname, pval1 FROM sys.aux_stats$ WHERE sname = 'SYSSTATS_MAIN';
- set autot trace
- alter system flush shared_pool;
- select * from test.t1 t where OBJECT_ID=1;
- PL/SQL procedure successfully completed.
- SQL>
- PL/SQL procedure successfully completed.
- SQL>
- PL/SQL procedure successfully completed.
- SQL>
- PL/SQL procedure successfully completed.
- SQL>
- PL/SQL procedure successfully completed.
- SQL> SQL>
- PNAME PVAL1
- ------------------------------ ----------
- CPUSPEED 2270
- CPUSPEEDNW 2270
- IOSEEKTIM 10
- IOTFRSPEED 4096
- MAXTHR
- MBRC
- MREADTIM 1000
- SLAVETHR
- SREADTIM 1
- 9 rows selected.
- SQL> SQL>
- System altered.
- SQL>
- 39999 rows selected.
- Execution Plan
- ----------------------------------------------------------
- Plan hash value: 3617692013
- --------------------------------------------------------------------------
- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
- --------------------------------------------------------------------------
- | 0 | SELECT STATEMENT | | 38294 | 3627K| 350 (1)| 00:00:05 |
- |* 1 | TABLE ACCESS FULL| T1 | 38294 | 3627K| 350 (1)| 00:00:05 |
- --------------------------------------------------------------------------
- Predicate Information (identified by operation id):
- ---------------------------------------------------
- 1 - filter("OBJECT_ID"=1)
- Statistics
- ----------------------------------------------------------
- 42 recursive calls
- 0 db block gets
- 3903 consistent gets
- 1253 physical reads
- 0 redo size
- 1852399 bytes sent via SQL*Net to client
- 29845 bytes received via SQL*Net from client
- 2668 SQL*Net roundtrips to/from client
- 6 sorts (memory)
- 0 sorts (disk)
- 39999 rows processed
附執(zhí)行操作腳本：
- exec dbms_stats.delete_system_stats;
- EXEC DBMS_STATS.gather_system_stats('start');
- EXEC DBMS_STATS.gather_system_stats('stop');
- EXEC DBMS_STATS.set_system_stats('SREADTIM', 1);
- EXEC DBMS_STATS.set_system_stats('MREADTIM', 1000);
- exec dbms_stats.set_system_stats('MBRC',128);
- SELECT pname, pval1 FROM sys.aux_stats$ WHERE sname = 'SYSSTATS_MAIN';
- set autot trace
- alter system flush shared_pool;
- select * from test.t1 t where OBJECT_ID=1;
- select /*+ full(t ) */ * from test.t1 t where OBJECT_ID=1;
- select /*+ index(t idx1) */ * from test.t1 t where OBJECT_ID=1;
- select count(*) from test.t1 t where OBJECT_ID=1;
- alter system flush shared_pool;
- oradebug setmypid
- oradebug unlimit
- oradebug event 10053 trace name context forever,level 1
- select * from test.t1 t where OBJECT_ID=1;
- oradebug event 10053 trace name context off
- oradebug tracefile_name
作者介紹
蔣健，云趣網(wǎng)絡(luò)科技聯(lián)合創(chuàng)始人，11g OCM，多年Oracle設(shè)計(jì)、管理及實(shí)施經(jīng)驗(yàn)，精通數(shù)據(jù)庫(kù)優(yōu)化，Oracle CBO及并行原理，曾為多個(gè)行業(yè)的客戶(hù)的Oracle系統(tǒng)實(shí)施小型機(jī)到X86跨平臺(tái)遷移和數(shù)據(jù)庫(kù)優(yōu)化服務(wù)。云趣鷹眼監(jiān)控核心設(shè)計(jì)和開(kāi)發(fā)者，資深Python Web開(kāi)發(fā)者。
