蔣健,雲趣網絡科技聯合創始人,11g OCM,多年Oracle設計、管理及實施經驗,精通數據庫優化,Oracle CBO及並行原理,曾為多個行業的客戶的Oracle系統實施小型機到X86跨平臺遷移和數據庫優化服務。雲趣鷹眼監控核心設計和開發者,資深Python Web開發者。
錯亂的系統
某客戶反饋生產庫ETL及報表類SQL全部運行不出來,監控告警近期大量SQL語句執行計劃發生變更。客戶DBA通過對比新舊執行計劃發現執行計劃變更的SQL大部分都變成了走索引加上NL的方式,而且不止一個SQL出現這種問題,該生產庫上幾乎所有的AP類型SQL都出現了該問題。問題到我們這邊前,客戶已經花了數週時間做了好幾輪排查,均沒有效果。
歷史的診斷
全庫統計信息排查
DBA排查過歷史的統計信息,並重新收集了對應schema的統計信息,重新收集相關表、索引的直方圖統計信息,部分SQL增加了多列統計信息。每次操作完成後的驗證均無效果,之後回退了以上無效操作。
綁定部分SQL執行計劃
部分業務過於緊急,約10條SQL臨時使用SQLPROFILE綁定了執行計劃,針對綁定的SQL有效,然而執行計劃發生變更SQL語句數量過多,針對每個SQL分析執行計劃並綁定,這完全不現實。
參數排查
排查了系統參數optimizer_index_*相關參數,均為默認值,優化器模式為默認ALL_ROWS,db_file_multiblock_read_count參數設置128,參數無異常變更,後檢查包括觸發器層面、進程級別,均為無異常參數調整。
故障重現
由於客戶生產上的案例文章中不方便使用真實數據,模擬了以下數據:
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;
查詢數據如下,T1表上有8.7W數據:
SQL>
select count(*) from test.t1 SQL> ;
COUNT(*)
----------
87629
簡單模擬的SQL如下,查詢OBJECT_ID=1的數據,數據量有4W,差不多一半的數據量,正常情況肯定走全表了,實際情況卻走索引。
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:
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
逐層分析
真實情況中,客戶發來了監視報告,10053trace文件,SQLT報告。因為監視報告這裡用處不大,沒做模擬。
10053trace信息
參數方面確認沒什麼問題跳過,快速定位到單表訪問路徑那部分,如下所示,單表路徑選擇的時候對比了訪問索引(cost :746.93),以及訪問全表的方式(cost :10050.77),(注:這裡人為造出來的數據cost值差異較大,真實場景中相差不是特別大)那麼問題在於為什麼會有這麼大的差異,Card: 38294.13,即預估返回結果集38294,對比實際值39999,可以發現統計信息這塊兒,基本準確。
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 s: 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
SQL> select BLOCKS from dba_segments where segment_name='T1' and owner='TEST';
BLOCKS
----------
1281
SQLT中發現關鍵信息
基於以往故障經驗的猜想都不成立,而現象看上去是Oracle CBO計算執行計劃時出了問題,有DBA已經開始認為是Oracle BUG了(當然沒找到對應的BUG編號)。在看客戶DBA發來的SQLT的報告時,終於在報告中找到了問題的突破口。
![避坑:一次离奇性能故障的排查与反思](http://p2.ttnews.xyz/loading.gif)
上圖可以發現客戶的系統是收集過系統統計信息的(報告為測試環境抓取的),再看單塊讀、多塊讀,MBRC(注測試環境模擬時,單塊讀、多塊讀數值差別較大,真實環境差別為十多倍,MBRC為3)均有統計信息,這點很是異常,畢竟看過的絕大部分系統都是沒收集過系統統計信息的。
當然其實10053 trace文件中也有系統統計信息,只是這塊兒相對關注較少。
問題分析
詳細分析前,先回顧下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
公式總結起來可以歸結為cost本質為單塊讀,獲取數據途徑為磁盤或內存,內存中的邏輯讀取消耗CPU時間除以單塊讀後,折算成以單位讀為單位,磁盤中獲取分為單塊讀(大部分索引訪問)或多塊讀(全表或部分索引訪問),多塊讀時間折算成單塊讀時間時,需要考慮每次讀取塊數(優先參考參數_db_file_optimizer_read_count,該隱含參數未設置情況下取db_file_multiblock_read_count,默認配置為8)。
可以驗算一下,全表掃描時COST值10033粗略計算方式:1281/128*1000。
而sreadtim,mreadtim在沒收集過系統統計信息時是通過公式計算得來的。
SREADTIM = IOSEEKTIM + db_block_size / IOTFRSPEED
MREADTIM = IOSEEKTIM + db_block_size * MBRC / IOTFRSPEED
IOSEEKTIM默認10ms,IOTFRSPEED默認4096字節/ms,推算可得默認值:SREADTIM 12ms, MREADTIM 26ms
回顧過COST相關的知識後,再來看當前的系統信息SREADTIM 1ms, MREADTIM 1000ms MBRC 128,即:通過單塊讀的方式讀取128個塊也只需要128ms,遠遠小於直接多塊讀128個塊的成本(1000ms),CBO當然會選錯。
故障處理
故障處理起來很簡單,運行以下語句,清除掉收集的系統統計信息就可以了。
exec dbms_stats.delete_system_stats;
清除完統計信息後,再清除下shared pool中的執行計劃,再次解析時,系統正常運行,至此困擾許久的問題終於解決。
追根溯源
為什麼收集系統統計信息會產生錯誤的單塊讀、多塊讀值?
這個主要是由於部分物理IO命中存儲/操作系統文件緩存引起,如果收集時間短,或是系統空閒可能導致信息非常不準確。
為什麼會收集系統統計信息?
默認收集全庫統計信息並不會收集系統統計信息,只能運行DBMS_STATS.gather_system_stats手工觸發,最終客戶DBA通過堡壘機排查發現運維人員存在違規操作,問題源頭得以查清。
是否應該收集系統統計信息?
這是一個非常有爭議的話題,甚至官方文檔的建議隨著不同的Oracle版本也在變化。無論參考Oracle的官方文檔,還是對比實際值( 實際awr報告中db file sequential read db file scattered read等待事件,大部分值都小於5ms的真實情景),或是參考Exadata以及各種國產一體機出色IO性能的大背景,單塊讀12ms,多塊讀26ms這個系統默認值都似乎過時了,應該調整。
事實上影響Oracle優化器的因素非常多,蒐集統計信息會引入一個額外的因素,導致系統性能波動。系統性能和擴展性問題更多是因為糟糕的schema設計和schema統計信息沒有維護好導致的。在現實情況中,我們沒有遇到過通過蒐集系統統計信息解決SQL性能問題,倒是遇到過多個案例因為蒐集系統統計信息,替換了默認的系統統計信息,從而導致執行計劃變差的案例。建議生產中不更新系統統計信息,使用默認的系統統計信息。
性能故障時的排查思路:
決定SQL性能的主要因素為以下四條,SQL性能問題時的排查可做參考:
統計信息;
schema訪問路徑;
SQL寫法;
Oracle版本補丁情況。
能否直接調整系統信息?
附上測試腳本,開始測試時,直接調整SREADTIM、MREADTIM、MBRC值,並不能達到效果,必須有個收集的過程,哪怕如腳本所示實際沒采集到數據(注:flush shared pool為危險操作,測試腳本內容不要在生產庫使用)。
為什麼收集系統統計信息不生效?
收集系統統計信息分為NOWORKLOAD及WORKLOAD兩種模式,腳本中gather_system_stats('start')方式為workload模式,該模式下大表讀取如果使用直接路徑讀方式,則無法採集到MBRC值。因為MBRC值必須讀進buffer cache中,才會被統計(alter session set “_serial_direct_read”=never; 關閉後測試可獲取)。SREADTIM、MREADTIM、MBRC值三個缺少任意一個,收集的系統統計信息均不會生效。
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> SQL>
PNAME PVAL1
------------------------------ ----------
CPUSPEED 2270
CPUSPEEDNW 2270
IOSEEKTIM 10
IOTFRSPEED 4096
MAXTHR
MBRC
MREADTIM 1000
SLAVETHR
SREADTIM 1
9 rows selected.
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 |
1 - filter("OBJECT_ID"=1)
42 recursive calls
0 db block gets
3903 consistent gets
1253 physical reads
0 redo size
1852399 bytes sent via SQL*Net to client
6 sorts (memory)
附執行操作腳本:
exec dbms_stats.set_system_stats('MBRC',128);
SELECT pname, pval1 FROM sys.aux_stats$ WHERE sname = 'SYSSTATS_MAIN';
set autot trace
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
參考文檔
http://www.oracle.com/technetwork/database/bi-datawarehousing/twp-bp-for-stats-gather-12c-1967354.pdf
https://blogs.oracle.com/optimizer/should-you-gather-system-statistics
近期熱文
近期活動
閱讀更多 DBAplus社群 的文章