某物流系统数据库故障诊断 – Fiyo – ITeye博客
故障现象：
某物流公司新上一套软件系统，数据库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、正确使用索引。
**
案例警示**
即使一个小的问题，也可能造成严重的事故。
将问题消灭在源头。
发生事故后，冷静分析，寻找最佳方案。