关于生产系统锁问题的排查(r3笔记第79天)
公众号：杨建荣的学习笔记 · 作者：r3笔记第79天 · 发布：2014-12-09 22:08:53 · 原文链接
今天生产系统中的一个daemon出现了严重的数据处理延迟，客户需要我们立即给出处理的方案。在综合评估之后，为了不保证在线业务延迟，开发部门给出了临时的解决意见。先停掉了一个应用，然后重启之后那个daemon就没有问题了。
等我连上系统，这个问题已经不存在了，但是还是要提供一些更加详细的信息来进一步诊断这个问题。
首先来明确问题，这个daemon出现的数据处理延迟，很可能是锁造成的，从开发部门提供的临时解决方向也是如此。从他们的排查来看，表PUB_LOG中可能存在着锁等待。
因为时间已经过去一会了，使用awr报告查看等待事件。看到了很明显的row lock contention.
| Event | Waits | Time(s) | Avg wait (ms) | % DB time | Wait Class |
| 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的信息。这个可以和我们已经掌握的信息来互相印证。
| Blocking Sid (Inst) | % Activity | Event Caused | % Event | User | Program | # Samples Active | XIDs |
| 7485,35335( 1) | 25.79 | enq: TX – row lock contention | 25.79 | PRODUSER | JDBC Thin Client | 2/60 [ 3%] | 1 |
在问题发生的时间段内的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%] | 1 |
| 117,218,815 | 2.61 | CPU + Wait for CPU | 2.34 | PRDAPPC | JDBC Thin Client | 53/60 [ 88%] | 0 |
| 2430, 8909 | 2.61 | db file sequential read | 2.39 | PRDAPPC | JDBC Thin Client | 54/60 [ 90%] | 0 |
这个时候我们已经得知了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)
7485,35335 PRODUSER ACCOUNT 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 | 0.01 |
| DB CPU(s): | 8.8 | 0.3 | 0.00 | 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 | 0.1 | ||
| Executes: | 3,248.3 | 125.8 | ||
| Rollbacks: | 0.7 | 0.0 | ||
| Transactions: | 25.8 |
我们来看看在问题发生的时间段，到底是哪些查询来运行，运行得这么频繁。
我们查看SQL ordered by Elapsed Time 这个章节，可以得到数据库负载的一个整体情况，看看是哪些sql语句的运行导致了整体的数据库负载.
结果抓取到的第1条语句就是一个update，是在ACCOUNT上的update,执行频率也挺高，10分钟之内执行了300次，基本2秒钟一次。
| Elapsed Time (s) | Executions | Elapsed Time per Exec (s) | %Total | %CPU | %IO | SQL Id | SQL Module | SQL Text |
| 5,916.37 | 300 | 19.72 | 26.12 | 0.00 | 0.00 | dynpzk1qbkgyr | JDBC Thin Client | UPDATE ACCOUNT……. |
通过load profile我们得知executes的频率过高，所以我们在awr中查看SQL ordered by Executions这个章节，可以得到运行频率极高的sql语句，基本上查询都是和subscriber,customer相关的。
执行频率都很高，差距都不大，当我看到第10几条记录的时候，找到了关于ACCOUNT的select语句，执行频率是很高的。
| Executions | Rows Processed | Rows per Exec | Elapsed Time (s) | %CPU | %IO | SQL Id | SQL Module | SQL Text |
| 43,436 | 43,415 | 1.00 | 16.25 | 30.07 | 70.72 | a4zhz34w7dzpr | JDBC Thin Client | select …. from ACCOUNT ….. |
通过以上的两个部分，我们可以这么理解，系统负载较高大部分原因都是基于IO，因为cpu使用率并不高，而数据库读的指标很高。相关sql语句的执行频率也很高。这样极为频繁的访问，造成了数据库的负载很高。
而对于锁的问题。我们可以看到在问题发生的时间段，session(7485,35335) 也在进行PUB_LOG的DML操作，同时也在进行ACCOUNT的DML操作。
而PUB_LOG这个表是归属于专门的daemon的，这个daemon要处理数据的时候就会总是阻塞。这样就难怪数据处理的延迟了。
这样问题的基本清晰了，剩下的部分就是和开发做确认了。
后续开发反馈在代码中发现了潜在的问题，会做进一步的跟踪。