某物流系统数据库故障诊断

标签： 物流 系统 数据库 | 发表时间：2015-05-15 22:48 | 作者：sdfiyon
出处：http://www.iteye.com

故障现象：

某物流公司新上一套软件系统，数据库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、正确使用索引。


案例警示

即使一个小的问题，也可能造成严重的事故。

将问题消灭在源头。

发生事故后，冷静分析，寻找最佳方案。



已有 0 人发表留言，猛击->> 这里<<-参与讨论


ITeye推荐



相关 [物流 系统 数据库] 推荐：

某物流系统数据库故障诊断

- - SQL - 编程语言 - ITeye博客
某物流公司新上一套软件系统，数据库CPU占用率基本维持在80%以上，业务高峰期数据库宕机. 重做日志缓冲区的已使用的空间达到三分之一时. 当dbwn进程向磁盘写入已修改的缓冲区的时候. 用户提交事务处理时的一条提交记录(经常commit会及时刷新重做日志缓冲区空间). 重做日志缓冲区的已使用的空间达到三分之一时.

8种Nosql数据库系统对比

- xcv58 - 伯乐在线 -博客
　　导读：Kristóf Kovács 是一位软件架构师和咨询顾问，他最近发布了一片对比各种类型NoSQL数据库的文章. 文章由敏捷翻译 - 唐尤华编译. 　　虽然SQL数据库是非常有用的工具，但经历了15年的一支独秀之后垄断即将被打破. 这只是时间问题：被迫使用关系数据库，但最终发现不能适应需求的情况不胜枚举.

OceanBase 数据库的系统架构

- -
OceanBase 数据库采用 Shared-Nothing 架构，各个节点之间完全对等，每个节点都有自己的 SQL 引擎、存储引擎，运行在普通 PC 服务器组成的集群之上，具备可扩展、高可用、高性能、低成本、云原生等核心特性. OceanBase 数据库的整体架构如下图所示. OceanBase 数据库支持数据跨地域（Region）部署，每个地域可能位于不同的城市，距离通常比较远，所以 OceanBase 数据库可以支持多城市部署，也支持多城市级别的容灾.

在数据库层面分析系统性能(原创)

- - ITeye博客
按照OracleDocument中的描述，v$sysstat存储自数据库实例运行那刻起就开始累计全实例(instance-wide)的资源使用情况. 1>.事件发生次数的统计(如：user commits). 2>.数据产生，存取或者操作的total列(如：redo size). 3>.如果TIMED_STATISTICS值为true,则统计花费在执行操作上的总时间(如：CPU used by this session).

Oracle、Db2、SqlServer、MySQL 数据库插入当前系统时间

- - CSDN博客推荐文章
例如有表table,table 中有两个字段：name 、makedate. 插入系统时间应为sysdate:. insert into table (name,makedate) values('测试',sysdate);. 插入系统时间应为current timestamp并且makedate数据类型为timestamp.

ActiveMQ系统之——消息持久化到MySQL数据库中（二）

- - CSDN博客推荐文章
关于这一节的程序，需要使用到《 ActiveMQ系列之——安装、运行及事例代码（一）》中的示例代码. 本文主要介绍关于消息持久化的配置. ActiveMQ默认情况下是基于文件的存储，使用的是kahaDB，当然还有其它的持久化方式，例如LevelDB，这个是在5.8的版本中引入的，本文主要介绍数据库持久化，使用的数据库是MySQL，其它数据库类似.

数据库系统load飙高问题解决思路

- - BlogJava-qileilove
数据库服务器器load 飙高的报警,比如:. 　　如何处理load 异常飙高的报警呢. 本文尝试从原理，原因，解决方法来阐述这类问题的解决思路. 　　CPU作为服务器的关键资源经常成为性能瓶颈的根源,CPU使用率高并不总是意味着CPU工作繁忙，它有可能是正在等待其他子系统. 在进行性能分析时，将所有子系统当做一个整体来看是非常重要的，因为在子系统中可能会出现瀑布效应.

美团 MySQL 数据库巡检系统的设计与应用

- - IT瘾-dev
我们生活中随处可见各种巡检系统，比如电力巡检、消防检查等，正是这些巡检工作，我们才能在稳定的环境下进行工作、生活. 巡检对于数据库或者其他IT系统来说也同样至关重要，特别是在降低风险、提高服务稳定性方面起到了非常关键作用. 为了保障数据库的稳定运行，以下核心功能组件必不可少：. 图1 数据库运维保障核心功能组件 其中，数据库巡检作为运维保障体系最重要的环节之一，能够帮助我们发现数据库存在的隐患，提前治理，做到防患于未然.

Binlog, Redolog 在分布式数据库系统中的应用

- - idea's blog
在一个系统中, 有 client 和 server 两个角色, client 向 server 发起请求(request), 这里的请求指写数据请求, 例如某条类似 "update table set a=1" 这样的 SQL 语句. 我们把 server 进行拆分, 得到下面这个更细化一些的系统结构:.

基于CWM的ETL元数据库系统模型的设计

- -
1 引 言 在工业领域,数据仓库连同前端的数据挖掘工具向企业高层提供决策分析的平台体系机制被称为商业智能（Business Intelligence,BI）. BI项目的实施牵涉到企业各个事务处理系统之间海量数据的定向流动,这个数据流动的过程被称为数据抽取、转换与装载（Extraction、Transformation and Loading,ETL）,是BI系统的心脏与灵魂.