关于生产系统锁问题的排查

今天生产系统中的一个daemon出现了严重的数据处理延迟，客户需要我们立即给出处理的方案。在综合评估之后，为了不保证在线业务延迟，开发部门给出了临时的解决意见。先停掉了一个应用，然后重启之后那个daemon就没有问题了。

等我连上系统，这个问题已经不存在了，但是还是要提供一些更加详细的信息来进一步诊断这个问题。

首先来明确问题，这个daemon出现的数据处理延迟，很可能是锁造成的，从开发部门提供的临时解决方向也是如此。从他们的排查来看，表PUB_LOG中可能存在着锁等待。

因为时间已经过去一会了，使用awr报告查看等待事件。看到了很明显的row lock contention.

<b>Event</b>

<b>Waits</b>

<b>Time(s)</b>

<b>Avg wait (ms)</b>

<b>% DB time</b>

<b>Wait Class</b>

db file sequential read

7,686,909

10,052

1

44.39

User I/O

enq:

TX - row lock contention

163

5,940

36442

26.23

Application

这个时候如果要进一步诊断这个等待事件，最好的工具就是ash了。

我们使用ash来查看对应的等待事件，然后可以从报告中得知blocking session的信息。这个可以和我们已经掌握的信息来互相印证。

<b>Blocking Sid</b>

(Inst)

<b>% Activity</b>

<b>Event Caused</b>

<b>% Event</b>

<b>User</b>

<b>Program</b>

<b># Samples Active</b>

<b>XIDs</b>

7485,35335( 1)

25.79

enq: TX - row lock contention

PRODUSER

JDBC Thin Client

2/60 [ 3%]

在问题发生的时间段内的active session情况如下。

Sid,

Serial#

% Activity

Event

% Event

User

Program

# Samples Active

XIDs

79,513,047

2.61

db

file sequential read

2.08

CCBSFMDEV

plsqldev.exe

47/60

[ 78%]

117,218,815

CPU

+ Wait for CPU

2.34

PRDAPPC

JDBC

Thin Client

53/60

[ 88%]

2430, 8909

2.39

54/60

[ 90%]

这个时候我们已经得知了session的信息。这个时候我们可以尝试使用脚本来查看一下锁的情况，如果对应的session还存在，我们可以基本定位客户端的信息了。

因为v$lock的信息也是实时变化的，在生产中我们也是采用了一定的时间频率来采集v$lock的数据。这些信息通过awr,ash也是不能完全定位的，额外的工具补充对于排查问题就显得尤为重要的。

以下是从监控存档中得到了关于session(7485,35335)的锁信息。

SID_SERIAL   ORACLE_USERN OBJECT_NAME               LOGON_TIM  SEC_WAIT   OSUSER    MACHINE      PROGRAM              STATE      STATUS     LOCK_ MODE_HELD

------------ ------------ ------------------------- --------- --------- ---------- ------------ -------------------- ---------- ---------- ----- ----------

7485,35335   PRODUSER       PUB_LOG                   09-DEC-14      18  mwrk01   fromClient1     JDBC Thin Client     WAITING    INACTIVE   DML   Row-X (SX)

7485,35335   PRODUSER       ACCOUNT                   09-DEC-14      18  mwrk01   fromClient2     JDBC Thin Client     WAITING    INACTIVE   DML   Row-X (SX)

7485,35335   PRODUSER       CUSTOMER                  09-DEC-14      20  lwrk01   fromClient2     sqlplus@ccbdbpr1 (TNS V1-V3) WAITING    ACTIVE     DML   Row-X (SX) 

7485,35335   PRODUSER       PUB_LOG                   09-DEC-14      18  mwrk01   fromClient2     JDBC Thin Client     WAITING    INACTIVE   DML   Row-X (SX)

7485,35335   PRODUSER       SUBSCRIBER                09-DEC-14      18  mwrk01   fromClient2     JDBC Thin Client     WAITING    INACTIVE   TO    Row-X (SX)

有了这些信息，我们就可以很确定的是在那个时间点上存在着表PUB_LOG相关的锁。

但是光是确定了锁，问题又回到原点了，这个问题是怎么导致的呢。我们现在只是证明了这个问题是锁引起的。

还需要更多的信息来确定倒底是由哪些原因导致的。

这个时候还是需要通过awr来进一步来确定。

我们来看看数据库的负载情况。相比于10分钟的时间间隔来说，负载算是比较高的了。

Snap Id

Snap Time

Sessions

Cursors/Session

Begin Snap:

22746

09-Dec-14 10:20:29

4510

6.0

End Snap:

22747

09-Dec-14 10:30:30

4523

5.9

Elapsed:

10.02 (mins)

DB Time:

377.45 (mins)

我们查看load profile的信息,可以很明显的看到executes和logical reads的值很高。尤其是executes部分，系统看起来应该很忙啊，但是“DB CPU(s)”的值不高。可见cpu的利用率也不高。很可能是由于IO问题导致的。

联系logical_reads和physical reads，相比于physical writes，数据库的负载基本都在于查询。从这个角度来说，和executes的值又是有关联的。

Per Second

Per Transaction

Per Exec

Per Call

DB Time(s):

37.7

1.5

0.01

DB CPU(s):

8.8

0.3

0.00

Redo size:

836,276.6

32,374.8

Logical reads:

1,686,403.9

65,285.8

Block changes:

3,940.3

152.5

Physical reads:

57,841.1

2,239.2

Physical writes:

443.4

17.2

User calls:

5,872.6

227.4

Parses:

2,098.2

81.2

Hard parses:

3.5

0.1

W/A MB processed:

40.0

1.6

Logons:

3.1

Executes:

3,248.3

125.8

Rollbacks:

0.7

Transactions:

25.8

我们来看看在问题发生的时间段，到底是哪些查询来运行，运行得这么频繁。

我们查看SQL ordered by Elapsed Time 这个章节，可以得到数据库负载的一个整体情况，看看是哪些sql语句的运行导致了整体的数据库负载.

结果抓取到的第1条语句就是一个update，是在ACCOUNT上的update,执行频率也挺高，10分钟之内执行了300次，基本2秒钟一次。

<b>Elapsed Time (s)</b>

<b>Executions </b>

<b>Elapsed Time per</b>

Exec (s)

<b>%Total</b>

<b>%CPU</b>

<b>%IO</b>

<b>SQL Id</b>

<b>SQL Module</b>

<b>SQL Text</b>

5,916.37

300

19.72

26.12

<a href="#dynpzk1qbkgyr">dynpzk1qbkgyr</a>

UPDATE ACCOUNT.......

通过load profile我们得知executes的频率过高，所以我们在awr中查看SQL ordered by Executions这个章节，可以得到运行频率极高的sql语句，基本上查询都是和subscriber,customer相关的。

执行频率都很高，差距都不大，当我看到第10几条记录的时候，找到了关于ACCOUNT的select语句，执行频率是很高的。

<b>Rows Processed</b>

<b>Rows per Exec</b>

43,436

43,415

16.25

30.07

70.72

<a href="#a4zhz34w7dzpr">a4zhz34w7dzpr</a>

select .... from ACCOUNT .....

通过以上的两个部分，我们可以这么理解，系统负载较高大部分原因都是基于IO，因为cpu使用率并不高，而数据库读的指标很高。相关sql语句的执行频率也很高。这样极为频繁的访问，造成了数据库的负载很高。

而对于锁的问题。我们可以看到在问题发生的时间段，session(7485,35335) 也在进行PUB_LOG的DML操作，同时也在进行ACCOUNT的DML操作。

而PUB_LOG这个表是归属于专门的daemon的，这个daemon要处理数据的时候就会总是阻塞。这样就难怪数据处理的延迟了。

这样问题的基本清晰了，剩下的部分就是和开发做确认了。

后续开发反馈在代码中发现了潜在的问题，会做进一步的跟踪。