一条简单的sql语句导致的系统问题(r4笔记第51天)

新年,给大家拜年了。祝大家工作顺利,万事如意。 今天照例简单检查了系统的情况,发现在客户的服务器在下午的3-5点这个时间段,数据库负载略有上升,但是幅度不大,因为生产的awr抓取频率是10分钟,所以还是能够通过awr分析出一些问题。 负载情况如下: 抓取了一个最新时间段的awr报告。 查看数据库负载,比平时的负载要高一些。

Host Name

Platform

CPUs

Cores

Sockets

Memory (GB)

xxxxx

Linux x86 64-bit

80

40

4

346.22

Snap Id

Snap Time

Sessions

Cursors/Session

Begin Snap:

33108

19-Feb-15 15:40:21

5147

5.4

End Snap:

33109

19-Feb-15 15:50:22

5256

5.5

Elapsed:

10.01 (mins)

DB Time:

533.14 (mins)

从这个概览来看还是看不出特别之处,只能对整体的情况有一个把握。这是一个10分钟的报告。 Load profile是我查看awr报告的重点部分。能够发现user calls和executions的值很高。

Load Profile

Convert to CSV

Per Second

Per Transaction

Per Exec

Per Call

DB Time(s):

53.3

0.9

0.00

0.00

DB CPU(s):

10.3

0.2

0.00

0.00

Redo size:

2.2 MB

37.4 KB

Logical reads:

10.3 GB

179.3 MB

Block changes:

10,738.9

182.2

Physical reads:

1.2 GB

21.5 MB

Physical writes:

7.8 MB

136.0 KB

User calls:

20,256.8

343.7

Parses:

2,447.3

41.5

Hard parses:

4.3

0.1

W/A MB processed:

72.5

1.2

Logons:

4.6

0.1

Executes:

11,414.1

193.7

Rollbacks:

0.6

0.0

Transactions:

58.9

这个时候基本能够从load profile里面找到问题的方向了,user calls和executions的部分需要注意,首先问题的方向很可能是从sql语句级别导致的,语句执行的如此频繁,势必会对buffer gets有较大的影响,这个报告中parses的值很低,至少说明问题不是由于绑定变量导致的。我们可以查看等待事件基本确定时间都去哪了,哪些等待事件是需要重点关注的。然后在sql语句部分来分析了,基本可以从order by Elapsed time, order by Gets, order by Executions这三个部分来佐证了。 等待事件如下:

Top 5 Timed Foreground Events

Event

Waits

Time(s)

Avg wait (ms)

% DB time

Wait Class

db file sequential read

13,019,569

15,375

1

48.06

User I/O

enq: TX - row lock contention

403

7,779

19303

24.32

Application

DB CPU

6,185

19.34

direct path read

425,941

1,882

4

5.88

User I/O

read by other session

1,126,812

774

1

2.42

User I/O

从这个等待事件可以看出,大部分的等待事件都集中在IO部分,当然导致的原因也是多方面的。第2个等待事件至少可以说明表中存在着锁,这个也可能是导致数据库负载增加的一个原因,在通过监控记录查看,或者抓取一个ash报告就能够基本定位出那个时间段的锁细节。已经做了确认,发现某一个process存在很多的并发dml操作,抓取了相应的信息交给了开发处理。 但是这个问题和load profile中的user calls,executions的值过高应该没有太大的关系。我们来直接进入sql信息部分。

SQL ordered by Elapsed Time

Elapsed Time (s)

Executions

Elapsed Time per Exec (s)

%Total

%CPU

%IO

SQL Id

SQL Module

SQL Text

01:39:59

1,344

4.46

18.75

0.33

0.00

dch8sxwt6ujvc

JDBC Thin Client

/* CL_ProcessController_update...

01:25:38

95

54.08

16.06

6.94

96.79

6csnjz5kqcffm

bl1extract@ccbdbpr1 (TNS V1-V3)

SELECT /*+ leading (list payp...

2,612.67

206

12.68

8.17

8.55

94.69

ffnjuh9qz1wy8

bl1extract@ccbdbpr1 (TNS V1-V3)

SELECT /*+ leading (cust rate ...

1,800.85

519

3.47

5.63

0.01

0.00

ffv3am85ccm25

JDBC Thin Client

/* AC_AcCloseUpdateAcControl_u...

1,554.22

13

119.56

4.86

17.15

86.22

fg5mc598u799u

JDBC Thin Client

select /*+ leading (bpm_ai bpm...

1,476.63

13

113.59

4.62

30.53

66.68

4gz51fphuarsw

JDBC Thin Client

/* CL_ProcInstScanner_selectAv...

952.12

361,344

0.00

2.98

12.69

92.74

62h1u7vsgjx9p

bl1extract@ccbdbpr1 (TNS V1-V3)

/* */ SELECT CUSTOMER_ID, SUBS...

924.90

13

71.15

2.89

30.09

66.53

6fu3z8pqd2y9g

JDBC Thin Client

/* CL_WaitScanner_selectWorkab...

600.66

0

1.88

8.85

94.53

1taqbbq0mw35u

JDBC Thin Client

SELECT OK.BAN, OK.MSISDN, OK.P...

565.49

0

1.77

4.19

97.80

cqrms45fqwvr3

JDBC Thin Client

/* Formatted on 2012/04/26 16:...

514.37

2,552,072

0.00

1.61

99.27

0.00

0mynq29fmat7d

getdate_int@ccbdbpr1 (TNS V1-V3)

select TO_CHAR(LOGICAL_DATE, '...

SQL ordered by Gets

  • Buffer GetsExecutionsGets per Exec%TotalElapsed Time (s)%CPU%IOSQL IdSQL ModuleSQL Text1.2 TB2,552,072486.9 KB19.12514.3799.270.000mynq29fmat7dgetdate_int@ccbdbpr1 (TNS V1-V3)select TO_CHAR(LOGICAL_DATE, '...705.8 GB2528.2 GB11.39105.9572.7127.951hg2wcuapy3y3JDBC Thin Clientselect bl1_run_request.run_mod...234.0 GB1318.0 GB3.781,476.6330.5366.684gz51fphuarswJDBC Thin Client/* CL_ProcInstScanner_selectAv...228.4 GB1317.6 GB3.69924.9030.0966.536fu3z8pqd2y9gJDBC Thin Client/* CL_WaitScanner_selectWorkab...190.4 GB335582.0 MB3.07192.3899.900.00aty7a3bvqfxxxJDBC Thin ClientSELECT COUNT(1) FROM (/* null_...

SQL ordered by Executions

  • ExecutionsRows ProcessedRows per ExecElapsed Time (s)%CPU%IOSQL IdSQL ModuleSQL Text2,552,0722,551,0771.00514.3799.270.000mynq29fmat7dgetdate_int@ccbdbpr1 (TNS V1-V3)select TO_CHAR(LOGICAL_DATE, '...445,868445,8651.0014.0590.200.20fa311gg43yjyfJDBC Thin ClientSelect CSM_TRX_1SQ.NEXTVAL fro...380,095380,0411.00101.0821.7183.42aprfnw5vk6szsjava_q4p@ccbappr7 (TNS V1-V3)SELECT ch_objects.obj_id, ch_o...

这个时候通过这三个部分,能够基本定位出问题发生在sql_id 0mynq29fmat7d这个语句上,这个语句就是 一个简单的select查询,查询的表也很小。但是问题就是在10分钟的时间范围内执行了2百多万次,这确实很不正常。从sql order by elapased部分可以看出这个语句占用的 db time比例不高,从sql语句的执行上还是没有问题的,但是通过sql order by gets和execution这两个部分,可以很明显的看到,这条语句是top 1的语句,使用的buffer gets高达1T,这个表中的数据量就几千条数据,大小都是MB级别的,但是在10分钟内却能使用1T的buffer gets,确实让我感觉很意外。 分析了这些问题之后,我的判断是认为程序逻辑中的问题,稍后发送了邮件和开发做确认。 通过这个问题可以看到sql语句导致的问题不一定是差的执行计划导致的,简单的sql语句照样能够导致一些意外的情况。但是执行的频率为什么这么频繁,还是属于应用部分,只能让他们提供更多的信息了。而且分析问题的时候,发现了一些问题,可能在检查的过程中又被其它的问题干扰了,很可能会让自己偏离问题检查的方向,很容易造成一个情况,发现忙活了半天,查问题的针对性不够。

原文发布于微信公众号 - 杨建荣的学习笔记(jianrong-notes)

原文发表时间:2015-02-19

本文参与腾讯云自媒体分享计划,欢迎正在阅读的你也加入,一起分享。

发表于

我来说两句

0 条评论
登录 后参与评论

相关文章

来自专栏杨建荣的学习笔记

记一次数据同步需求的改进(二) (r7笔记第5天)

在之前写过记一次数据同步需求的改进(一) (r7笔记第2天)之后,就开始着手对这个需求进行实践。 所谓实践出真知,在实际做的时候才发现可能计划的再好,做的时候还...

40780
来自专栏杨建荣的学习笔记

动态创建MySQL Group Replication的节点(r11笔记第84天)

前几天分享了下搭建MySQL Group Replication的脚本, 分分钟搭建MySQL Group Replication测试环境(r11笔记第82天)...

32560
来自专栏微信公众号:Java团长

Spring MVC+Spring+Mybatis实现支付宝支付功能(图文详解)

本教程详细介绍了如何使用ssm框架实现支付宝支付功能。本文章分为两大部分,分别是「支付宝测试环境代码测试」和「将支付宝支付整合到ssm框架」,详细的代码和图文解...

27210
来自专栏数据和云

预警揭秘:倒计时炸弹11.2.0.4前版本DB Link必须在2019年4月升级真相

在 Oracle 官方支持站点 MOS 上,最近发布了两篇告警文章,引发了用户的广泛关注,这两篇文章分别是: Oracle Databases Need to ...

42380
来自专栏杨建荣的学习笔记

ADG备库批量查询失败的原因分析(r8笔记第33天)

目前线上有一套环境是10gR2的,采用了一主两备的架构。在其中一个备库上每天凌晨会开放一个窗口运行一些批量的查询,目前使用dg broker会在指定的时间把备库...

37480
来自专栏乐沙弥的世界

Oracle ADDM性能诊断利器及报告解读

性能优化是一个永恒的话题,性能优化也是最具有价值,最值得花费精力深入研究的一个课题,因为资源是有限的,时间是有限的。在Oracle数据库中,随着Oracle功能...

16820
来自专栏杨建荣的学习笔记

当12C PDB遇上JDBC (r10笔记第59天)

最近整合了几个测试环境,都放入了12c的容器数据库中。今天本来计划再整合几个测试库进来,结果因为碰到了JDBC的问题给耽搁了。 迁移数据库的步骤...

30090
来自专栏Web项目聚集地

Spring MVC+Spring+Mybatis实现支付宝支付功能(图文详解)

本教程详细介绍了如何使用ssm框架实现支付宝支付功能。本文章分为两大部分,分别是「支付宝测试环境代码测试」和「将支付宝支付整合到ssm框架」,详细的代码和图文解...

28710
来自专栏杨建荣的学习笔记

linux kernel引发的oracle问题及解决

最近测试环境的连接数老是不够用,session/process 都相应的从5000提到了8000,但还是不够,而且还是不断有新环境需要增加。最后根据评估,ses...

41560
来自专栏杨建荣的学习笔记

关于db link权限分配的苦旅(二)(r7笔记第45天)

在几天前说过关于db link分配权限的问题,当时也折磨了我好一会儿 关于db link权限分配的苦旅(一) (r7笔记第42天) ? 大体的情况还是在11...

34240

扫码关注云+社区

领取腾讯云代金券