从业务角度分析奇怪的数据库高负载问题 (r4笔记第35天)
今天到公司以后,照例查看了数据库的负载情况,发现有一些异常。11点开始到12点的时候,数据库的负载格外的高。按照平时的经验,这个时间段内不会有太多的高峰业务在运行,为了简单验证,自己抓取了近几天的数据库负载情况。 自己抓取了2月1号,1月30号的负载情况,发现在这个时间段内数据库的负载其实不高。
snap_begin |
snap_end |
start_time |
level |
duration(mins) |
DB time(mins) |
|||
---|---|---|---|---|---|---|---|---|
30775 |
30776 |
3 |
Feb |
2015 |
10:50 |
1 |
10 |
875 |
30776 |
30777 |
3 |
Feb |
2015 |
11:00 |
1 |
10 |
1203 |
30777 |
30778 |
3 |
Feb |
2015 |
11:10 |
1 |
10 |
1176 |
30778 |
30779 |
3 |
Feb |
2015 |
11:20 |
1 |
10 |
1202 |
30779 |
30780 |
3 |
Feb |
2015 |
11:30 |
1 |
10 |
1152 |
30780 |
30781 |
3 |
Feb |
2015 |
11:40 |
1 |
10 |
1313 |
30781 |
30782 |
3 |
Feb |
2015 |
11:50 |
1 |
10 |
1401 |
30782 |
30783 |
3 |
Feb |
2015 |
12:00 |
1 |
10 |
1089 |
30783 |
30784 |
3 |
Feb |
2015 |
12:10 |
1 |
10 |
1124 |
30784 |
30785 |
3 |
Feb |
2015 |
12:20 |
1 |
10 |
1195 |
30785 |
30786 |
3 |
Feb |
2015 |
12:30 |
1 |
10 |
1118 |
30786 |
30787 |
3 |
Feb |
2015 |
12:40 |
1 |
10 |
1083 |
30787 |
30788 |
3 |
Feb |
2015 |
12:50 |
1 |
10 |
980 |
30788 |
30789 |
3 |
Feb |
2015 |
13:00 |
1 |
10 |
968 |
30789 |
30790 |
3 |
Feb |
2015 |
13:10 |
1 |
10 |
860 |
30790 |
30791 |
3 |
Feb |
2015 |
13:20 |
1 |
10 |
758 |
30791 |
30792 |
3 |
Feb |
2015 |
13:30 |
1 |
10 |
736 |
30792 |
30793 |
3 |
Feb |
2015 |
13:40 |
1 |
10 |
655 |
30793 |
30794 |
3 |
Feb |
2015 |
13:50 |
1 |
10 |
489 |
30794 |
30795 |
3 |
Feb |
2015 |
14:00 |
1 |
10 |
571 |
30795 |
30796 |
3 |
Feb |
2015 |
14:10 |
1 |
10 |
576 |
30796 |
30797 |
3 |
Feb |
2015 |
14:20 |
1 |
10 |
687 |
30797 |
30798 |
3 |
Feb |
2015 |
14:30 |
1 |
10 |
727 |
30798 |
30799 |
3 |
Feb |
2015 |
14:40 |
1 |
10 |
550 |
30799 |
30800 |
3 |
Feb |
2015 |
14:50 |
1 |
10 |
648 |
30487 |
30488 |
1 |
Feb |
2015 |
10:50 |
1 |
10 |
312 |
30488 |
30489 |
1 |
Feb |
2015 |
11:00 |
1 |
10 |
489 |
30489 |
30490 |
1 |
Feb |
2015 |
11:10 |
1 |
10 |
429 |
30490 |
30491 |
1 |
Feb |
2015 |
11:20 |
1 |
10 |
311 |
30491 |
30492 |
1 |
Feb |
2015 |
11:30 |
1 |
10 |
331 |
30492 |
30493 |
1 |
Feb |
2015 |
11:40 |
1 |
10 |
288 |
30493 |
30494 |
1 |
Feb |
2015 |
11:50 |
1 |
10 |
221 |
30494 |
30495 |
1 |
Feb |
2015 |
12:00 |
1 |
10 |
335 |
30495 |
30496 |
1 |
Feb |
2015 |
12:10 |
1 |
10 |
530 |
30496 |
30497 |
1 |
Feb |
2015 |
12:20 |
1 |
10 |
430 |
30497 |
30498 |
1 |
Feb |
2015 |
12:30 |
1 |
10 |
366 |
30498 |
30499 |
1 |
Feb |
2015 |
12:40 |
1 |
10 |
370 |
30499 |
30500 |
1 |
Feb |
2015 |
12:50 |
1 |
10 |
288 |
30500 |
30501 |
1 |
Feb |
2015 |
13:00 |
1 |
10 |
286 |
30501 |
30502 |
1 |
Feb |
2015 |
13:10 |
1 |
10 |
283 |
30502 |
30503 |
1 |
Feb |
2015 |
13:20 |
1 |
10 |
193 |
30503 |
30504 |
1 |
Feb |
2015 |
13:30 |
1 |
10 |
215 |
30504 |
30505 |
1 |
Feb |
2015 |
13:40 |
1 |
10 |
205 |
30505 |
30506 |
1 |
Feb |
2015 |
13:50 |
1 |
10 |
200 |
30506 |
30507 |
1 |
Feb |
2015 |
14:00 |
1 |
10 |
239 |
30507 |
30508 |
1 |
Feb |
2015 |
14:10 |
1 |
10 |
202 |
30508 |
30509 |
1 |
Feb |
2015 |
14:20 |
1 |
10 |
175 |
30509 |
30510 |
1 |
Feb |
2015 |
14:30 |
1 |
10 |
229 |
30510 |
30511 |
1 |
Feb |
2015 |
14:40 |
1 |
10 |
226 |
30511 |
30512 |
1 |
Feb |
2015 |
14:50 |
1 |
10 |
216 |
30199 |
30200 |
30 |
Jan |
2015 |
10:50 |
1 |
10 |
377 |
30200 |
30201 |
30 |
Jan |
2015 |
11:00 |
1 |
10 |
572 |
30201 |
30202 |
30 |
Jan |
2015 |
11:11 |
1 |
10 |
428 |
30202 |
30203 |
30 |
Jan |
2015 |
11:20 |
1 |
9 |
664 |
30203 |
30204 |
30 |
Jan |
2015 |
11:30 |
1 |
10 |
580 |
30204 |
30205 |
30 |
Jan |
2015 |
11:40 |
1 |
10 |
409 |
30205 |
30206 |
30 |
Jan |
2015 |
11:50 |
1 |
10 |
277 |
30206 |
30207 |
30 |
Jan |
2015 |
12:00 |
1 |
10 |
464 |
30207 |
30208 |
30 |
Jan |
2015 |
12:10 |
1 |
10 |
365 |
30208 |
30209 |
30 |
Jan |
2015 |
12:20 |
1 |
10 |
333 |
30209 |
30210 |
30 |
Jan |
2015 |
12:30 |
1 |
10 |
315 |
30210 |
30211 |
30 |
Jan |
2015 |
12:40 |
1 |
10 |
355 |
30211 |
30212 |
30 |
Jan |
2015 |
12:50 |
1 |
10 |
304 |
30212 |
30213 |
30 |
Jan |
2015 |
13:00 |
1 |
10 |
287 |
30213 |
30214 |
30 |
Jan |
2015 |
13:10 |
1 |
10 |
234 |
30214 |
30215 |
30 |
Jan |
2015 |
13:20 |
1 |
10 |
255 |
30215 |
30216 |
30 |
Jan |
2015 |
13:30 |
1 |
10 |
321 |
30216 |
30217 |
30 |
Jan |
2015 |
13:40 |
1 |
10 |
329 |
30217 |
30218 |
30 |
Jan |
2015 |
13:50 |
1 |
10 |
273 |
30218 |
30219 |
30 |
Jan |
2015 |
14:00 |
1 |
10 |
398 |
30219 |
30220 |
30 |
Jan |
2015 |
14:10 |
1 |
10 |
347 |
30220 |
30221 |
30 |
Jan |
2015 |
14:20 |
1 |
10 |
363 |
30221 |
30222 |
30 |
Jan |
2015 |
14:30 |
1 |
10 |
511 |
30222 |
30223 |
30 |
Jan |
2015 |
14:40 |
1 |
10 |
527 |
30223 |
30224 |
30 |
Jan |
2015 |
14:50 |
1 |
10 |
356 |
从客户那里了解的情况是,他们昨天晚上对系统打了补丁,但是没有修改其它的地方。 为了查找问题,我抓取了问题时间段内的awr报告。 得到的等待事件情况如下:
Top 5 Timed Foreground Events
Event |
Waits |
Time(s) |
Avg wait (ms) |
% DB time |
Wait Class |
---|---|---|---|---|---|
direct path read |
757,842 |
25,844 |
34 |
36.61 |
User I/O |
db file sequential read |
6,253,924 |
24,112 |
4 |
34.16 |
User I/O |
DB CPU |
8,433 |
11.95 |
|||
read by other session |
1,736,151 |
5,387 |
3 |
7.63 |
User I/O |
log file sync |
98,407 |
2,715 |
28 |
3.85 |
Commit |
可以看到等待时间都是和IO紧密相关的。从等待事件direct path read来看,我的一个直观感觉就是并行查询导致的。 使用并行扫描的SQL语句也会影响系统范围的direct path read等待事件。在并行执行过程中,direct path read等待事件与从属查询有关,而与父查询无关,运行父查询的会话基本上会在PX Deq:Execute Reply上等待,从属查询会产生direct path read等待事件。 从SQL Order by Elapsed time这个章节,可以看到几个消耗很大的语句都和一个信控相关的扫描服务相关。
Elapsed Time (s) |
Executions |
Elapsed Time per Exec (s) |
%Total |
%CPU |
%IO |
SQL Id |
SQL Module |
SQL Text |
---|---|---|---|---|---|---|---|---|
14,326.71 |
24 |
596.95 |
20.30 |
8.58 |
89.48 |
4gz51fphuarsw |
JDBC Thin Client |
/* ProcInstScanner_selectAv... |
10,674.05 |
23 |
464.09 |
15.12 |
6.01 |
92.01 |
6fu3z8pqd2y9g |
JDBC Thin Client |
/* WaitScanner_selectWorkab... |
5,641.97 |
24 |
235.08 |
7.99 |
6.90 |
93.09 |
fg5mc598u799u |
JDBC Thin Client |
select /*+ leading (bpm_ai bpm... |
1,628.99 |
5 |
325.80 |
2.31 |
2.85 |
98.39 |
b56c37kvdwn1m |
JDBC Thin Client |
select /*+ leading(s) index(s ... |
这几个服务的启动时间大概是在10点左右,但是今天却在11点多开始对数据库有相当的压力。当时也没多想,继续查看并行的部分来验证direct path read的想法。 结果在并行的部分发现了一些问题。 下面标黄的部分是weblogic节点的连接用户,按照规律来看都是truwlxxx的样式,但是今天看到是确实truwld5,truwld4这种类型的。这个问题没有做过多的确认,但是感觉已经是个问题了。 和最近的系统升级联系起来,最近在生产库中加入了一些weblogic节点来分担一部分的业务压力,但是据我所知,这些新加入的节点都是不需要开启信控服务的。
SESS_ID USERNAME OSUSER MACHINE PROGRAM QCSID SQL_ID
------------------------------------------------------------------------------------------------------------------------------------
3787,15127 PRDAPPC truwld5 ccbpr13 JDBC Thin Client 3787 4gz51fphuarsw
5199,3205 PRDAPPC pblwrk01 ccbpr1 bl1b@ccbdbpr1 (TNS V1- V3) 5199 cjfjyu20nhaws
9198,11215 PRDAPPC pcmwrk01 ccbpr1 JDBC Thin Client 9198 9s6vg5rnupjv9
18629,16045 PRDAPPC truwld5 ccbpr13 JDBC Thin Client 18629 6fu3z8pqd2y9g
13255,52127 PRDAPPC pblwrk01 ccbpr1 sqlplus@ccbdbpr1 (TNS V1- V3) 13255 55u2k96k7bx91
3053,36995 PRDAPPC pcmwrk01 ccbpr1 JDBC Thin Client 3053 cq7p84hrug0wx
18716,785 PRDAPPC truwld4 ccbpr13 JDBC Thin Client 18716 4gz51fphuarsw
1753,1793 PRDAPPC truwl25 ccbpr2 JDBC Thin Client 1753 4gz51fphuarsw
7478,19407 CCBSFMDEV Phongs4 TIT-C25 plsqldev.exe 7478
4792,5385 PRDAPPC truwld2 ccbpr13 JDBC Thin Client 4792 4gz51fphuarsw
带着这种半信半疑,还是给客户发送了邮件,让他们确认一下,是否开启了新加的weblogic节点的信控服务,他们在查找之后最后反馈,确实是启用了这些服务,马上做了禁用操作。 系统负载马上就降下来了。最后客户对相关的节点都做了检验,从我的监控来看,再也没有捕捉到新节点的并行进程。问题的处理就告一段落了。 从这个问题的分析来看,有几个关键的注意点,首先从负载上来看可能存在着问题,但是单纯从负载来看也不能说明问题,需要自己对系统的业务情况进行一个基本的了解,这样在分析问题的时候才能更加的准备到位,可以自己沉淀一些监控的数据,在问题发生之后及时做比对,就很能够说明一些看似复杂的问题。 这个问题的分析结果也是在了解了近期的系统变更上,自己了解了信控服务的特点,所以在分析问题的时候按照这个基准来验证新加入的节点可能有问题。然后逐步分析验证了自己的推论。这个时候如果单纯从技术角度来看,可能这些并行进程的执行还真不是问题,很可能看做是业务需要,导致分析到最后可能在sql调优上反复下很多的功夫,最后发现调优的工作已经很难有改进空间了,导致问题方向性的错误。 最后一个就是敢于质疑,如果你的推论正确了,就可以避免一次不必要的系统问题,如果你的推论错了,可能还需要从其他的角度来分析这些问题,对自己也没有什么害处,切忌不要抱着抓到客户小辫子的态度,这样客户也会显得不够配合。
- 【设计模式】—— 中介者模式Mediator
- 【设计模式】—— 迭代模式Iterator
- 【设计模式】—— 解释器模式Interpret
- 【设计模式】—— 命令模式Commond
- 【设计模式】—— 职责链模式ChainOfResponsibility
- 【设计模式】—— 代理模式Proxy
- 【设计模式】—— 享元模式Flyweight
- 【设计模式】—— 外观模式Facade
- 【设计模式】—— 装饰模式Decorator
- 【设计模式】—— 组合模式Composite
- 【设计模式】—— 桥接模式Bridge
- 【插件开发】—— 1 Eclipse插件开发导盲
- 【插件开发】—— 4 SWT编程须知
- 【插件开发】—— 5 SWT控件以及布局使用
- 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 数组属性和方法
- R语言实现输出文本的多样式
- 学习|Unity3d的导航实现循环线路移动
- 【redis】闲得无聊,来聊聊当下爆火的 redis集群,顺便搭一个玩玩呗
- 【redis入门】Centos下安装redis
- LeetCode精选好题(五)
- 【leetcode两题选手】MySQL类题目(一)
- 【LeetCode每日一题】(8.11)被围绕的区域
- 二叉树的前中后序遍历(迭代法)(带动画)
- 【LeetCode两题选手】算法类题目(8.8)
- 【LeetCode每日一题】(8.9)复原IP地址(回溯)
- 【回溯算法】N叉树相关技巧
- 【回溯算法】回溯,从入门到入土,七道试题精选、精讲、精练
- 数据结构练手小项目(AVL树、哈希表、循环链表、MySQL数据库)
- 【LeetCode】每日一题(8.2)二叉树展开为链表
- 【小技巧】argc和argv的用法