继续前几天的一个案例一个SQL性能问题的优化探索（一）(r11笔记第33天)
如下的SQL语句存在索引字段CARD_NO,但是执行的时候却走了全表扫描，因为这是一个核心表，数据量很大，导致数据库负载很高。
SQL_FULLTEXT
----------------------------------------------------------------------------------------------------
SELECT ID,CN,CARD_NO,TO_CHAR(CHARGE_DATE,'yyyy-MM-dd HH24:mi:ss') AS CHARGE_DATE ,IP,POINT,PRESENT_P
OINT,SUCCESS,CARD_TYPE,PRODUCTNUM,SALEMETHOD,ITEM_ID,SERVICEID,ORDER_NO,TO_CHAR(EXPIREDATE,'yyyy-MM-
dd HH24:mi:ss') AS EXPIREDATE,REMARK FROM RECHARGE_LOG WHERE CARD_NO = TO_NUMBER(:1)
对于这个问题，苦于无法复现，通过各种途径进行分析，有些信息似乎有些矛盾。如果说是统计信息的问题，但是查看直方图的信息是有的。而且分为了200多个bucket，索引列card_no的统计信息也没有发现什么问题。而且比较奇怪的是问题发生后查看执行计划情况，后面的语句是可以走索引的。这个问题怎么来进一步分析呢。
我们可以化被动为主动，我对这个列对应的索引添加了索引监控，即alter index xxxx monitoring usage;然后有了这个标识之后，就可以随时查看v$object_usage查看索引是否被启用，当然这个视图得到的信息毕竟很有限。我们只能知道索引是否被启用，但是每次启用的时间等这些没法定位，而且因为走了索引本身执行效率就很高，所以在快照中是很可能不会被收编进来的。
这个问题还有一个疑点就是统计信息的收集时间，和同事确认问题发生当天他是没有收集统计信息的，但是查看字段last_analyzed的时间却恰恰是发生收集以后。
问题暂时搁置下来，在这两天问题有了进一步的发现，另外一个报警引起了我的注意。报警是CPU使用率较高，查看数据库层面的负载也突然有了较大的抖动。
定位到相关的语句如下：
SNAP_ID SQL_ID EXECUTIONS_DELTA ELAPSED_TI PER_TOTAL
---------- ------------- ---------------- ---------- ----------
108829 bbtwpb1aamud2 0 1766s 45%
108829 7zmnkpfaumuk1 1 1141s 29%
108829 4y30fbyjmrrqr 1 432s 11%
108829 f7h0xrkw1wy48 1 192s 4%
108829 63t40nvuuwrdp 258730 116s 2%
可以看到明显有几个SQL执行效率较差。
查看TOP 1的语句发现竟然是一个JOB在运行。
SQL_FULLTEXT
----------------------------------------------------------------------------------------------------
DECLARE job BINARY_INTEGER := :job; next_date TIMESTAMP WITH TIME ZONE := :mydate; broken BOOLEAN
:= FALSE; job_name VARCHAR2(30) := :job_name; job_subname VARCHAR2(30) := :job_subname; job_owner
VARCHAR2(30) := :job_owner; job_start TIMESTAMP WITH TIME ZONE := :job_start; job_scheduled_start
TIMESTAMP WITH TIME ZONE := :job_scheduled_start; window_start TIMESTAMP WITH TIME ZONE := :window
_start; window_end TIMESTAMP WITH TIME ZONE := :window_end; BEGIN BEGIN
dbms_stats.gather_table_stats(ownname=>'TEST',tabname=>'RECHARGE_LOG',cascade=>true);
END; :mydate := next_date; IF broken THEN :b := 1; ELSE :b := 0; END IF; END;
语句的核心就是dbms_stats的部分，竟然是收集表recharege_log的统计信息。
后面的几个语句也是收集统计相关的递归SQL，我列举出一个是因为这里面有非常重要的一个信息。先卖个关子。
$sh showsqltext.sh 7zmnkpfaumuk1
insert /*+ append */ into
sys.ora_temp_1_ds_33892 select /*+ no_parallel(t) no_parallel_index(t)
dbms_stats cursor_sharing_exact use_weak_name_resl dy
namic_sampling(0)
no_monitoring */"CHARGE_DATE","SERVICEID","ORDER_NO","EXPIREDATE",
rowid SYS_DS_ALIAS_0 from "TEST"."RECHARGE_LOG" sample ( 12.12452
80643) t
这个时候查看语句的执行计划情况，只有全表扫描的执行计划。
明显不合理嘛。看起来问题又想回到了原点。
这个时候不要气馁，我们重新捋一捋信息，列的统计信息的情况如下：
> select column_name,histogram from dba_tab_col_statistics
where table_name='RECHARGE_LOG';
COLUMN_NAME HISTOGRAM
-------------------- ---------------
ID NONE
CN HEIGHT BALANCED
CARD_NO HEIGHT BALANCED
CHARGE_DATE HEIGHT BALANCED
IP HEIGHT BALANCED
POINT FREQUENCY
PRESENT_POINT NONE
SUCCESS FREQUENCY
CARD_TYPE FREQUENCY
PRODUCTNUM NONE
SALEMETHOD FREQUENCY
ITEM_ID FREQUENCY
SERVICEID NONE
ORDER_NO HEIGHT BALANCED
REMARK NONE
EXPIREDATE NONE
ID NONE
CN NONE
CARD_NO NONE
CHARGE_DATE NONE
IP NONE
POINT NONE
....
看起来有点不大对劲，因为CARD_NO的直方图信息是空的。
查看另外一个数据字典，发现这个列的直方图信息竟然是存在的，输出有上百行。
select to_char(endpoint_value) value,endpoint_number,column_name ,ENDPOINT_ACTUAL_VALUE from dba_tab_histograms where table_name = 'RECHARGE_LOG' and column_name in ('CARD_NO') ORDER BY endpoint_number
所以这个问题就比较有意思了，存在直方图的列的统计信息，但是两个视图中信息却有些冲突。
由此一来可以推断是这个地方导致全表扫描的一个原因。
我们来看看另外一个潜在的问题，收集统计信息的部分，可以看到是在凌晨3点运行，明显就是一个定时任务。所以同事所说的没有手工收集统计信息是真实的。
select table_name,
to_char(LAST_ANALYZED,'YYYY-MM-DD HH24:MI:SS') LAST_ANALYZED
from dba_tables where TABLE_NAME='RECHARGE_LOG';
TABLE_NAME LAST_ANALYZED
------------------------------ -------------------
RECHARGE_LOG 2017-01-07 03:40:45
还有一个问题，那就是收集统计信息，怎么会有这些影响呢，我们得看看dbms_stats.gather_table_stats的参数method_opt,因为method_opt:决定histograms信息是怎样被统计的.method_opt的取值(默认值为FOR ALL COLUMNS SIZE AUTO)，也就意味着是一个动态的过程。这不card_no摊上事情了，直接忽略了，没收集。
关于这个问题，可以参考一个bug
Bug 5949981 - Bad cardinality with histogram (Doc ID 5949981.8)
而问题原因跟进一步，为什么card_no没有收集统计信息。可以参考一条SQL语句的执行计划变化探究（r10笔记第9天） 原因也是大同小异。