錯亂的系統(tǒng)

某客戶反饋生產(chǎn)庫ETL及報表類SQL全部運行不出來，監(jiān)控告警近期大量SQL語句執(zhí)行計劃發(fā)生變更?？蛻鬌BA通過對比新舊執(zhí)行計劃發(fā)現(xiàn)執(zhí)行計劃變更的SQL大部分都變成了走索引加上NL的方式，而且不止一個SQL出現(xiàn)這種問題，該生產(chǎn)庫上幾乎所有的AP類型SQL都出現(xiàn)了該問題。問題到我們這邊前，客戶已經(jīng)花了數(shù)周時間做了好幾輪排查，均沒有效果。

歷史的診斷

全庫統(tǒng)計信息排查

DBA排查過歷史的統(tǒng)計信息，并重新收集了對應(yīng)schema的統(tǒng)計信息，重新收集相關(guān)表、索引的直方圖統(tǒng)計信息，部分SQL增加了多列統(tǒng)計信息。每次操作完成后的驗證均無效果，之后回退了以上無效操作。

[[234937]]

綁定部分SQL執(zhí)行計劃

部分業(yè)務(wù)過于緊急，約10條SQL臨時使用SQLPROFILE綁定了執(zhí)行計劃，針對綁定的SQL有效，然而執(zhí)行計劃發(fā)生變更SQL語句數(shù)量過多，針對每個SQL分析執(zhí)行計劃并綁定，這完全不現(xiàn)實。

參數(shù)排查

排查了系統(tǒng)參數(shù)optimizer_index_*相關(guān)參數(shù)，均為默認值，優(yōu)化器模式為默認ALL_ROWS，db_file_multiblock_read_count參數(shù)設(shè)置128，參數(shù)無異常變更，后檢查包括觸發(fā)器層面、進程級別，均為無異常參數(shù)調(diào)整。 

故障重現(xiàn)

由于客戶生產(chǎn)上的案例文章中不方便使用真實數(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; 

查詢數(shù)據(jù)如下，T1表上有8.7W數(shù)據(jù)：

SQL> 
select  count(*) from test.t1 SQL> ; 
 
  COUNT(*) 
---------- 
     87629 

簡單模擬的SQL如下，查詢OBJECT_ID=1的數(shù)據(jù)，數(shù)據(jù)量有4W，差不多一半的數(shù)據(jù)量，正常情況肯定走全表了，實際情況卻走索引。

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 

逐層分析

真實情況中，客戶發(fā)來了監(jiān)視報告，10053trace文件，SQLT報告。因為監(jiān)視報告這里用處不大，沒做模擬。

10053trace信息

參數(shù)方面確認沒什么問題跳過，快速定位到單表訪問路徑那部分，如下所示，單表路徑選擇的時候?qū)Ρ攘嗽L問索引（cost ：746.93），以及訪問全表的方式（cost ：10050.77），（注：這里人為造出來的數(shù)據(jù)cost值差異較大，真實場景中相差不是特別大）那么問題在于為什么會有這么大的差異，Card: 38294.13，即預(yù)估返回結(jié)果集38294，對比實際值39999，可以發(fā)現(xiàn)統(tǒng)計信息這塊兒，基本準確。

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 

線索到這里時，同事考慮到全表掃描COST值基本來源于IO，冒出一個大膽的想法：是否可能數(shù)據(jù)塊兒碎片嚴重化，極端情況下比如所有不需要的數(shù)據(jù)分布為每條數(shù)據(jù)均存于不同的塊兒中，而需要的數(shù)據(jù)則集中于幾個需要的塊兒。這個腦洞大開的想法馬上被他自己的查詢證偽了。 

SQL> select BLOCKS from dba_segments where segment_name='T1' and owner='TEST'; 
 
    BLOCKS 
---------- 
      1281 

SQLT中發(fā)現(xiàn)關(guān)鍵信息

基于以往故障經(jīng)驗的猜想都不成立，而現(xiàn)象看上去是Oracle CBO計算執(zhí)行計劃時出了問題，有DBA已經(jīng)開始認為是Oracle BUG了（當然沒找到對應(yīng)的BUG編號）。在看客戶DBA發(fā)來的SQLT的報告時，終于在報告中找到了問題的突破口。

上圖可以發(fā)現(xiàn)客戶的系統(tǒng)是收集過系統(tǒng)統(tǒng)計信息的（報告為測試環(huán)境抓取的），再看單塊讀、多塊讀，MBRC（注測試環(huán)境模擬時，單塊讀、多塊讀數(shù)值差別較大，真實環(huán)境差別為十多倍，MBRC為3）均有統(tǒng)計信息，這點很是異常，畢竟看過的絕大部分系統(tǒng)都是沒收集過系統(tǒng)統(tǒng)計信息的。

當然其實10053 trace文件中也有系統(tǒng)統(tǒng)計信息，只是這塊兒相對關(guān)注較少。

問題分析

詳細分析前，先回顧下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é)起來可以歸結(jié)為cost本質(zhì)為單塊讀，獲取數(shù)據(jù)途徑為磁盤或內(nèi)存，內(nèi)存中的邏輯讀取消耗CPU時間除以單塊讀后，折算成以單位讀為單位，磁盤中獲取分為單塊讀（大部分索引訪問）或多塊讀（全表或部分索引訪問），多塊讀時間折算成單塊讀時間時，需要考慮每次讀取塊數(shù)（優(yōu)先參考參數(shù)_db_file_optimizer_read_count，該隱含參數(shù)未設(shè)置情況下取db_file_multiblock_read_count，默認配置為8）。

可以驗算一下，全表掃描時COST值10033粗略計算方式：1281/128*1000。

而sreadtim，mreadtim在沒收集過系統(tǒng)統(tǒng)計信息時是通過公式計算得來的。 

SREADTIM = IOSEEKTIM + db_block_size        / IOTFRSPEED 
MREADTIM = IOSEEKTIM + db_block_size * MBRC / IOTFRSPEED 

IOSEEKTIM默認10ms，IOTFRSPEED默認4096字節(jié)/ms，推算可得默認值：SREADTIM 12ms， MREADTIM 26ms

回顧過COST相關(guān)的知識后，再來看當前的系統(tǒng)信息SREADTIM 1ms， MREADTIM 1000ms MBRC 128，即：通過單塊讀的方式讀取128個塊也只需要128ms，遠遠小于直接多塊讀128個塊的成本（1000ms），CBO當然會選錯。

故障處理

故障處理起來很簡單，運行以下語句，清除掉收集的系統(tǒng)統(tǒng)計信息就可以了。 

exec dbms_stats.delete_system_stats;

清除完統(tǒng)計信息后，再清除下shared pool中的執(zhí)行計劃，再次解析時，系統(tǒng)正常運行，至此困擾許久的問題終于解決。

追根溯源

• 為什么收集系統(tǒng)統(tǒng)計信息會產(chǎn)生錯誤的單塊讀、多塊讀值？

這個主要是由于部分物理IO命中存儲/操作系統(tǒng)文件緩存引起，如果收集時間短，或是系統(tǒng)空閑可能導致信息非常不準確。

• 為什么會收集系統(tǒng)統(tǒng)計信息？

默認收集全庫統(tǒng)計信息并不會收集系統(tǒng)統(tǒng)計信息，只能運行DBMS_STATS.gather_system_stats手工觸發(fā)，最終客戶DBA通過堡壘機排查發(fā)現(xiàn)運維人員存在違規(guī)操作，問題源頭得以查清。

• 是否應(yīng)該收集系統(tǒng)統(tǒng)計信息？

這是一個非常有爭議的話題，甚至官方文檔的建議隨著不同的Oracle版本也在變化。無論參考Oracle的官方文檔，還是對比實際值（ 實際awr報告中db file sequential read db file scattered read等待事件，大部分值都小于5ms的真實情景），或是參考Exadata以及各種國產(chǎn)一體機出色IO性能的大背景，單塊讀12ms，多塊讀26ms這個系統(tǒng)默認值都似乎過時了，應(yīng)該調(diào)整。

事實上影響Oracle優(yōu)化器的因素非常多，搜集統(tǒng)計信息會引入一個額外的因素，導致系統(tǒng)性能波動。系統(tǒng)性能和擴展性問題更多是因為糟糕的schema設(shè)計和schema統(tǒng)計信息沒有維護好導致的。在現(xiàn)實情況中，我們沒有遇到過通過搜集系統(tǒng)統(tǒng)計信息解決SQL性能問題，倒是遇到過多個案例因為搜集系統(tǒng)統(tǒng)計信息，替換了默認的系統(tǒng)統(tǒng)計信息，從而導致執(zhí)行計劃變差的案例。建議生產(chǎn)中不更新系統(tǒng)統(tǒng)計信息，使用默認的系統(tǒng)統(tǒng)計信息。

• 性能故障時的排查思路：

決定SQL性能的主要因素為以下四條，SQL性能問題時的排查可做參考：

1. 統(tǒng)計信息；
2. schema訪問路徑；
3. SQL寫法；
4. Oracle版本補丁情況。

• 能否直接調(diào)整系統(tǒng)信息？

附上測試腳本，開始測試時，直接調(diào)整SREADTIM、MREADTIM、MBRC值，并不能達到效果，必須有個收集的過程，哪怕如腳本所示實際沒采集到數(shù)據(jù)（注：flush shared pool為危險操作，測試腳本內(nèi)容不要在生產(chǎn)庫使用）。

• 為什么收集系統(tǒng)統(tǒng)計信息不生效？

收集系統(tǒng)統(tǒng)計信息分為NOWORKLOAD及WORKLOAD兩種模式，腳本中g(shù)ather_system_stats('start')方式為workload模式，該模式下大表讀取如果使用直接路徑讀方式，則無法采集到MBRC值。因為MBRC值必須讀進buffer cache中，才會被統(tǒng)計（alter session set “_serial_direct_read”=never; 關(guān)閉后測試可獲?。?。SREADTIM、MREADTIM、MBRC值三個缺少任意一個，收集的系統(tǒng)統(tǒng)計信息均不會生效。 

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īng)驗，精通數(shù)據(jù)庫優(yōu)化，Oracle CBO及并行原理，曾為多個行業(yè)的客戶的Oracle系統(tǒng)實施小型機到X86跨平臺遷移和數(shù)據(jù)庫優(yōu)化服務(wù)。云趣鷹眼監(jiān)控核心設(shè)計和開發(fā)者，資深Python Web開發(fā)者。