年后一次系统升级后,监控数据库的工具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引起的。其实还是因为绑定变量的数据类型与实际字段的数据类型不一致而引起的。