缓慢的update语句性能分析(r6笔记第61天)

最近处理一个问题的时候,先是收到DB time升高的报警,然后查看DB time的情况发现,已经有近1000%的负载了。

带着好奇心想看看到底是什么样的一个语句导致如此的情况。 先抓取了一个awr报告,因为问题发生的时间段比较集中而且时间持续有几个小时,所以抓取了一个小时的快照。 得到的awr部分内容如下:

Cache Sizes

Begin

End

Buffer Cache:

39,472M

39,472M

Std Block Size:

8K

Shared Pool Size:

1,440M

1,440M

Log Buffer:

14,256K

从下面的部分可以看出数据库其实内部的活动并不多,redo生成量不高,tps也不高。 Load Profile

Per Second

Per Transaction

Redo size:

154,276.41

24,024.13

Logical reads:

4,864.90

757.57

Block changes:

779.75

121.42

Physical reads:

509.53

79.35

Physical writes:

359.90

56.04

User calls:

2,658.46

413.98

Parses:

837.89

130.48

Hard parses:

0.09

0.01

Sorts:

171.22

26.66

Logons:

0.47

0.07

Executes:

949.10

147.80

Transactions:

6.42

而查看等待时间,发现第一个等待事件是db file sequential read,平均等待时间有近17ms,

延迟一般需要在10ms以下,或者至少100 reads/sec,在基于SAN存储缓存数据的情况下,sequential read的指标有时候会保持在2ms左右,这个只能说明SAN已经把数据转化为缓存了,倒不能说明硬盘驱动确实很快。这个地方已经超过了10ms说明IO上还是存在较大的影响。我们先放过这个问题,继续往下看。

Event

Waits

Time(s)

Avg Wait(ms)

% Total Call Time

Wait Class

db file sequential read

917,810

15,310

17

96.1

User I/O

CPU time

596

3.7

log file sync

16,085

186

12

1.2

Commit

log file parallel write

15,466

140

9

.9

System I/O

ARCH wait on SENDREQ

374

10

27

.1

Network

而根据时间模型来看,绝大部分的DB time都在sql语句方面,所以关注sql语句就是一个很重要的部分。

Statistic Name

Time (s)

% of DB Time

sql execute elapsed time

15,533.43

97.47

DB CPU

596.11

3.74

connection management call elapsed time

82.89

0.52

parse time elapsed

20.22

0.13

而对于top1的sql语句让自己和吃惊,竟然是一个很简单的update.

Elapsed Time (s)

CPU Time (s)

Executions

Elap per Exec (s)

% Total DB Time

SQL Id

SQL Module

SQL Text

8,659

69

622

13.92

54.34

94p345yuqh3zd

update user_test t set t.login_status='' where t.CN_TEST=:1

第一感觉就是这个语句走了全表扫描,因为一个简单的Update竟然需要花费近13秒的时间,已经算很长的了。 当然猜测也需要验证,我们来看看awrsqrpt的结果。 发现这个报告还是蛮有意思。至于执行计划是走了唯一性索引扫描,所以执行计划的情况来看还是没有问题的。

Id

Operation

Name

Rows

Bytes

Cost (%CPU)

Time

0

UPDATE STATEMENT

1 (100)

1

UPDATE

USER_BILLING

2

INDEX UNIQUE SCAN

IDX_USER_TEST_CNMASTER

1

30

1 (0)

00:00:01

但是查看sql语句的执行统计信息,就有些奇怪了。

Stat Name

Statement Total

Per Execution

% Snap Total

Elapsed Time (ms)

8,659,180

13,921.51

54.34

CPU Time (ms)

69,346

111.49

11.63

Executions

622

Buffer Gets

3,146,068

5,057.99

35.91

Disk Reads

645,229

1,037.35

70.31

Parse Calls

622

1.00

0.04

Rows

621,827

999.72

User I/O Wait Time (ms)

8,608,075

sql语句的执行总共持续8659s左右,然后8608s的时间在user I/O的等待上,这样下来,622次的执行其实花费的时间并不多。 对于这个问题,自己也比较疑惑,开始怀疑是否是磁盘的IO上出现了问题。 但是使用MegaCli查看的时候,发现不存在任何的坏块。 # MegaCli -CfgDsply -a0|grep Error Media Error Count: 0 Other Error Count: 0 Media Error Count: 0 Other Error Count: 0 Media Error Count: 0 Other Error Count: 0 Media Error Count: 0 Other Error Count: 0 Media Error Count: 0 Other Error Count: 0 Media Error Count: 0 Other Error Count: 0 Media Error Count: 0 这个时候的一个猜测就是可能由绑定变量的数据类型不同导致的sql性能问题。但是排查一番,发现还是没有得到自己期望的结果。 查看输入的参数类型,都是期望中的varchar2,所以sql语句的过程中还是不会出现自己猜想的全表扫描的可能性。 select name,datatype_string,value_string,datatype from DBA_HIST_SQLBIND where sql_id='94p345yuqh3zd' and snap_id between 58711 and 58712 NAME DATATYPE_STRING VALUE_STRING DATATYPE ------------------------------ --------------- ------------------------------ ---------- :1 VARCHAR2(128) xxxxxx9@test.com 1 :1 VARCHAR2(128) 23234324324234 1 对于IO的瓶颈问题,自己还是从addm中得到了自己需要的东西。 对于磁盘吞吐量的说法,addm的报告中是这么描述的。

FINDING 6: 39% impact (6136 seconds) ------------------------------------ The throughput of the I/O subsystem was significantly lower than expected.

RECOMMENDATION 1: Host Configuration, 39% benefit (6136 seconds) ACTION: Consider increasing the throughput of the I/O subsystem. Oracle's recommended solution is to stripe all data file using the SAME methodology. You might also need to increase the number of disks for better performance. Alternatively, consider using Oracle's Automatic Storage Management solution. RATIONALE: During the analysis period, the average data files' I/O throughput was 3.9 M per second for reads and 2.7 M per second for writes. The average response time for single block reads was 16 milliseconds. 这个部分还是能够说明问题的,在IO上还是遇到了较大的瓶颈。这些延迟等待是造成DB time急剧升高的主因。 当然了我们也不能按照addm的说法,直接替换成asm,这个不是马上能够实现的方法。 但是在awr报告中还是发现了一丝蛛丝马迹,有一些辅助的调优方法。 第一个就是shared pool的大小,这个库大概有1000个session,但是因为使用了sga的自动管理,结果shared pool被30G的空间中只剩下了1.4G左右的缓存,很明显对于支持1000多个session的库来说,shard pool被压榨的太多了,可以指定一个稍大一些的值,保证shared pool不被全部榨干。 另外一个问题就是update执行如此缓慢,出了user I/O的原因之外,可以一个执行极为频繁的sql语句扫描的是同一张表,会造成一些热块的争用。同时会为了支持一致性读,势必在undo上会有较大的消耗,查看了这个库的undo还是一个相对较小的值,可以调大一些。

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

原文发表时间:2015-09-16

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

发表于

我来说两句

0 条评论
登录 后参与评论

相关文章

来自专栏数据库新发现

Oracle数据库恢复:归档日志损坏案例一则

链接:http://www.eygle.com/archives/2010/11/recover_archivelog_corruption.html

10920
来自专栏大大的微笑

深入理解JVM原理之编译openjdk7

Java虚拟机种类很多例如:HotSpot 丶 JRockit 丶 J9等 我们一般用的就是HotSpot,如果我们电脑上装了JDK,可以运行java -ver...

29490
来自专栏Albert陈凯

2018-11-17 面试必问问题TransactionalJava事务之一——Java事务的基本问题

关于加@Transactional注解的方法之间调用,事务是否生效的问题 https://blog.csdn.net/blacktal/article/det...

33720
来自专栏Android中高级开发

Android开发之漫漫长途 IX——彻底掌握Binder

该文章是一个系列文章,是本人在Android开发的漫漫长途上的一点感想和记录,我会尽量按照先易后难的顺序进行编写该系列。该系列引用了《Android开发艺术探索...

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

详解Intellij IDEA搭建SpringBoot

Spring Boot是由Pivotal团队提供的全新框架,其设计目的是用来简化新Spring应用的初始搭建以及开发过程。该框架使用了特定的方式来进行配置,从而...

75040
来自专栏黑泽君的专栏

常用的 default.properties 文件 + 常用的 struts-default.xml 文件 + 常用的 struts-plugin.xml 文件 + 常用的 struts.xml 文件

常用的 default.properties 文件,所在位置:\struts-2.3.15.3-all\struts-2.3.15.3\apps\struts2...

10040
来自专栏菩提树下的杨过

CQRS框架:AxonFramework 之 Hello World

Command Query Responsibility Segregation,CQRS 这个架构好象最近博客园里讨论得比较多,有几篇园友的文章很有深度,推荐...

48270
来自专栏乐沙弥的世界

ORA-27090 故障一例

    最近的alert日志中碰到了ORA-27090的错误信息,其错误提示为Unable to reserve kernel resources for as...

8120
来自专栏程序员与猫

Log system architecture

Keywords: Collector, Processor, Aggregator

18810
来自专栏耕耘实录

找回win7桌面IE图标我有绝招

现在很多同学都用了微软的新一代操作系统Windows7,都为Windows7的华丽界面及更人性化得操作所深深吸引,但是由于我们大多数同学都习惯了原来的Windo...

34150

扫码关注云+社区

领取腾讯云代金券