去年底,某运营商客户反馈某个核心业务模块突然出现严重性能问题,产生了极为不好的用户体验,客服接到了大量投诉电话。这样的问题,处理起来相对容易一些。首先我们根据v$session.program很容易就可以定位到业务程序,并结合event、SQL_ID和SQL_TEXT 很快就确认是运行较慢的业务SQL语句,经过分析发现是SQL选择了错误的Index,导致执行计划效率不高。这里我通过在客户生产库创建相同的对象,然后执行类似SQL,完全可以重现问题。
首先我们来分析一下出问题的SQL语句,如下所示。
SELECT SERIAL_NBR FROM BILLUSER.I_B2O_OWE_C_BAK WHERE (PROC_TYPE = '13' or PROC_TYPE = '14' or PROC_TYPE = 'S13' or PROC_TYPE = 'S14') AND BEGIN_OWE_DATE >= TO_DATE('2015-12-02 12:00:00', 'YYYY/MM/DD HH24:MI:SS') AND ACC_NBR = '18115258610'
需要说明一点,这里的I_B2O_OWE_C_BAK 表是复制的I_B2O_OWE_C表。
该SQL语句从结构上看很简单,初步怀疑是这个SQL的执行计划可能存在异常,这里我们首先来分析一下执行计划,如下所示。
Plan hash value: 239766388 ----------------------------------------------------------------------------------- | Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | ----------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | | 0 |00:00:00.59 | 3049 | |* 1 | TABLE ACCESS BY INDEX ROWID| I_B2O_OWE_C_BAK | 1 | 1 | 0 |00:00:00.59 | 3049 | |* 2 | INDEX RANGE SCAN | I_B2O_OWE_C_BAK_BDATE| 1 | 3 | 19871 |00:00:00.01 | 236 | ----------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 1 - filter((TO_NUMBER("ACC_NBR")=:SYS_B_6 AND INTERNAL_FUNCTION("PROC_TYPE"))) 2 - access("BEGIN_OWE_DATE">=TO_DATE(:SYS_B_4,:SYS_B_5))
我相信,有SQL优化经验的同学应该都能看出来,上述的执行计划确实有些异常,SQL通过走Index range scan的方式,最后返回了仅仅1条数据,然而逻辑读的消耗却高达3000之多,这很明显是有问题的。同时我们还可以看出Oracle优化器评估出来的R-rows 和实际的A-rows差距非常大。也正是由于这一点,导致该执行计划选择了I_B20_OWE_C_BAK_BDATE索引后进行回表操作,产生了大量的逻辑读(逻辑读消耗几乎都在回表操作上)。
由于是客户反馈,那么在处理时我们首先想到的是,这个问题SQL是不是真如客户所讲那样,在当天才出现问题,而之前都是正常呢?还是说有可能之前也出现过异常,只是业务没有反馈而已。
要验证这一点,需要查询该SQL_ID的历史执行计划信息。通过查询确认该SQL实际上在12 月 1 日就出现了异常。但是由于当天业务量较小,没有对业务产生实质性的影响,如下所示。
SNAP_ID SQL_ID PLAN_HASH_VALUE OPTIMIZER_ FORCE_MATCHING_SIGNATURE ---------- ------------- --------------- ---------- ------------------------ 80546 1pzv7x3nhszva 1247210496 ALL_ROWS 8159205349038030075 …… 80569 1pzv7x3nhszva 1247210496 ALL_ROWS 8159205349038030075 80570 1pzv7x3nhszva 1247210496 ALL_ROWS 8159205349038030075 80571 1pzv7x3nhszva 239766388 ALL_ROWS 8159205349038030075 80571 1pzv7x3nhszva 1247210496 ALL_ROWS 8159205349038030075 80573 1pzv7x3nhszva 1247210496 ALL_ROWS 8159205349038030075 80573 1pzv7x3nhszva 239766388 ALL_ROWS 8159205349038030075 80596 1pzv7x3nhszva 239766388 ALL_ROWS 8159205349038030075 ……. 80609 1pzv7x3nhszva 239766388 ALL_ROWS 8159205349038030075 80609 1pzv7x3nhszva 1247210496 ALL_ROWS 8159205349038030075 80610 1pzv7x3nhszva 239766388 ALL_ROWS 8159205349038030075 80610 1pzv7x3nhszva 1247210496 ALL_ROWS 8159205349038030075 80623 1pzv7x3nhszva 1247210496 ALL_ROWS 8159205349038030075 80624 1pzv7x3nhszva 1247210496 ALL_ROWS 8159205349038030075
其中快照ID的对应的时间段信息如下所示。
SNAP_ID BEGIN_INTERVAL_TI ---------- ----------------- 80546 20151129 23:00:34 80547 20151130 00:00:48 …… 80569 20151130 22:00:02 80570 20151130 23:00:20 80571 20151201 00:00:40 80572 20151201 01:00:59 80573 20151201 02:00:16 80574 20151201 03:00:38 …… 80596 20151202 01:01:00 ……. 80609 20151202 14:00:49 80610 20151202 15:00:16 80611 20151202 16:00:50 80612 20151202 17:00:19
其中plan_hash_value 为239766388 的执行计划为错误的执行计划。当产生错误的执行计划之后,由于Oracle bind peeking 的问题,就可能导致数据库在之后的一段时间内一直沿用错误的执行计划。
我开始怀疑可能是统计信息的问题,由于客户后续已经重新收集了统计信息。因此现在我想,是否可以将统计信息还原到出问题之前的某天,然后执行SQL语句,看其执行计划是怎么样的。
实际上Oracle本身就提供了这样一个功能,利用DBMS_STATS可以将表的统计信息还原到过去某个时间点,操作步骤如下所示。
SQL> exec dbms_stats.restore_table_stats(ownname=>'BILLUSER',tabname=>'I_B2O_OWE_ C_BAK',AS_OF_TIMESTAMP=>'01-DEC-15 12.09.22.020077 AM +08:00'); PL/SQL procedure successfully completed. SQL> select owner,table_name,COLUMN_NAME,NUM_DISTINCT,DENSITY,NUM_BUCKETS,LAST_ ANALYZED,HISTOGRAM from dba_tab_col_statistics where table_name='I_B2O_OWE_C_BAK'; OWNER TABLE_NAME COLUMN_NAME NUM_DISTINCT DENSITY NUM_BUCKETS LAST_ANALYZED HISTOGRAM ------------ ------------- ------------- ---------- -------- -------- --------------- BILLUSER I_B2O_OWE_C_BAK SOURCE 0 0 0 2015-11-17 00:10:25 NONE BILLUSER I_B2O_OWE_C_BAK TDBS 3 3.4099E-08 3 2015-11-17 00:10:25 FREQUENCY BILLUSER I_B2O_OWE_C_BAK SERIAL_NBR 14663108 6.8198E-08 1 2015-11-17 00:10:25 NONE BILLUSER I_B2O_OWE_C_BAK PROC_TYPE 5 3.4099E-08 5 2015-11-17 00:10:25 FREQUENCY BILLUSER I_B2O_OWE_C_BAK PROD_ID 2326397 4.2985E-07 1 2015-11-17 00:10:25 NONE BILLUSER I_B2O_OWE_C_BAK CREATE_DATE 5660648 1.3521E-06 254 2015-11-17 00:10:25 HEIGHT BALANCED BILLUSER I_B2O_OWE_C_BAK BEGIN_OWE_DATE 5833484 7.9253E-07 254 2015-11-17 00:10:25 HEIGHT BALANCED BILLUSER I_B2O_OWE_C_BAK STATE 3 3.4099E-08 3 2015-11-17 00:10:25 FREQUENCY BILLUSER I_B2O_OWE_C_BAK STATE_DATE 5927070 6.3963E-07 254 2015-11-17 00:10:25 HEIGHT BALANCED BILLUSER I_B2O_OWE_C_BAK ACC_NBR 2306453 1.2826E-06 254 2015-11-17 00:10:25 HEIGHT BALANCED BILLUSER I_B2O_OWE_C_BAK PRODUCT_TYPE 3 3.4099E-08 3 2015-11-17 00:10:25 FREQUENCY BILLUSER I_B2O_OWE_C_BAK BILLING_MODE_ID 3 .333333333 1 2015-11-17 00:10:25 NONE BILLUSER I_B2O_OWE_C_BAK AREA_CODE 5 .2 1 2015-11-17 00:10:25 NONE BILLUSER I_B2O_OWE_C_BAK JRFS 0 0 0 2015-11-17 00:10:25 NONE
---基于列的详细统计信息
COLUMN_NAME DATA_TYPE M NUM_VALS NUM_NULLS DNSTY LOW_V HI_V ---------------- ------- - ---------- ---------- ------- -------- ------------------ SERIAL_NBR NUMBER Y 14663,108 0 0.0000 118812796 142619179 PROC_TYPE VARCHAR2 Y 5 0 0.0000 11 15 PROD_ID NUMBER Y 2326,397 0 0.0000 10282208 561259458 CREATE_DATE DATE Y 5660,648 0 0.0000 2015-2-10 21:50:52 2015-11-16 23:53:30 BEGIN_OWE_DATE DATE N 5833,484 0 0.0000 2015-2-10 21:50:51 2015-11-16 23:55:26 STATE VARCHAR2 Y 3 0 0.0000 101 3 STATE_DATE DATE Y 5927,070 0 0.0000 2015-2-10 23:0:47 2015-11-16 23:59:41 ACC_NBR VARCHAR2 Y 2306,453 0 0.0000 13309500000 18995499998 PRODUCT_TYPE NUMBER Y 3 0 0.0000 401731 403094 BILLING_MODE_ID NUMBER N 3 0 0.3333 1 4 AREA_CODE VARCHAR2 N 5 0 0.2000 0951 0955 JRFS VARCHAR2 N 0 14765,004 0.0000 TDBS NUMBER Y 3 0 0.0000 0 2 SOURCE VARCHAR2 N 0 14765,004 0.0000
通过还原统计信息之后,发现该表的统计信息最新值实际上是11月17日凌晨,也就是说从11月17日到12月1日,该表的统计信息都没有发现发现过变动(实际上到12月1日客户感觉到出问题之后,手工收集过统计信息)。由于最近半月数据变化比较大,但统计信息却并没有更新,说明统计信息过旧也可能导致Oracle 仍然沿用旧的统计信息进行执行计划评估,进而产生错误的执行计划。至少目前为止我们还不能排除这个可能性。
这里首先来看一下Oracle card的计算公式,如下所示。
= 基数计算公式 :1/num_distinct*(num_rows-num_nulls)
>= 基数计算公式:((high_value-limit)/(high_value-low_value)+1/num_distinct)*(num_rows- num_nulls)
对于该问题SQL的索引,如下所示。
OWNER TABLE_NAME INDEX_NAME BLEVEL LEAF_BLOCKS NUM_ROWS CLUSTERING_FACTOR DISTINCT_KEYS ---------- --------- ------------- ------- ------- -------- --------- ------------- BILLUSER I_B2O_OWE_C_BAK I_B2O_OWE_C_BDATE_BAK 2 42001 15833626 7108231 6150468 BILLUSER I_B2O_OWE_C_BAK I_B2O_OWE_C_ACCNBR_BAK 2 50751 15833626 15723479 2421731
那么根据Oracle Card计算公式,对于两个索引的估算情况如下所示。
对于其中的索引I_B2O_OWE_C_ACCNBR_BAK,由于SQL的过滤条件为 = 符号。当统计信息不变的情况之下,根据公式所计算的Card值都是不变的。
对于索引 I_B2O_OWE_C_BDATE_BAK,由于其过滤条件是 >=符号。根据Card的计算公式,是需要通过high value等值来进行计算的。
这里我们怀疑极有可能跟这个BDATE 时间列的high value等统计信息有关系,为了验证这个观点,这里我进行了如下的测试验证过程。
情况一:当时间条件取值大于high value时。
SQL> SELECT /*+ gather_plan_statistics */ SERIAL_NBR FROM BILLUSER.I_B2O_OWE_C_BAK WHERE (PROC_TYPE='13' or PROC_TYPE='14' or 2 PROC_TYPE='S13' or PROC_TYPE='S14') AND BEGIN_OWE_DATE >= 3 TO_DATE('2015-11-16 23:56:00','YYYY/MM/DD HH24:MI:SS') AND ACC_NBR ='18909502122' 4 / no rows selected SQL> select * from table(dbms_xplan.display_cursor(NULL,NULL,'ALLSTATS')); PLAN_TABLE_OUTPUT ------------------------------------------------------------------------------------ SQL_ID 4fjrp8d5gqz1z, child number 0 ------------------------------------- SELECT /*+ gather_plan_statistics */ SERIAL_NBR FROM BILLUSER.I_B2O_OWE_C_BAK WHERE (PROC_TYPE='13' or PROC_TYPE='14' or PROC_TYPE='S13' or PROC_TYPE='S14') AND BEGIN_OWE_DATE >= TO_DATE('2015-11-16 23:56:00','YYYY/MM/DD HH24:MI:SS') AND ACC_NBR ='18909502122' Plan hash value: 3356388844 ------------------------------------------------------------------------------------ | Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads | ------------------------------------------------------------------------------------ | 0 | SELECT STATEMENT | | 1 | | 0 |00:00:06.29 | 450K| 8861 | |* 1 | TABLE ACCESS BY INDEX ROWID| I_B2O_OWE_C_BAK | 1 | 1 | 0 |00:00:06.29 | 450K| 8861 | |* 2 | INDEX RANGE SCAN | I_B2O_OWE_C_BDATE_BAK | 1 | 3 | 1068K|00:00:00.01 | 2838 | 0 | ------------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 1 - filter(("ACC_NBR"='18909502122' AND INTERNAL_FUNCTION("PROC_TYPE"))) 2 - access("BEGIN_OWE_DATE">=TO_DATE(' 2015-11-16 23:56:00', 'syyyy-mm-dd hh24:mi:ss'))
情况二:当时间条件取值不超过high value时。
SQL> SELECT /*+ gather_plan_statistics */ SERIAL_NBR FROM BILLUSER.I_B2O_OWE_C_BAK WHERE (PROC_TYPE='13' or PROC_TYPE='14' or 2 PROC_TYPE='S13' or PROC_TYPE='S14') AND BEGIN_OWE_DATE >= 3 TO_DATE('2015-11-16 23:52:00','YYYY/MM/DD HH24:MI:SS') AND ACC_NBR ='18909502122' 4 / no rows selected SQL> select * from table(dbms_xplan.display_cursor(NULL,NULL,'ALLSTATS')); PLAN_TABLE_OUTPUT ------------------------------------------------------------------------------------ SQL_ID 6vrh3x0qqnxnh, child number 0 ------------------------------------- SELECT /*+ gather_plan_statistics */ SERIAL_NBR FROM BILLUSER.I_B2O_OWE_C_BAK WHERE (PROC_TYPE='13' or PROC_TYPE='14' or PROC_TYPE='S13' or PROC_TYPE='S14') AND BEGIN_OWE_DATE >= TO_DATE('2015-11-16 23:52:00','YYYY/MM/DD HH24:MI:SS') AND ACC_NBR ='18909502122' Plan hash value: 1431363508 ----------------------------------------------------------------------------------- | Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads | ----------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | | 0 |00:00:00.40 | 36 | 35 | |* 1 | TABLE ACCESS BY INDEX ROWID| I_B2O_OWE_C_BAK | 1 | 1 | 0 |00:00:00.40 | 36 | 35 | |* 2 | INDEX RANGE SCAN | I_B2O_OWE_C_ACCNBR_BAK | 1 | 7 | 33 |00:00:00.03 | 3 | 2 | ----------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 1 - filter(("BEGIN_OWE_DATE">=TO_DATE(' 2015-11-16 23:52:00', 'syyyy-mm-dd hh24:mi:ss') AND INTERNAL_FUNCTION("PROC_TYPE"))) 2 - access("ACC_NBR"='18909502122')
从上面的测试验证可以看出,当where 条件的时间列取值超过该列的high value时,Oracle 选择了错误的Index。而当时间列取值小于该列的high value时,Oracle 则会选择正确的执行计划。
当取值小于high value时,此时BEGIN_OWE_DATE的选择性为 ((high_value-limit)/(high_value-low_value)+1/num_distinct)即为(2015-11-16 23:55:26 - 2015-11-16 23:50:00 )/(2015-11-16 23:55:26-2015-2-10 21:50:51)+ (7.9253E-07)= 0.000013691。这样计算出来的结果表明begin_owe_date列的选择性要比accnbr列的选择性低。这种情况下Oracle会选择正确的索引。当取值大于high value时,begin_owe_date 列的选择性所计算出来的只要比accnbr要高,这样就会导致Oracle 选择错误的索引。
为什么会出现这样奇怪的情况呢? 实际上是因为当谓词条件取值超过high value时,此时Oracle无法判断,只能进行猜测。而这种情况之下,通常都会导致所计算出来的Card不合理,导致SQL选择错误的执行计划。尤其是针对date列、sequence等情况,相对要常见得多,这是Oracle CBO的一个老问题。
实际上,为了避免这种情况出现,我们要尽可能地保证统计信息的准确性,这样可以最大程度降低地执行计划改变的风险。同时也要改变一种错误的认识,即统计信息不改变,SQL的执行计划不一定一成不变,而事实往往恰恰相反,很可能改变。
当然,对于前面的问题,要解决是相对简单的。由于我们确认ACCNBR列的选择性永远都是非常高的,因此可以通过SQL Profile来固定这个执行计划,可以确保后续的稳定性。
最后针对前面这个SQL执行计划改变的案例进简单总结。由于11月16日至11月30日该业务表数据变动不大,未触发Oracle 对表进行统计信息收集的阈值(数据变更超过10%)时,导致统计信息一直未进行更新。直到12月1日凌晨,随着大量数据的加载和更新,超过统计信息收集的阈值后,Oracle进行了统计信息收集。然而由于Oracle 默认的统计信息收集Job是每周一到周六的晚上22点才进行收集,因此这就会出现一天时间的间隔。在该间隔时间段内,由于统计信息不准确,SQL语句索引列的high value值过旧的问题,导致Oracle 优化器评估出的Card值较小,最后选择了错误的执行计划。