某物流系統資料庫故障診斷案例分析

jelephant發表於2015-10-27

故障現象:

某物流公司新上一套軟體系統,資料庫CPU佔用率基本維持在80%以上,業務高峰期資料庫當機。

 

知識預覽:

LGWR什麼時候開始工作的,觸發他的動作?

  A. 重做日誌緩衝區的已使用的空間達到三分之一時

  B. 當dbwn程式向磁碟寫入已修改的緩衝區的時候

  C. 每隔3秒鐘

  D. 使用者提交事務處理時的一條提交記錄(經常commit會及時重新整理重做日誌緩衝區空間)

 

LGWR什麼時候開始工作的?

  A. 重做日誌緩衝區的已使用的空間達到三分之一時

  B. 當DBWn程式向磁碟寫入已修改的緩衝區的時候

  C. 每隔3秒鐘

  D. 使用者提交事務處理時

 

什麼情況下會產生Log file sync等待事件?



1.使用者程式發起commit

  2.使用者程式通知LGWR寫日誌

3.LGWR接收到請求開始寫

4.LGWR寫完成

5.LGWR通知使用者程式寫完成

6.使用者程式獲得通知,繼續做其他事

1,2階段的時間,主要是使用者提交等待時間,如果系統CPU資源充足,在這個階段一般不會出現大的延遲。前臺程式提交到LGWR後,就開始等待log file sync。

2,3階段的時間,主要是LGWR為了獲取CPU資源,等待cpu排程的時間.如果系統CPU資源充足,一般不會出現大的延遲。

3,4階段的時間,主要是真正的物理IO時間,LGWR通知OS把log buffer的內容寫入到磁碟,然後LGWR進入睡眠,這個時間正常情況下的延遲佔整個log file sync的大部分時間。

4,5階段的時間,OS排程lgwr 重新獲得cpu資源,lgwr post前臺程式寫完成。lgwr可能會post很多前臺程式

5,6階段的時間,前臺程式接受到lgwr的通知,返回cpu執行佇列,處理其他事物(log file sync結束)。

 

Log file sync等待事件有哪些優化方案?

儘量使用快速磁碟,不要把redo log file存放在raid 5的磁碟上;

加大日誌緩衝區(log buffer);

使用批量提交,減少提交的次數;

部分經常提交的事務設定為非同步提交;

安裝最新版本資料庫避免bug;

 

環境:

 

Platform

CPUs

Cores

Sockets

Memory(GB)

iZ28vfyim2vZ

Microsoft Windows x86 64-bit

8

8

1

16.00

資料庫執行在一臺8核16G記憶體Windows上;這臺伺服器上同時還執行著web應用。

 

資料庫基本資訊:

DB Name

DB Id

Instance

Inst num

Startup Time

Release

RAC

PMDB

128847122

pmdb

1

27-Feb -15 21:02

11.2.0.1.0

NO

 

AWR資料庫效能取樣報告:

 

Snap Id

Snap Time

Sessions

Cursors/Session

Begin Snap:

6603

3-Mar-15 14:30:15

80

2.2

End Snap:

6604

3-Mar-15 15:30:20

82

3.0

Elapsed:

 

239.56 (mins)

 

 

DB Time:

 

5205.71(mins)

 

 

問題時間段60分鐘的AWR資料庫效能取樣報告,DB Time為5205分鐘,CPU數為8核,平均每個CPU忙於執行任務的時間為5205/8=650mins分鐘,而資料庫處理任務花費的時間為239mins,忙於執行任務時間遠遠大於處理任務花費的時間。

 

TOP5事件:

Event

Waits

Time(s)

Avg wait (ms)

% DB time

Wait Class

DB CPU

 

22,574

 

42.59

 

log file sync

25,313

310

12

0.58

Commit

db file sequential read

10,645

24

2

0.05

User I/O

direct path read

9,191

22

2

0.04

User I/O

latch:cache buffers chains

127,566

13,136

103

4.21

Concurrency

Top 5 Event可以看出,DB CPU消耗超高,佔 42.59% 的事件比例;

而日誌檔案同步等待事件單次等待達到12毫秒,這表明IO可能存在遲緩;

併發latch:cache buffers chains事件平均等待時間也超高,這個事件,很大程式上與邏輯讀有關,說明可能邏輯讀比較大。

 

負載概要資訊:

 

Per Second

Per Transaction

Per Exec

Per Call

DB Time(s):

14.7

3.0

0.07

0.02

DB CPU(s):

6.3

1.3

0.03

0.01

Redo size:

55,291.8

11,421.6

 

 

Logical reads:

662,383.2

136,828.5

 

 

Block changes:

189.9

39.2

 

 

Physical reads:

7.0

1.5

 

 

Physical writes:

19.9

4.1

 

 

User calls:

883.5

182.5

 

 

Parses:

21.1

4.4

 

 

Hard parses:

3.4

0.7

 

 

W/A MB processed:

1,170.6

241.8

 

 

Logons:

1.2

0.3

 

 

Executes:

214.9

44.4

 

 

Rollbacks:

0.0

0.0

 

 

Transactions:

5.0

 

 

 

資料庫每秒僅僅摺合5個事務,而此前的日誌檔案同步等待事件較高,這說明IO資源可能被其他操作佔用。

除了事務之外,應該就是查詢,也就是說,可能有大量低效查詢消耗盡了IO資源。

 

主機CPU

Load Average Begin

Load Average End

%User

%System

%WIO

%Idle

 

 

88.3

3.8

 

8.0

從主機層面來看,CPU空閒只有8.0%,表明目前cpu基本滿負荷運轉了。


例項CPU

%Total CPU

%Busy CPU

%DB time waiting for CPU (Resource Manager)

83.6

90.8

0.0

從資料庫佔用CPU資源來看,資料庫消耗了主機cpu資源的83.6%,說明大量的cpu資源都是由oracle消耗了。


記憶體統計資訊:

 

Begin

End

Host Mem (MB):

 16,383.6

16,383.6

SGA use (MB):

2,144.0

2,144.0

PGA use (MB):

1,018.7

1,018.7

% Host Mem used for SGA+PGA:

19.30

19.30

主機記憶體16G,其中SGA:2G、PGA:1G,記憶體小了,資料在Buffer cache中快取的就少,前面我們注意到邏輯讀超高,這將導致物理讀,從而解釋了IO資源遲緩的問題。


SQL邏輯讀:

Buffer Gets

Executions

Gets per Exec

%Total

Elapsed Time (s)

%CPU

%IO

SQL Id

SQL Module

SQL Text

1,171,388,996

90,764

12,905.88

46.05

30,514.20

44.7

0

6t0q3nw8b2b68

JDBC Thin Client

select * from ( select row_.*,...

554,429,813

42,299

13,107.40

32.22

9,923.23

40.9

0

btn84j9rhuf4h

JDBC Thin Client

select * from ( select row_.*,...

503,809,511

127,506

3,951.26

11.10

7,669.52

37.3

0

cp9wdanzmzj4q

JDBC Thin Client

select * from (select JOBID, S...

30,497,069

2,331

13,083.26

1.28

409.63

42.2

0

fqjyuzjgm89qv

JDBC Thin Client

select * from ( select trunc(P...

total列表明這個sql執行時間佔據db time的比例,第一個這個比值達到46.05%,顯然這個SQL導致的邏輯讀,消耗了大量的IO資源。

 

段邏輯讀:

Owner

Tablespace Name

Object Name

Subobject Name

Obj. Type

Logical Reads

%Total

PMSOFT

PMTABLESPACE

PM_EXTRACT_GOODS

 

TABLE 

2,145,895,024

89.21

PMSOFT

PMTABLESPACE_IDX

PM_GOODS_LETTER_LL_PK

 

INDEX

35,438,144

1.48

PMSOFT

PMTABLESPACE

PM_GOODS_HANDLE_INFO

 

TABLE 

18,438,384

0.77

PMSOFT

PMTABLESPACE_IDX

PM_TRACE_GOODS_GOODID

 

INDEX

17,049,488

0.71

PMSOFT

USER

PM_LINE_INFO

 

TABLE

5,766,448

0.24

在"Segments by Logical Reads"部分可以看到,邏輯讀集中在一個物件上,第一位的表佔用89.21%的邏輯讀。

 

問題彙總及解決方法:

1、資料庫安裝在Windows上

資料庫遷移到Linux上,增加穩定性。

2、資料庫與WEB應用部署在同一臺伺服器上

資料庫和WEB應用分開部署,減少其它應用對伺服器的壓力。

3、資料庫版本11.0.2.1較低

資料庫版本升級成11.0.2.4,減少軟體Bug造成的影響。

4、資料庫使用預設例項,採用預設配置引數

加大記憶體、日誌緩衝區、閃回恢復區、增加日誌組數。

5、表PM_EXTRACT_GOODS貢獻的邏輯讀異常大

解決邏輯讀問題。

以上解決步驟不再詳述,下面看一下如何降低邏輯讀。

 

如何降低邏輯讀?

1、複查應用程式,減少查詢?

經過分析,這張表是主要業務表,沒法減少查詢。

2、檢視相關SQL的執行計劃,然後進行優化?

我就是用的這個,當然還有很多其它的方式,可以確定是否是因為熱點塊問題造成的、增加DBWn程式個數、建立反向索引、小buffer cache等等。

 

檢視問題SQL執行計劃:

select * from ( select row_.*, rownum rownum_ from ( select letter.bill_no bill_no, letter.id receive_id, letter.goods_desc, letter.receiver_name, letter.receiver_phone, letter.sender_name, letter.sender_phone, letter.hm_npay, letter.hm_paid, letter.insur_coverage, letter.insur_cost, letter.ag_fund, TO_CHAR(letter.createdate, 'yyyy-MM-dd HH24:MI:SS') bill_date, letter.fdept_id, letter.fdept_code, letter.fdept_name, letter.tdept_id, letter.tdept_code, letter.tdept_name, letter.ticket_no, bigg.remark, bigg.les_num, bigg.id , TO_CHAR( bigg.handle_time, 'yyyy-MM-dd HH24:MI:SS') handle_time from pm_goods_letter letter left join (select * from pm_extract_goods gin2 where (gin2.receive_id, gin2.handle_time) in ( select gin.receive_id, max(gin.handle_time) from pm_extract_goods gin group by gin.receive_id)) bigg on bigg.receive_id=letter.id where 1=1 AND (letter.fdept_id =:1 or letter.tdept_id=:2) ) row_ ) where rownum_ > 0 and rownum_ <= 20

執行計劃如下:

通過執行計劃,我們能夠發現,可能是索引缺失導致了全表的掃描。

嘗試解決問題:

在表PM_EXTRACT_GOODS的receive_id和handle_time欄位建一個組合索引,問題解決。

 

優化前後對比

資料庫基本資訊

優化前,資料庫安裝在Windows server 2008 R2下,8核,記憶體16G,資料庫版本11.2.0.1.0

Host Name

Platform

CPUs

Cores

Sockets

Memory(GB)

iZ28vfyim2vZ

Microsoft Windows x86 64-bit

8

8

1

16.00

 

DB Name

DB Id

Instance

Inst num

Startup Time

Release

RAC

PMDB

128847122

pmdb

1

27-Feb -15 21:02

11.2.0.1.0

NO

 

優化後,資料庫安裝在CentOS6.5下,16核,記憶體64G,資料庫版本11.2.0.4.0

Host Name

Platform

CPUs

Cores

Sockets

Memory(GB)

iZ28od1kf25Z

Linux x86 64-bit

16

16

1

62.90

 

DB Name

DB Id

Instance

Inst num

Startup Time

Release

RAC

PMDB

135174046

pmdb

1

05-Mar-15 00:03

11.2.0.4.0

NO

 

AWR資料庫效能取樣報告

優化前

 

Snap Id

Snap Time

Sessions

Cursors/Session

Begin Snap:

6603

3-Mar-15 14:30:15

80

2.2

End Snap:

6604

3-Mar-15 15:30:20

82

3.0

Elapsed:

 

239.56 (mins)

 

 

DB Time:

 

5205.71(mins)

 

 

優化後

 

Snap Id

Snap Time

Sessions

Cursors/Session

Begin Snap:

36

06-Mar-15 14:30:05

49

3.7

End Snap:

37

06-Mar-15 15:30:11

49

3.7

Elapsed:

 

180.10 (mins)

 

 

DB Time:

 

23.35 (mins)

 

 


TOP5事件

優化前

Event

Waits

Time(s)

Avg wait (ms)

% DB time

Wait Class

DB CPU

 

22,574

 

42.59

 

log file sync

25,313

310

12

0.58

Commit

db file sequential read

10,645

24

2

0.05

User I/O

direct path read

9,191

22

2

0.04

User I/O

latch:cache buffers chains

127,566

13,136

103

4.21

Concurrency

優化後

Event

Waits

Time(s)

Avg wait (ms)

% DB time

Wait Class

DB CPU

 

1,267.9

 

20.5

 

reliable message

2,281

1.2

0

0.0

Other 

SQL*Net more data from client

27,707

0.6

0

0.0

Network 

SQL*Net message to client

205,173

0.3

0

0.0

Network 

db file sequential read

3,612

0.1

0

0.0

User I/O


負載概要資訊

優化前

 

Per Second

Per Transaction

Per Exec

Per Call

DB Time(s):

14.7

3.0

0.07

0.02

DB CPU(s):

6.3

1.3

0.03

0.01

Redo size:

55,291.8

11,421.6

 

 

Logical reads:

662,383.2

136,828.5

 

 

Block changes:

189.9

39.2

 

 

Physical reads:

7.0

1.5

 

 

Physical writes:

19.9

4.1

 

 

User calls:

883.5

182.5

 

 

Parses:

21.1

4.4

 

 

Hard parses:

3.4

0.7

 

 

W/A MB processed:

1,170.6

241.8

 

 

Logons:

1.2

0.3

 

 

Executes:

214.9

44.4

 

 

Rollbacks:

0.0

0.0

 

 

Transactions:

5.0

 

 

 

優化後

 

Per Second

Per Transaction

Per Exec

Per Call

DB Time(s):

0.1

0

0.00

0.00

DB CPU(s):

0.1

0

0.00

0.00

Redo size:

7,989.4

1,900.1

 

 

Logical reads:

23,833.5

5,668.3

 

 

Block changes:

46.5

11.1

 

 

Physical reads:

7.0

1.5

 

 

Physical writes:

4.4

1.1

 

 

Read IO requests:

62.2

14.8

 

 

Write IO requests:

2.7

0.6

 

 

Read IO (MB):

57.2

13.6

 

 

Write IO (MB):

0.0

0.0

 

 

User calls:

51.8

12.3

 

 

Parses:

22.5

5.3

 

 

Hard parses:

0.7

0.2

 

 

SQL Work Area (MB):

6.0

1.4

 

 

Logons:

0.2

0.1

 

 

Executes:

32.4

7.7

 

 

Rollbacks:

0.0

0.0

 

 

Transactions:

4.2

 

 

 


主機CPU

優化前,CPU空閒率只有8%

Load Average Begin

Load Average End

%User

%System

%WIO

%Idle

 

 

88.3

3.8

 

8.0

優化後,從主機層面來看,優化後CPU空閒佔到99%

CPUs

Cores

Sockets

Load Average Begin

Load Average End

%User

%System

%WIO

%Idle

16

16

1

0.31

0.15

0.7

0.3

0.1

99.0


例項CPU

優化前

%Total CPU

%Busy CPU

%DB time waiting for CPU (Resource Manager)

83.6

90.8

0.0

優化後

%Total CPU

%Busy CPU

%DB time waiting for CPU (Resource Manager)

0.8

77.5

0.0

從資料庫佔用CPU資源來看,優化後資料庫只消耗了主機cpu資源的0.8%


記憶體統計資訊

優化前

 

Begin

End

Host Mem (MB):

 16,383.6

16,383.6

SGA use (MB):

2,144.0

2,144.0

PGA use (MB):

1,018.7

1,018.7

% Host Mem used for SGA+PGA:

19.30

19.30

優化後

 

Begin

End

Host Mem (MB):

64,411.3

64,411.3

SGA use (MB):

20,480.0

20,480.0

PGA use (MB):

247.6

267.2

% Host Mem used for SGA+PGA:

3.56

3.59


SQL邏輯讀

優化前, %total列表明這個sql執行時間佔據db time的比例,第一個這個比值達到46.05%,顯然這個SQL導致的邏輯讀,消耗了大量的IO資源

Buffer Gets

Executions

Gets per Exec

%Total

Elapsed Time (s)

%CPU

%IO

SQL Id

SQL Module

SQL Text

1,171,388,996

90,764

12,905.88

46.05

30,514.20

44.7

0

6t0q3nw8b2b68

JDBC Thin Client

select * from ( select row_.*,...

554,429,813

42,299

13,107.40

32.22

9,923.23

40.9

0

btn84j9rhuf4h

JDBC Thin Client

select * from ( select row_.*,...

503,809,511

127,506

3,951.26

11.10

7,669.52

37.3

0

cp9wdanzmzj4q

JDBC Thin Client

select * from (select JOBID, S...

30,497,069

2,331

13,083.26

1.28

409.63

42.2

0

fqjyuzjgm89qv

JDBC Thin Client

select * from ( select trunc(P...

優化後, %total列表明這個sql執行時間佔據db time的比例,第一個這個比值只有5.39%

Buffer Gets

Executions

Gets per Exec

%Total

Elapsed Time (s)

%CPU

%IO

SQL Id

SQL Module

SQL Text

270,368,217

20,198

13,385.89

5.39 

1,023.63

34.7

0

bqxs5y957g75m

JDBC Thin Client

select count(*) from PM_GOODS_...

211,213,752

1,544

136,796.47

4.21

890.64

28.2

0

6x7279fvzt5pk

JDBC Thin Client

select * from ( select row_.*,...

90,328,606

5,188

17,411.07

1.30

457.81

37.3

0

d577budk4k7aq

JDBC Thin Client

select letter.bill_no bill_no,...

81,834,742

5,698

14,362.01

1.13

1.63

39.2

0

740wmdm31jyzp

JDBC Thin Client

select pickup_total.name tihuo...


段邏輯讀

優化前

Owner

Tablespace Name

Object Name

Subobject Name

Obj. Type

Logical Reads

%Total

PMSOFT

PMTABLESPACE

PM_EXTRACT_GOODS

 

TABLE 

2,145,895,024

89.21

PMSOFT

PMTABLESPACE_IDX

PM_GOODS_LETTER_LL_PK

 

INDEX

35,438,144

1.48

PMSOFT

PMTABLESPACE

PM_GOODS_HANDLE_INFO

 

TABLE 

18,438,384

0.77

PMSOFT

PMTABLESPACE_IDX

PM_TRACE_GOODS_GOODID

 

INDEX

17,049,488

0.71

PMSOFT

USER

PM_LINE_INFO

 

TABLE

5,766,448

0.24

優化後

Owner

Tablespace Name

Object Name

Subobject Name

Obj. Type

Logical Reads

%Total

PMSOFT

PMTABLESPACE

PM_MID_DAOHUO

 

TABLE 

47,626,288

9.21

PMSOFT

PMTABLESPACE

PM_GOODS_LETTER

 

TABLE PARTITION

40,368,688

1.50

PMSOFT

PMTABLESPACE

PM_TRACE_GOODS

 

TABLE PARTITION

10,344,832

0.97

PMSOFT

PMTABLESPACE_IDX

VOICE_SEND

 

TABLE

10,603,568

0.56

PMSOFT

PMTABLESPACE

PM_GOODS_LETTER

 

TABLE PARTITION

5,302,848

0.34


案例總結

1、瞭解日誌檔案同步事件優化方案

2、合理配置資料庫引數

3、根據sql執行計劃判斷執行計劃是否正確

2、正確使用索引。


案例警示

即使一個小的問題,也可能造成嚴重的事故。

將問題消滅在源頭。

發生事故後,冷靜分析,尋找最佳方案。

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

相關文章