从业务角度分析奇怪的数据库高负载问题 (r4笔记第35天)
发布日期:2021-06-30 13:30:11 浏览次数:2 分类:技术文章

本文共 5992 字,大约阅读时间需要 19 分钟。

今天到公司以后,照例查看了数据库的负载情况,发现有一些异常。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 4gz51fphuarsw5199,3205 PRDAPPC pblwrk01 ccbpr1 bl1b@ccbdbpr1 (TNS V1- V3) 5199 cjfjyu20nhaws 9198,11215 PRDAPPC pcmwrk01 ccbpr1 JDBC Thin Client 9198 9s6vg5rnupjv918629,16045 PRDAPPC truwld5 ccbpr13 JDBC Thin Client 18629 6fu3z8pqd2y9g13255,52127 PRDAPPC pblwrk01 ccbpr1 sqlplus@ccbdbpr1 (TNS V1- V3) 13255 55u2k96k7bx913053,36995 PRDAPPC pcmwrk01 ccbpr1 JDBC Thin Client 3053 cq7p84hrug0wx18716,785 PRDAPPC truwld4 ccbpr13 JDBC Thin Client 18716 4gz51fphuarsw1753,1793 PRDAPPC truwl25 ccbpr2 JDBC Thin Client 1753 4gz51fphuarsw7478,19407 CCBSFMDEV Phongs4 TIT-C25 plsqldev.exe 74784792,5385 PRDAPPC truwld2 ccbpr13 JDBC Thin Client 4792 4gz51fphuarsw带着这种半信半疑,还是给客户发送了邮件,让他们确认一下,是否开启了新加的weblogic节点的信控服务,他们在查找之后最后反馈,确实是启用了这些服务,马上做了禁用操作。系统负载马上就降下来了。最后客户对相关的节点都做了检验,从我的监控来看,再也没有捕捉到新节点的并行进程。问题的处理就告一段落了。从这个问题的分析来看,有几个关键的注意点,首先从负载上来看可能存在着问题,但是单纯从负载来看也不能说明问题,需要自己对系统的业务情况进行一个基本的了解,这样在分析问题的时候才能更加的准备到位,可以自己沉淀一些监控的数据,在问题发生之后及时做比对,就很能够说明一些看似复杂的问题。这个问题的分析结果也是在了解了近期的系统变更上,自己了解了信控服务的特点,所以在分析问题的时候按照这个基准来验证新加入的节点可能有问题。然后逐步分析验证了自己的推论。这个时候如果单纯从技术角度来看,可能这些并行进程的执行还真不是问题,很可能看做是业务需要,导致分析到最后可能在sql调优上反复下很多的功夫,最后发现调优的工作已经很难有改进空间了,导致问题方向性的错误。最后一个就是敢于质疑,如果你的推论正确了,就可以避免一次不必要的系统问题,如果你的推论错了,可能还需要从其他的角度来分析这些问题,对自己也没有什么害处,切忌不要抱着抓到客户小辫子的态度,这样客户也会显得不够配合。

转载地址:https://jeanron100.blog.csdn.net/article/details/102506995 如侵犯您的版权,请留言回复原文章的地址,我们会给您删除此文章,给您带来不便请您谅解!

上一篇:使用ash分析ORA-01652问题(r4笔记第36天)
下一篇:通过shell绑定系统进程调优 (r4笔记第34天)

发表评论

最新留言

网站不错 人气很旺了 加油
[***.192.178.218]2024年04月23日 01时21分09秒