一条执行4秒的sql语句导致的系统问题(r3笔记第10天)

一般来说一条sql语句执行个4秒钟是可以接受的,没有什么问题,但是如果应该执行1秒,却执行了4秒,问题就挺大的了。 今天查看数据库负载,发现在中午12:00 到1点之间,数据库的负载急剧增加,负载达到了百倍。

Snap Id

Snap Time

Sessions

Cursors/Session

Begin Snap:

15106

29-Sep-14 12:00:07

1602

7.3

End Snap:

15107

29-Sep-14 13:00:13

2807

9.7

Elapsed:

60.10 (mins)

DB Time:

8,575.93 (mins)

为了一看究竟,抓取了一个awr报告。 发现系统的负载情况确实很严重,每秒的redo有1.6M,可见系统的负载不是主要在select上,可能有一些dml之类的操作极为频繁。

Per Second

Per Transaction

Per Exec

Per Call

DB Time(s):

142.7

1.7

0.04

0.03

DB CPU(s):

5.9

0.1

0.00

0.00

Redo size:

1,694,755.6

20,724.1

Logical reads:

671,861.2

8,215.8

Block changes:

6,638.8

81.2

Physical reads:

51,477.6

629.5

Physical writes:

1,075.6

13.2

User calls:

5,458.5

66.8

Parses:

1,247.7

15.3

Hard parses:

2.0

0.0

W/A MB processed:

34.3

0.4

Logons:

1.9

0.0

Executes:

3,522.4

43.1

Rollbacks:

0.5

0.0

Transactions:

81.8

看了下等待事件。都是关于lock的。这个时候就有些纳闷了。到底什么样的操作会导致严重的锁等待。

Top 5 Timed Foreground Events

Event

Waits

Time(s)

Avg wait (ms)

% DB time

Wait Class

enq: TX - row lock contention

1,132,995

235,312

208

45.73

Application

log file sync

305,880

120,935

395

23.50

Commit

db file sequential read

35,361,005

110,402

3

21.46

User I/O

DB CPU

21,248

4.13

read by other session

259,224

17,942

69

3.49

User I/O

首先DB time极高,这个时候就可以关注一些elapsed time比较高的sql语句。 可以看到第一个sql语句占用了大量的时间,而且是一个dml语句。后面的几个都是select相关的,占用的比例不是很大,就没有全列出来。

Elapsed Time (s)

Executions

Elapsed Time per Exec (s)

%Total

%CPU

%IO

SQL Id

SQL Module

SQL Text

235,032.84

57,646

4.08

45.68

0.06

0.00

cws3pma51s3tf

JDBC Thin Client

update EC1_USER set SYS_UPDAT...

14,459.33

0

2.81

30.97

70.80

7wx3cgjqsmnn4

ORACLE.EXE

SELECT "A3"."SUBSCRIBER_NO", "...

11,493.79

375,757

0.03

2.23

0.88

99.41

bhm5y9tb096qd

JDBC Thin Client

selectNameAd...

这个时候怎么把这条sql语句和对应的等待时间关联起来呢,如果为了清晰方便,可以使用ash。 Top SQL with Top Events

SQL ID

Planhash

Sampled # of Executions

% Activity

Event

% Event

Top Row Source

% RwSrc

SQL Text

cws3pma51s3tf

3040658791

5229

55.84

enq: TX - row lock contention

55.82

UPDATE

55.82

update EC1_USER set SYS_UPDAT...

bhm5y9tb096qd

1654978926

324

2.32

db file sequential read

1.62

INDEX - RANGE SCAN

0.48

selectNameAd...

7wx3cgjqsmnn4

418872265

4

2.30

db file sequential read

1.58

TABLE ACCESS - FULL

1.10

SELECT "A3"."SUBSCRIBER_NO", "...

c0m89v4d91uhh

799822736

160

1.35

read by other session

0.82

INDEX - UNIQUE SCAN

0.46

selectS...

问题基本确定了,是这条Update语句的执行极为频繁,但是执行时间达到了4秒。一个小时以内执行了5万多次。 但是为什么sql语句的执行时间这么长呢,是不是没有走索引,在简单排查了一下,索引是启用了的。 抓了一个awrsqrpt的报告。可以看到执行计划中的唯一性索引是启用了的,而且查取效率很多。0.01秒就查到了对应的记录,对于update的部分,不会那么慢把。 Execution Plan

Id

Operation

Name

Rows

Bytes

Cost (%CPU)

Time

0

UPDATE STATEMENT

1 (100)

1

UPDATE

EC1_USER

2

INDEX UNIQUE SCAN

EC1_USER_PK

1

102

1 (0)

00:00:01

这个时候怎么解释执行计划效率很高,但是执行时间却很长的问题。 第一个猜想就是系统的负载加大了,可能查取数据的时候就慢了。但是反过来说,也不会慢这么高的比例啊。 所以这种猜想不成立的。 第二个猜想就是有大量的并发dml,同时做update,导致其他的一些Update就在等待。当然这种设计是有问题的。 但是时间已经过去了很久,v$session里面早就没有对应的记录了。怎么验证自己的猜想呢。 还是使用ash。里面有一个章节是blocking sessions的细节。

Blocking Sid (Inst)

% Activity

Event Caused

% Event

User

Program

# Samples Active

XIDs

2647, 1( 1)

16.74

log file sync

16.74

SYS

oracle@xxxx(LGWR)

97/360 [ 27%]

0

2909,15473( 1)

3.77

enq: TX - row lock contention

3.77

ECC

JDBC Thin Client

45/360 [ 13%]

0

3624,52345( 1)

3.01

enq: TX - row lock contention

3.01

ECC

JDBC Thin Client

44/360 [ 12%]

1

6453,29237( 1)

2.83

enq: TX - row lock contention

2.83

ECC

JDBC Thin Client

18/360 [ 5%]

0

793,65345( 1)

2.79

enq: TX - row lock contention

2.79

ECC

JDBC Thin Client

65/360 [ 18%]

0

通过这个就能看到有4个并发的session在同时做dml操作了。这样问题就能够基本定位了。 有了这些信息,就可以和开发部门协调。看看下一步该怎么改进了。

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

原文发表时间:2014-09-29

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

发表于

我来说两句

0 条评论
登录 后参与评论

相关文章

来自专栏码匠的流水账

解决jd-gui在Sierra下闪退问题

在升级了mac操作系统到Sierra版本之后,之前的jd-gui就闪退了,本文就讲述一下如何解决这个问题。

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

抢红包案例分析以及代码实现

电商的秒杀、抢购,春运抢票,微信QQ抢红包,从技术的角度来说,这对于Web 系统是一个很大的考验. 高并发场景下,系统的优化和稳定是至关重要的.

4624
来自专栏乐沙弥的世界

自定义 RMAN 显示的日期时间格式

      缺省情况下,使用RMAN备份与恢复界面仅仅显示的是日期,而没有具体的时间。有时候需要查看具体的时间,如查看当天多个Incarnation的情形。对于...

1094
来自专栏数据和云

推陈出新:12C 推进 SCN 新方法实践

在数据库异常恢复中,经常需要修改数据库的 SCN 值,在 12C 之前,我们常用的方法有如下几个: oradebug poke 直接修改内存中的值; event...

40710
来自专栏linux驱动个人学习

基于input子系统的sensor驱动调试(二)

继上一篇:https://cloud.tencent.com/developer/article/1054078 一、驱动流程解析: 1、模块加载: 1 st...

6317
来自专栏数据和云

回答了这四个问题,少踩12c 多租户的好多坑

在ACOUG的年终大会上,我分享了一个主题,列举了使用Oracle 12c多租户的过程中可能遇到的各种坑,当你使用一个新产品或者新特性时,如果你不了解,就可能是...

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

三封报警邮件的分析(r6笔记第95天)

今天收到3封报警邮件,从邮件内容中的报警情况来看,还是比较反常的。需要引起关注,找到原因处理。 这个库是一个历史库,库中的数据非常庞大,几十亿数据的表还是有好几...

2854
来自专栏Kubernetes

原 荐 Flannel是如何工作的

Author: xidianwangtao@gmail.com 概述 最近我们的TaaS平台遇到很多的网络问题,事实证明“contiv + ovs + v...

1.5K11
来自专栏乐沙弥的世界

Oracle数据恢复顾问(Data Recovery Advisor)

Oracle数据恢复顾问用于当数据发生错误或故障时,进行自动收集数据故障信息,并生成恢复脚本,用于完成数据恢复。数据恢复顾问也可以主动检查故障。 在这种模式下,...

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

探究AWR 第二篇(r3笔记第93天)

在探究awr第一篇中介绍了awr的一些基本操作 http://blog.itpub.net/23718752/viewspace-1123134/ 在这一篇中,...

3207

扫码关注云+社区

领取腾讯云代金券