从业务角度分析奇怪的数据库高负载问题 (r4笔记第35天)
从业务角度分析奇怪的数据库高负载问题 (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调优上反复下很多的功夫，最后发现调优的工作已经很难有改进空间了，导致问题方向性的错误。 最后一个就是敢于质疑，如果你的推论正确了，就可以避免一次不必要的系统问题，如果你的推论错了，可能还需要从其他的角度来分析这些问题，对自己也没有什么害处，切忌不要抱着抓到客户小辫子的态度，这样客户也会显得不够配合。