job處理緩慢的效能問題排查與分析

dbhelper發表於2015-01-31
昨天開發的同事找到我說，生產有個job處理資料的速度很慢，想讓我幫忙看看是怎麼回事，最近碰到這種問題相對比較多了，但是問題的原因也是五花八門。我還是大體找他們瞭解了下情況，說有一個Job是處理檔案傳輸的，但是從目前的執行情況來看，處理速度很慢，基本沒什麼進展，我向他們確認這幾天是否有資料變更的操作，他們說沒有。得到這個確認檢視問題的方向就有明顯的不同，我還是照例檢視了一下資料庫負載，鎖情況。但是麼有發現什麼資訊。
從資料庫的負載來看，負載倒不高。
Snap Id Snap Time Sessions Cursors/Session
Begin Snap: 17844 16-Jan-15 12:00:37 303 4.2
End Snap: 17845 16-Jan-15 13:00:40 303 4.4
Elapsed:   60.04 (mins)    
DB Time:   119.10 (mins)    

Load Profile

Per Second Per Transaction Per Exec Per Call
DB Time(s): 2.0 0.1 0.00 0.00
DB CPU(s): 1.2 0.1 0.00 0.00
Redo size: 1,222,354.8 56,665.6    
Logical reads: 54,092.4 2,507.6    
Block changes: 4,395.0 203.7    
Physical reads: 5,172.7 239.8    
Physical writes: 273.2 12.7    
User calls: 4,952.3 229.6    
Parses: 12.9 0.6    
Hard parses: 1.1 0.1    
W/A MB processed: 1.0 0.1    
Logons: 0.1 0.0    
Executes: 3,000.2 139.1    
Rollbacks: 0.0 0.0    
Transactions: 21.6      


接下來看看等待事件，還是沒有發發現特殊之處。

Top 5 Timed Foreground Events

Event Waits Time(s) Avg wait (ms) % DB time Wait Class
DB CPU   4,204   58.83  
db file sequential read 1,539,592 3,003 2 42.03 User I/O
log file sync 79,884 164 2 2.30 Commit
direct path read 14,973 68 5 0.95 User I/O
control file sequential read 43,790 18 0 0.25 System I/O

從時間模型的情況來看，資源消耗還在在I/O上。
Statistic Name Time (s) % of DB Time
sql execute elapsed time 6,440.43 90.12
DB CPU 4,204.39 58.83
RMAN cpu time (backup/restore) 88.32 1.24

這個時候和開發做一個簡短的溝通，最起碼得明確一些資訊，要不大海撈針的查問題還是針對性不強，他們說Job處理速度慢，是哪個job呢，他們反饋說是MF1ppMD的job
我從Sql Order by Elapsed time中查得MFppMD的相關top sql有幾個，但是這幾個語句執行時間都很短，都在0.01秒以內，效能算是不錯的了。

Elapsed Time (s)

Executions

Elapsed Time per Exec (s)

%Total

%CPU

%IO

SQL Id

SQL Module

SQL Text

898.97

14,042

0.06

12.58

99.81

0.00

pm1EnvelopeMT@ccbdbpr2 (TNS V1-V3)

/* */ select count (1) from RP...

775.20

1,671,968

0.00

10.85

23.36

79.06

pm1EnvelopeMT@ccbdbpr2 (TNS V1-V3)

/* */ SELECT CYCLE_CODE, CYCLE...

722.13

1,167,005

0.00

10.10

12.88

91.02

MF1ppMD@ccbdbpr1 (TNS V1-V3)

select L9_SPLIT_PERIOD into :b...

717.11

14,042

0.05

10.03

99.84

0.00

pm1EnvelopeMT@ccbdbpr2 (TNS V1-V3)

/* */ select count (1) from RP...

478.57

368,271

0.00

6.70

7.07

95.56

pm1EnvelopeMT@ccbdbpr2 (TNS V1-V3)

/* */ SELECT SUBSCRIBER_ID, EF...

394.40

1,167,196

0.00

5.52

39.54

63.55

MF1ppMD@ccbdbpr1 (TNS V1-V3)

select sk.rowid , sk.subscribe...

338.74

12,793

0.03

4.74

14.76

86.26

pm1EnvelopeMT@ccbdbpr2 (TNS V1-V3)

INSERT INTO RATED_EVENT (L3_NE...

236.40

1

236.40

3.31

81.22

9.47

oracle@ccbstbpr2 (TNS V1-V3)

SELECT "A1"."TABLE_ISSUE_CODE"...

228.46

1

228.46

3.20

83.76

6.67

oracle@ccbstbpr2 (TNS V1-V3)

SELECT "A1"."TABLE_ISSUE_CODE"...

198.10

1

198.10

2.77

79.23

10.20

TOAD 9.6.0.27

select*from ac1_control_hist w...

197.33

368,304

0.00

2.76

11.04

91.58

pm1EnvelopeMT@ccbdbpr2 (TNS V1-V3)

/* */ SELECT SUBSCRIBER_ID, DY...

136.72

1,166,948

0.00

1.91

34.69

67.32

MF1ppMD@ccbdbpr1 (TNS V1-V3)

select ROWID , BAN , COMPANY_C...

85.23

555,724

0.00

1.19

53.23

49.46

pm1EnvelopeMT@ccbdbpr2 (TNS V1-V3)

/* */ Update RPR1_SUBS_RERATE ...

80.38

196,631

0.00

1.12

22.43

79.87

pm1EnvelopeMT@ccbdbpr2 (TNS V1-V3)

/* */ SELECT SUBSCRIBER_ID, OF...

72.03

4,448

0.02

1.01

29.52

71.04

MF1ppMD@ccbdbpr1 (TNS V1-V3)

insert into MF1_DUPCHECK_KEYS ...


從系統最佳化的角度來說，ppMD的效能問題還是比較奇怪的。
繼續檢視其它的指標型別，一邊注意ppMD相關的job，一邊留意是否是其它的原因導致的。
當我看到Sql Order by Executions的時候。注意到一個奇怪的地方，執行頻率最高的正是ppMD這個job

Executions

Rows Processed

Rows per Exec

Elapsed Time (s)

%CPU

%IO

SQL Id

SQL Module

SQL Text

2,333,806

0

0.00

43.03

106.28

0.00

MF1ppMD@ccbdbpr1 (TNS V1-V3)

select ROWID , PRIM_RESOURCE_T...

1,671,968

1,664,009

1.00

775.20

23.36

79.06

pm1EnvelopeMT@ccbdbpr2 (TNS V1-V3)

/* */ SELECT CYCLE_CODE, CYCLE...

1,167,196

1,166,977

1.00

394.40

39.54

63.55

MF1ppMD@ccbdbpr1 (TNS V1-V3)

select sk.rowid , sk.subscribe...


但是仔細檢視會發現一個奇怪的現象， Rows Processed卻是0.這是一個比較特殊的情況，這個引數代表的意思是SQL在快照時間內累計執行所處理的總行數。代表0說明執行了幾百萬次，但是沒有任何資料處理，相當於空跑。
來看看執行的sql語句是什麼。

select ROWID,

       PRIM_RESOURCE_TP,

       PRIM_RESOURCE_VAL,

       TO_CHAR(EFFECTIVE_DATE, 'YYYYMMDDHH24MISS'),

       TO_CHAR(EXPIRATION_DATE, 'YYYYMMDDHH24MISS'),

       TO_CHAR(SYS_CREATION_DATE, 'YYYYMMDDHH24MISS'),

       TO_CHAR(SYS_UPDATE_DATE, 'YYYYMMDDHH24MISS'),

       OPERATOR_ID,

       APPLICATION_ID,

       DL_SERVICE_CODE,

       DL_UPDATE_STAMP,

       FUTURE_1,

       FUTURE_2,

       FUTURE_3

  into :b0  :b1,

       :b2  :b3,

       :b4  :b5,

       :b6  :b7,

       :b8  :b9,

       :b10 :b11,

       :b12 :b13,

       :b14 :b15,

       :b16 :b17,

       :b18 :b19,

       :b20 :b21,

       :b22 :b23,

       :b24 :b25,

       :b26 :b27

  from MI9_PAID_SUBSCR

where (((PRIM_RESOURCE_TP = :b2 and PRIM_RESOURCE_VAL = :b4) and

       EFFECTIVE_DATE <= TO_DATE(:b6, 'YYYYMMDDHH24MISS')) and

       (EXPIRATION_DATE is null or

       EXPIRATION_DATE > TO_DATE(:b6, 'YYYYMMDDHH24MISS')))

這是一個很簡單的查詢，一看這個表，我就恍然大悟了，這個表是在這兩天才做的變更，在最新的需求中需要建立這個表，從目前的需求來看，這個表需要同步一些資料，但是資料的同步機制還沒有達成共識，所以最後臨時決定先把這個表建立好，讓job在校驗的時候不出錯，但是表裡面沒有資料，暫時先按照dummy表來處理。但是在升級中沒有包含這個變更,只是提供了臨時的補丁做了修復。
看來這個dummy表還是對資料的處理造成了嚴重的影響，導致了Job空跑。開發有時候提供的資訊還是需要斟酌的，不一定都是正確的。需要我們在特定的問題情況下去確認。
最後和開發做了溝通，他們在做了進一步的分析之後確認是這個新表導致的問題，需要進一步討論技術實現細節。
最後小結一下。
可能有些問題的處理和診斷，不一定是IO,CPU等異常導致的，很可能是業務層出現的問題，需要我們從awr報告中發現細節來佐證自己的判斷。
有時候問題排查的方向需要自己來按照合理的流程來做，有時候客戶，同事提供的資訊自己需要辨識，可能有些問題是他們沒有意識到，但是對問題排查的方向影響還是比較大的。


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

相關文章