完美的執行計劃導致的效能問題

fengzhanhai發表於2015-01-22
今天現場的開發同事反饋有一個job處理資料的速度很慢,從半夜2點開始執行,結果到了早上8點還沒有執行完,最後無奈kill掉了程式。等我剛到公司,他們想讓我查查倒底是什麼原因導致的執行速度很慢。
首先和他們簡單溝通了下,問最近有什麼新的變更嗎,他們說沒有,平時跑這個job的使用者量不是很大,今天早晨呼叫job的時候使用者量要略微大些。
瞭解了這些我檢視了下資料庫的負載,發現在問題發生的時間段,沒有明顯的效能抖動。

DB_NAME   BEGIN_SNAP   END_SNAP SNAPDATE                 LVL DURATION_MINS     DBTIME
--------- ---------- ---------- ----------------- ---------- ------------- ----------
XXXXX     13222      13223 16 Jan 2015 00:00          1            60         14
               13223      13224 16 Jan 2015 01:00          1            60          1
               13224      13225 16 Jan 2015 02:00          1            60          1
               13225      13226 16 Jan 2015 03:00          1            60        180
               13226      13227 16 Jan 2015 04:00          1            60        260
               13227      13228 16 Jan 2015 05:00          1            60        167
               13228      13229 16 Jan 2015 06:00          1            60        210
               13229      13230 16 Jan 2015 07:00          1            60        138
               13230      13231 16 Jan 2015 08:00          1            60        118
               13231      13232 16 Jan 2015 09:00          1            60        170
               13232      13233 16 Jan 2015 10:00          1            60        221
然後抓取了一個awr報告來看看倒底是哪裡出了問題。
資料庫的整體負載情況如下,可以看出在問題發生的時間段,每秒的redo有2M左右,這個庫的使用不是很頻繁,而且資料量相對來說不是很大,所以相比來說還是比較繁忙的。
Snap Id Snap Time Sessions Cursors/Session
Begin Snap: 13226 16-Jan-15 04:00:22 255 4.3
End Snap: 13228 16-Jan-15 06:00:28 253 4.5
Elapsed:   120.11 (mins)    
DB Time:   427.54 (mins)    

Load Profile

Per Second Per Transaction Per Exec Per Call
DB Time(s): 3.6 0.4 0.00 0.00
DB CPU(s): 0.7 0.1 0.00 0.00
Redo size: 2,840,080.5 347,986.4    
Logical reads: 36,781.2 4,506.7    
Block changes: 4,940.6 605.4    
Physical reads: 1,502.6 184.1    
Physical writes: 488.4 59.8    
User calls: 7,156.8 876.9    
Parses: 12.7 1.6    
Hard parses: 4.1 0.5    
W/A MB processed: 1.0 0.1    
Logons: 0.1 0.0    
Executes: 2,238.8 274.3    
Rollbacks: 0.0 0.0    
Transactions: 8.2      

沒有發現很明顯的效能問題之後,直接進入等待事件和時間模型統計資訊。

Top 5 Timed Foreground Events

Event Waits Time(s) Avg wait (ms) % DB time Wait Class
db file sequential read 4,568,909 14,710 3 57.34 User I/O
DB CPU   5,316   20.72  
db file parallel read 1,557,170 5,163 3 20.13 User I/O
log file sync 58,073 785 14 3.06 Commit
db file scattered read 127,236 194 2 0.75 User I/O
從等待事件來看沒有lock contention相關的等待事件,說明也不大可能是鎖的原因。
Time Model Statistics
Statistic Name Time (s) % of DB Time
sql execute elapsed time 23,044.78 89.83
DB CPU 5,316.31 20.72

從上面可以得出問題還是主要在基於IO消耗的sql上,直接進入”SQL ordered by Elapsed Time"來檢視更多的細節。
可以明顯得看到有一個job消耗了大量的時間,但是在兩個小時的時間內還沒有執行完。這個很可能就是問題所在,其它的sql佔有的比例都不高。
Elapsed Time (s) Executions Elapsed Time per Exec (s) %Total %CPU %IO SQL Id SQL Module SQL Text
7,201.85 0   28.07 7.78 95.17 EnvelopeMT@ccbdbpr5 (TNS V1-V3) SELECT /*+ ordered use_nl (RAT...
1,945.01 3,984 0.49 7.58 8.94 91.79 EnvelopeMT@ccbdbpr5 (TNS V1-V3) /* */ UPDATE TED_EVENT SET L...

檢視“SQL ordered by Gets”, buffer gets有近133G(17,418,703*8k)。就這一個查詢還是相當的龐大的消耗。
Buffer Gets Executions Gets per Exec %Total Elapsed Time (s) %CPU %IO SQL Id SQL Module SQL Text
17,418,703 0   6.57 7,201.85 7.78 95.17 EnvelopeMT@ccbdbpr5 (TNS V1-V3) SELECT /*+ ordered use_nl (RAT...

來看看是什麼樣的sql語句導致瞭如此的效能問題。
語句大體如下:
SELECT /*+ ordered use_nl (RATED_EVENT) index (RATED_EVENT
             RATED_EVENT_1UQ) */  RPR3_CUSTOMER_EX.GROUP_ID, 'USAG'
                     ||RPAD(LTRIM(RATED_EVENT.BA_NO),12)
                     .......
                     ||RPAD(NVL(TRIM(TO_CHAR(L9_DUMMY_STRING_2)),' '),10)
                     ||RPAD(0,9)
                      FROM RPR3_CUSTOMER_EX, RATED_EVENT  WHERE
             RATED_EVENT.CYCLE_CODE=:h_cycleCode AND
             RATED_EVENT.CYCLE_MONTH=:CYCLE_MONTH AND
             RATED_EVENT.SUB_PARTITION_ID=:h_subPartitionId AND
             RATED_EVENT.CUSTOMER_ID=RPR3_CUSTOMER_EX.CUSTOMER_ID AND
             RPR3_CUSTOMER_EX.CYCLE_MONTH=RATED_EVENT.CYCLE_MONTH AND
             RPR3_CUSTOMER_EX.CYCLE_CODE=RATED_EVENT.CYCLE_CODE AND
             RPR3_CUSTOMER_EX.CYCLE_YEAR=RATED_EVENT.CYCLE_YEAR AND  (
             RPR3_CUSTOMER_EX.BA_NO =-1   OR (RATED_EVENT.BA_NO=RPR3_CUSTOMER_
             EX.BA_NO )) AND  RATED_EVENT.CYCLE_YEAR=:h_cycleYear AND
             EVENT_TYPE_ID NOT IN (1110189,7790,33131,1156067) AND (
             EVENT_STATE in ('N') or EVENT_STATE is null ) and
             L9_DISPLAY_ON_BILL='Y'

其中RATED_EVENT這個表相當的大,有近5億條資料,做了分割槽。而RPR3_CUSTOMER_EX這個表比較奇怪,查詢資料,竟然1條資料都沒有。
帶著疑問,檢視了執行計劃,從執行的情況來看著條sql語句沒有什麼問題。
Plan hash value: 1180507974
--------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                          | Name                | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
--------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                   |                     |     1 |   344 |    18   (0)| 00:00:01 |       |       |
|   1 |  NESTED LOOPS                      |                     |       |       |            |          |       |       |
|   2 |   NESTED LOOPS                     |                     |     1 |   344 |    18   (0)| 00:00:01 |       |       |
|*  3 |    INDEX FULL SCAN                 | RPR3_CUSTOMER_EX_PK |     1 |    78 |     3   (0)| 00:00:01 |       |       |
|   4 |    PARTITION RANGE SINGLE          |                     |    12 |       |     1   (0)| 00:00:01 |   KEY |   KEY |
|*  5 |     INDEX RANGE SCAN               | RATED_EVENT_1UQ     |    12 |       |     1   (0)| 00:00:01 |   KEY |   KEY |
|*  6 |   TABLE ACCESS BY LOCAL INDEX ROWID| RATED_EVENT         |     6 |  1596 |    16   (0)| 00:00:01 |     1 |     1 |
--------------------------------------------------------------------------------------------------------------------------

但是為什麼執行計劃如此完美的sql,預計執行時間需要1秒,實際上卻執行了兩個多小時還沒有執行完。
我的關注點都集中在了RPR3_CUSTOMER_EX這個表上,表裡沒有資料,執行計劃也沒有問題,但是執行時間卻相差幾千倍。

帶著這個疑問和開發再次溝通,沒有得到太多相關的細節。最後抓取了一個addm報告。
得到的一個建議和這條sql有關。
 Rationale
      The SQL spent 100% of its database time on CPU, I/O and Cluster waits.
      This part of database time may be improved by the SQL Tuning Advisor.
   Rationale
      Database time for this SQL was divided as follows: 100% for SQL
      execution, 0% for parsing, 0% for PL/SQL execution and 0% for Java
      execution.
   Rationale
      I/O and Cluster wait for TABLE PARTITION
      "RATED_EVENT.C25_M10_S8" with object ID 672092 consumed 75% of
      the database time spent on this SQL statement.
   Rationale
      I/O and Cluster wait for INDEX PARTITION
      "RATED_EVENT_1UQ.C25_M10_S8" with object ID 672095 consumed 24%
      of the database time spent on this SQL statement.

可以看到大量的IO都在一個分割槽 C25_M10_S8上面,看到這個自己的第一反應是可能統計資訊導致的。目前在生產環境中沒隔一段時間都會收集一次統計資訊。
partiton_name              high_value    tablespace_name    LOGGING              analyzed_time
C25_M10_S6                25, 10, 30      DATAH01             1 YES     DISABLED YES     06-DEC-14
C25_M10_S7                25, 10, 35      DATAH01             1 YES     DISABLED YES 24-NOV-14
C25_M10_S8                25, 10, 40      DATAH01             1 YES     DISABLED YES 16-DEC-14
C25_M10_S9                25, 10, 45      DATAH01             1 YES     DISABLED YES 24-NOV-14
C25_M10_S10               25, 10, 50      DATAH01             1 YES     DISABLED YES 24-NOV-14
可以看到分割槽的統計時間是在上個月中,檢視了下這個分割槽中的資料情況,發現和資料字典中的統計資訊基本沒有差別。
SQL> set time on
12:44:45 SQL> set timing on 
12:44:48 SQL> select  /*+ index_ffs(RATED_EVENT,RATED_EVENT_1UQ ) parallel_index(RATED_EVENT,RATED_EVENT_1UQ,8) */  count(*) from RATED_EVENT partition(c25_m10_s8) ;
  11067075
Elapsed: 00:00:02.04

所以問題又回到了原點,這個問題看似很清晰,但是又從道理上說不通。
轉眼一想,那個rpr3的表可能是臨時表,這樣問題就能解釋通了。為了簡單驗證,自己嘗試匯出這個表,然後檢視對應的建表語句是下面的樣子。
CREATE GLOBAL TEMPORARY TABLE "RPR3_CUSTOMER_EX"
    ("CUSTOMER_ID" NUMBER(9, 0) CONSTRAINT "RPR3CRE_CUSTOMER_ID_NN" NOT NULL ENABLE,
    "SYS_CREATION_DATE" DATE CONSTRAINT "RPR3CRE_SYS_CREATION_DATE_NN" NOT NULL ENABLE,
    "SYS_UPDATE_DATE" DATE,
。。。
    "BA_NO" NUMBER(12, 0) CONSTRAINT "RPR3CRE_BA_NO_NN" NOT NULL ENABLE) ON COMMIT DELETE ROWS 
這樣的話問題,就能說通了,至於為什麼查詢表中的資料是0條,一下子也就明朗了。
那麼至於為什麼效能變化這麼大呢,這個還得從表分割槽的統計資訊來說,這個表有5億多條記錄,查詢語句中的相關分割槽有1千5多萬的資料量,
很可能是什麼地方執行計劃出現了某些偏差造成的。
重新審視sql語句,發現開始的Hint還是值得注意的。
SELECT /*+ ordered use_nl (RATED_EVENT) index (RATED_EVENT
             RATED_EVENT_1UQ) */  
對於這條sql語句的調優就相對來說有針對性了。表RPR3_CUSTOMER_EX是個臨時表,表中的資料可能是不固定的。和開發做了進一步的確認,這個表中的資料還是很少的。
如果記錄數很少,可以按照最佳化器預設的執行情況來做,就不需要手工干預了。表RPR3_CUSTOMER_EX中的資料很少,就完全可以走一個全表掃描和RATED_EVENT關聯即可。
使用sqlp_profile再次驗證了這個想法。執行情況也要更加穩定。
2- Using SQL Profile
--------------------
Plan hash value: 2402883198
----------------------------------------------------------------------------------------------------------------------
| Id  | Operation                         | Name             | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
----------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                  |                  |     1 |   344 |    18   (0)| 00:00:01 |       |       |
|*  1 |  TABLE ACCESS BY LOCAL INDEX ROWID| RATED_EVENT      |     6 |  1596 |    16   (0)| 00:00:01 |       |       |
|   2 |   NESTED LOOPS                    |                  |     1 |   344 |    18   (0)| 00:00:01 |       |       |
|*  3 |    TABLE ACCESS FULL              | RPR3_CUSTOMER_EX |     1 |    78 |     2   (0)| 00:00:01 |       |       |
|   4 |    PARTITION RANGE SINGLE         |                  |    12 |       |     1   (0)| 00:00:01 |   KEY |   KEY |
|*  5 |     INDEX RANGE SCAN              | RATED_EVENT_1UQ  |    12 |       |     1   (0)| 00:00:01 |   KEY |   KEY |
----------------------------------------------------------------------------------------------------------------------
從這個案例來看,發現了問題,在問題解釋不通的情況下,不要輕易放棄,多想想方法來佐證自己的推論才可能發現最終的問題。而且看似完美的執行計劃並不能說明效能一定是好的,穩定的,需要根據具體的情況來評估。



來自 “ ITPUB部落格 ” ,連結:http://blog.itpub.net/25723371/viewspace-1411470/,如需轉載,請註明出處,否則將追究法律責任。

相關文章