一条执行4秒的sql语句导致的系统问题

一般来说一条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

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

W/A MB processed:

34.3

0.4

Logons:

1.9

Executes:

3,522.4

43.1

Rollbacks:

0.5

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

首先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

<a>cws3pma51s3tf</a>

JDBC Thin Client

update EC1_USER set SYS_UPDAT...

14,459.33

2.81

30.97

70.80

<a>7wx3cgjqsmnn4</a>

ORACLE.EXE

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

11,493.79

375,757

2.23

0.88

99.41

<a>bhm5y9tb096qd</a>

selectNameAd...

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

Top SQL with Top Events

SQL ID

Planhash

Sampled # of Executions

% Activity

% Event

Top Row Source

% RwSrc

3040658791

5229

55.84

55.82

UPDATE

1654978926

324

2.32

1.62

INDEX - RANGE SCAN

0.48

418872265

4

2.30

1.58

TABLE ACCESS - FULL

1.10

<a>c0m89v4d91uhh</a>

799822736

160

1.35

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

UPDATE STATEMENT

1 (100)

1

   UPDATE

EC1_USER

     INDEX UNIQUE SCAN

EC1_USER_PK

102

1 (0)

00:00:01 

这个时候怎么解释执行计划效率很高，但是执行时间却很长的问题。

第一个猜想就是系统的负载加大了，可能查取数据的时候就慢了。但是反过来说，也不会慢这么高的比例啊。

所以这种猜想不成立的。

第二个猜想就是有大量的并发dml,同时做update,导致其他的一些Update就在等待。当然这种设计是有问题的。

但是时间已经过去了很久，v$session里面早就没有对应的记录了。怎么验证自己的猜想呢。

还是使用ash。里面有一个章节是blocking sessions的细节。

Blocking Sid (Inst)

Event Caused

User

Program

# Samples Active

XIDs

2647, 1( 1)

16.74

SYS

oracle@xxxx(LGWR)

97/360 [ 27%]

2909,15473( 1)

3.77

ECC

45/360 [ 13%]

3624,52345( 1)

3.01

44/360 [ 12%]

6453,29237( 1)

2.83

18/360 [ 5%]

793,65345( 1)

2.79

65/360 [ 18%]

通过这个就能看到有4个并发的session在同时做dml操作了。这样问题就能够基本定位了。

有了这些信息，就可以和开发部门协调。看看下一步该怎么改进了。