某物流系統資料庫故障診斷案例分析
故障現象:
某物流公司新上一套軟體系統,資料庫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/,如需轉載,請註明出處,否則將追究法律責任。
相關文章
- Oracle___診斷案例__資料庫的exp故障Oracle資料庫
- 大語言模型與資料庫故障診斷模型資料庫
- 故障分析 | Kubernetes 故障診斷流程
- 公司某資料子系統定期cpu過高的診斷
- 資料庫異常智慧分析與診斷資料庫
- Oracle 11g資料庫緩慢診斷案例Oracle資料庫
- DB2資料庫故障與效能瓶頸診斷思路DB2資料庫
- 【記錄】Linux 系統故障診斷與排除Linux
- Oracle故障診斷Oracle
- mysql資料庫效能診斷MySql資料庫
- 【Oracle】資料庫hang 診斷Oracle資料庫
- Oracle配置資料庫診斷Oracle資料庫
- 資料庫診斷一例資料庫
- 資料庫大設計需求分析(門診掛號系統)資料庫
- 一次DG故障診斷過程分析
- MySQL故障診斷常用方法手冊(含指令碼、案例)MySql指令碼
- ORACLE診斷案例Oracle
- 光纖故障診斷和故障排查
- ASM磁碟故障診斷(二)ASM
- ASM磁碟故障診斷(一)ASM
- 故障診斷學習工具
- RAC故障診斷指令碼指令碼
- B站大資料系統診斷實踐-SQLSCAN篇大資料SQL
- ODX 診斷資料庫轉換工具 — DDC資料庫
- 診斷Oracle資料庫Hanging問題Oracle資料庫
- 資料庫伺服器系統I/O 100%案例分析資料庫伺服器
- 物流資料來源系統
- 9 Oracle Data Guard 故障診斷Oracle
- DB2故障診斷工具DB2
- Win10系統下網路故障診斷功能的使用方法Win10
- 風機故障診斷學習資源(更新中)
- 整車EOL診斷系統
- 整車EOL 診斷系統
- ECS控制檯診斷系統
- 案例 - EBS SQL效能診斷SQL
- Oracle資料庫故障恢復資料庫系統故障恢復效能優化指南大全Oracle資料庫優化
- Part II 診斷和優化資料庫效能優化資料庫
- MySQL資料庫診斷:InnoDB關機問題MySql資料庫