天天看點

一個SQL性能問題的優化探索(二)(r11筆記第38天)

如下的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使用率較高,檢視資料庫層面的負載也突然有了較大的抖動。

一個SQL性能問題的優化探索(二)(r11筆記第38天)

定位到相關的語句如下:

   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在運作。

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

這個時候檢視語句的執行計劃情況,隻有全表掃描的執行計劃。

一個SQL性能問題的優化探索(二)(r11筆記第38天)

明顯不合理嘛。看起來問題又想回到了原點。

這個時候不要氣餒,我們重新捋一捋資訊,列的統計資訊的情況如下:

>  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

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)