年後一次系統升級後,監控數據庫的工具DPA發現數據庫的Total Wait時間突然飙增,如下截圖所示,數據庫的總體等待時間對比升級前飙增了非常多
另外就是發現出現了較多的等待事件,主要有latch: cache buffers chains、 latch: shared pool 、db file scattered read。根據這邊的監控發現TOP SQL裡面從升級前的0次變為了一天的一萬多次(有些甚至更多),分析過後我們就找開發人員了解一下系統升級變跟的內容和改動
開發人員堅定的告訴們介紹,他只是將他負責的那個模塊裡面那些拼接SQL(Literal SQL)語句改寫成了綁定變量(因為我們系統大量使用拼接SQL的方式,硬解析非常嚴重),所以我們一直建議他們使用綁定變量。由於改為綁定變量,所以DPA以前沒有捕獲這些SQl,後面因為執行次數激增,所以捕獲了這些SQL,也發現其執行次數明顯變化了,例如有些SQL語句的執行次數上萬了。
後面經過分析、跟蹤過後發現修改為綁定變量的SQL的實際執行計劃變成全表掃描了。這也能解釋為什麼db file scattered read等待事件出現,因為全表掃描的緣故。下面就其中的一個SQL語句做分析,如下所示,我們在Toad或SQL Developer工具裡面查看預估執行計劃時,其執行計劃都是走索引掃描(Index Scan),但是實際執行計劃就是走全表掃描
實際執行計劃(截圖來自WORKLOAD REPOSITORY SQL Report )
剛開始我們以為是綁定變量的窺探機制造成(使用SQL首次運行時的值來生成執行計劃。後續再次運行該SQL語句則使用首次執行計劃來執行),但是分析過後發現,SC_NO這個字段建有唯一索引,不存在所謂的數據傾斜的情況。非常的糾結,納悶,不解。同事用10046跟蹤了SQL語句(其實是跟蹤某個自己在Toad裡面執行的SQL語句,這也是問題一直沒有發現的原因),想不明白為什麼,隱隱懷疑是數據庫的bug來著,直到後面我在sqltrpt.sql查看某些SQL的調優優化建議,突然看到下面信息:
3- Restructure SQL finding (see plan 1 in explain plans section)
---------------------------------------------------------------------------
The predicate SYS_OP_C2C("SC_NO")=:B1 used at line ID 5 of the execution plan contains an implicit data type conversion on indexed column "SC_NO".This implicit data type conversion prevents the optimizer from selecting indices on table "SC_HD".
Recommendation
--------------------------------------------------------------------------
- Rewrite the predicate into an equivalent form to take advantage of indices.
頓時豁然開朗,肯定是開發人員在使用綁定變量時,使用了不一致的數據類型,導致了隱式轉換(implicit data type conversion),於是聯系開發人員確認,要了程序裡面的代碼,果然如此,SC_NO的數據類型為VARCHAR2,但是在代碼裡面綁定變量的類型為OracleType.NVarChar。悲劇的是幾乎所有綁定變量都由於開發人員疏忽,都給錯了數據類型。所以出現這麼嚴重的情況
...........................................................
param = new OracleParameter(":scNo", OracleType.NVarChar);
param.Value = Server.UrlDecode(joNo).ToUpper();
paramsList.Add(param);
...........................................................
那麼我們下面我們模擬一下綁定變量數據類型不一致,出現隱式轉換導致不走索引的情況
SQL> alter system flush shared_pool;
System altered.
SQL> set autotrace on;
SQL> variable sc_no nvarchar2(20);
SQL> exec :sc_no :='A01Adfddf01I';
PL/SQL procedure successfully completed.
SQL> select count(1) from sc_hd
2 where sc_no =:sc_no
3 and jo_status<>'l2'
4 and status<>'x';
COUNT(1)
----------
0
Execution Plan
----------------------------------------------------------
Plan hash value: 326413811
----------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
----------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 16 | 3 (0)| 00:00:01 |
| 1 | SORT AGGREGATE | | 1 | 16 | | |
|* 2 | TABLE ACCESS BY INDEX ROWID| SC_HD | 1 | 16 | 3 (0)| 00:00:01 |
|* 3 | INDEX UNIQUE SCAN | SC_HEAD | 1 | | 2 (0)| 00:00:01 |
----------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - filter("JO_STATUS"<>'l2' AND "STATUS"<>'x')
3 - access("SC_NO"=:SC_NO)
Statistics
----------------------------------------------------------
2082 recursive calls
6 db block gets
109260 consistent gets
108647 physical reads
0 redo size
514 bytes sent via SQL*Net to client
492 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
48 sorts (memory)
0 sorts (disk)
1 rows processed
SQL>
此時,你查看實際執行計劃,就會發現其走全表掃描。如下所示
如果此時你用一模一樣的SQL(空格,字符大小一致,如下所示),在TOAD裡面執行,即使你給綁定變量賦予的是VARCHAR2類型的數據,也會發現其實際執行計劃走全表掃描,這個是因為綁定變量窺探,使用SQL首次運行時的值來生成執行計劃。後續再次運行該SQL語句則使用首次執行計劃來執行的緣故
select count(1) from sc_hd
where sc_no =:sc_no
and jo_status<>'l2'
and status<>'x';
如果空格不一致,或大小寫,或換行不一致,你又會發現其實際執行計劃走索引了,這也是當初我們在不了解應用程序源代碼的情況,被這個情況給折騰瘋了的情況,以為是數據庫的bug引起的。其實還是因為綁定變量的數據類型與實際字段的數據類型不一致而引起的。