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

标签: 物流 系统 数据库 | 发表时间: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年的一支独秀之后垄断即将被打破. 这只是时间问题:被迫使用关系数据库,但最终发现不能适应需求的情况不胜枚举.

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

- - 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企业级数据库灾备(备份)系统-DMB v2.1发布

- 彦强 - MySQL 实验室(BLOG) - MySQL性能、MySQL Cluster集群、MySQL HA高可用等研究 - MySQL实验室
为了这系统宅了很多个周末,又一个小长假过去了, DMB v2.1终于可以那得出手了,现在分享出来让朋友们使用,希望能得到更多更好的建议. DMB 对InnoDB存储引擎支持在线热备(ibbackup, xtrabackup等),还可以根据用户需求选择备份模式,是否加锁获取Master信息等. “DMB数据库监控及灾备系统(监控、备份) for MySQL” 简单介绍见 http://www.mysqlab.net/tool/dmb/.

淘宝开源的PB级分布式数据库系统OceanBase简介

- Linker Lin - 弯曲评论
[ 编者注: OceanBase是一个支持海量数据的高性能数据库系统,实现了数千亿条记录、数百TB数据上的跨行跨表事务,由淘宝网核心系统研发部、运维、DBA、广告、应用研发等部门共同完成. 其源代码已于8月31日遵照GPL2开源. 本文第一部分转载于淘宝网核心系统研发部博客, 原始链接位于http://rdc.taobao.com/blog/cs/?p=956.

Oracle数据库系统工程师培训视频教程下载

- - Oracle - 数据库 - ITeye博客
   分享一套穆远龙老师的Oracle数据库系统工程师培训的视频教程下载,一共57讲,教程涉及到内存结构、物理结构、备份和恢复、安全审计、性能调优等等技术点.    该课程系统详细的介绍了Oracle数据库的整个过程,让您从基础入门到精通,贯穿整个学习.      第一讲:Oracle数据库系统基础.

为什么不建议采用数据库写入的方式集成不同系统

- - 企业架构 - ITeye博客
今天参加一个项目方案沟通会,实施方是一个外部公司,需要我帮忙确定内部系统和本次开发系统的接口需求. 实施方提出的方案是直接写入内部系统的数据库,我给出的建议是通过交换一个XML文件实现数据同步. 直接写入数据库,很难记录访问日志,一旦出现问题,很难界定责任. 一个单据是否有效,单靠数据库提供的约束机制是很难准确描述的,在很多情况下,是由应用逻辑负责检查验证.