关于生产系统锁问题的排查(r3笔记第79天)
今天生产系统中的一个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要处理数据的时候就会总是阻塞。这样就难怪数据处理的延迟了。 这样问题的基本清晰了,剩下的部分就是和开发做确认了。 后续开发反馈在代码中发现了潜在的问题,会做进一步的跟踪。
- Java中使用Hibernate系列之加载并存储对象学习(第三节)
- Java中使用Hibernate系列之启动方法学习(第二节)
- Java中使用Hibernate系列之映射文件学习(第一节)
- Java中为图片添加水印效果的方法——实例代码
- Java中使用Hibernate系列之过滤器(filters)学习
- Node.js中的内存泄漏分析
- Java实现把整数转换为英语单词的方法,实用代码
- Chrome XSS审计之SVG标签绕过
- Java实现的一个简单计算器,有字符分析功能
- Java中实现判断括号是否有效的方法,实用代码
- Java中使用栈实现一个队列,实用代码
- NDK 的开发流程
- 蜜罐背后的影子系统探秘
- Oracle 免费的数据库--Database 快捷版 11g 安装使用与SOD框架对Oracle的CodeFirst支持
- JavaScript 教程
- JavaScript 编辑工具
- JavaScript 与HTML
- JavaScript 与Java
- JavaScript 数据结构
- JavaScript 基本数据类型
- JavaScript 特殊数据类型
- JavaScript 运算符
- JavaScript typeof 运算符
- JavaScript 表达式
- JavaScript 类型转换
- JavaScript 基本语法
- JavaScript 注释
- Javascript 基本处理流程
- Javascript 选择结构
- Javascript if 语句
- Javascript if 语句的嵌套
- Javascript switch 语句
- Javascript 循环结构
- Javascript 循环结构实例
- Javascript 跳转语句
- Javascript 控制语句总结
- Javascript 函数介绍
- Javascript 函数的定义
- Javascript 函数调用
- Javascript 几种特殊的函数
- JavaScript 内置函数简介
- Javascript eval() 函数
- Javascript isFinite() 函数
- Javascript isNaN() 函数
- parseInt() 与 parseFloat()
- escape() 与 unescape()
- Javascript 字符串介绍
- Javascript length属性
- javascript 字符串函数
- Javascript 日期对象简介
- Javascript 日期对象用途
- Date 对象属性和方法
- Javascript 数组是什么
- Javascript 创建数组
- Javascript 数组赋值与取值
- Javascript 数组属性和方法