oracle48108,​记一次oracle连接数暴涨hang分析经验

小伙伴们，大家好。

这次分享一个因为应用连接数暴涨进而导致数据库hang的故障分析处理经验。

1、事件背景

2020年01月13日，收到某运营商一核心数据库告警，提示数据库连接数超过预警阈值，短时间内连接数暴涨，同事也收到业务人员反馈。现将整个事件过程介绍如下:

01-1310:40 收到短信告警，某业务数据库b节点连接数超过预警阈值。01-1310:43 某业务库连接数突增到16000导致实例hang住。01-1310:45 为快速恢复故障决定重启b节点实例及CRS服务，发现crs长时间无法关闭。01-1310:47 决定直接重启b节点主机。01-1311:00 b节点主机重启完成，CRS服务启动正常，但b节点与a节点通信异常导致b节点实例无法启动。01-1311:10 与业务人员沟通业务可以停止，于是，重启a节点实例及CRS服务，业务a节点关闭完成后，业务b节点实例正常启动，状态正常。01-1311:15 启动a节点实例，均恢复正常。

2、分析过程

根据问题发生时段数据库预警文件、Trc、OSW、dbwait日志、ash视图数据，查询相关MOS资料。

问题时间点的主要是librarycache lock

通过

发现都是被9599阻塞了

查询发现9599也是被阻塞的进程

查询6674

阻塞者是LGWR的这个进程，它的状态是ONCPU。

回到AWR里看看LGWR的工作情况。

首先在AWR里看到top1的等待就是logfile sync ，而且它的平均等待时间非常夸张：每次commit，需要等516.49ms，也就是每次提交都要等半秒多。

检查下I/O是否有问题：

dbfile sequential read 5,300,861 3031 571.79us 8.7 User I/O

logfile parallel write 77,000 0 132 1.72ms 3.22 1.02

这几个指标显示，平均读和平均写的速度还是非常快的。排除掉IO性能引发的问题。

匹配MOS中相关资料，根据文档：

Troubleshooting:’Log file sync’ Waits ( Doc ID 1376916.1)的介绍，再来排查应用设计的问题。特别是ExcessiveApplication Commits 这部分。

AWR报告里的usercall 和commit/rollback的比例：211

这里也远远高于期望值，说明应用的涉及和提交的频率也都是合理的。

这里，基本上可以排除掉了：

A、IO问题

B、应用提交过于频繁的问题。

基于以上情况，我们再结合ASH的报告看一下：

TopSQL with Top EventsTopSQL statements by DB Time along with the top events by DB Time forthose SQLs.%Activity is the percentage of DB Time due to the SQL.%Event is the percentage of DB Time due to the event that the SQL iswaiting on.%Row Source is the percentage of DB Time due to the row source for theSQL waiting on the event.Executionsis the number of executions of the SQL that were sampled in ASH.SQLID Plan Hash Executions % Activity Event % Event Top Row Source % RowSource SQL Text Container Name6n7g6c077brjn803 20.85 CPU + Wait for CPU 9.44 ** Row Source Not Available ** 9.44insert into EVENT_FLOW_DETAIL_… PDBTPH16n7g6c077brjn803 20.85 db file sequential read 6.69 ** Row Source Not Available **6.69 insert into EVENT_FLOW_DETAIL_… PDBTPH16n7g6c077brjn803 20.85 log buffer space 2.04 ** Row Source Not Available ** 2.04insert into EVENT_FLOW_DETAIL_… PDBTPH1f8sc80c9z96d6459533022 61 5.38 buffer busy waits 3.99 INDEX – UNIQUE SCAN 3.99select count(*) from READWRITE… PDBTPH10npaa07q0pttb74 3.74 log buffer space 2.31 ** Row Source Not Available ** 2.31insert into READWRITE_LOG(data… PDBTPH188kr8yruv2gnj39 2.75 buffer busy waits 1.36 ** Row Source Not Available ** 1.36insert into READWRITE_LOG(data… PDBTPH1gdk0gfjud55cd3141682953 36 1.41 log buffer space 0.68 UPDATE 0.68 updatest_cdr_eventerr set tot… PDBTPH1

这个报告里，直接看到的20.85的Activity%都是CPU+WaitOn CPU上，而我们知道数据库的等待的事件logbuffer space也是它造成的，那么也就是20.85+20.85+3.74+1.41的百分比的事件采样都在CPU上等待。

看OSwatcher里CPU的情况：

vmstat里看起来CPU不是特别忙：

zzz***Fri Jan 15 14:22:13 BEIST 2021Systemconfiguration: lcpu=72 mem=184320MB ent=18.00kthrmemory page faults cpu——————- ———————— ———————————–rb p avm fre fi fo pi po fr sr in sy cs us sy id wa pc ec110 0 18182240 26782687 0 64 0 0 0 0 3077 95404 18331 14 13 74 0 7.3240.6170 2 18227945 26736960 0 0 0 0 0 0 1708 67546 16123 12 10 77 0 6.1434.1110 0 18259599 26705274 0 0 0 0 0 0 1668 104636 20241 12 10 79 0 5.9132.8zzz***Fri Jan 15 14:22:43 BEIST 2021Systemconfiguration: lcpu=72 mem=184320MB ent=18.00

由于vmstat计算的是平均值，我们看看具体的信息：

Systemconfiguration: lcpu=72 ent=18.0 mode=Capped

cpumin maj mpc int cs ics rq mig lpa sysc us sy wa id pc %ec lcs011582 0 0 696 1105 116 1 404 94 5318 46 53 0 1 0.37 2.1 46610 0 0 17 0 0 0 0 – 0 0 0 0 100 0.07 0.4 1720 0 0 18 0 0 0 0 – 0 0 0 0 100 0.07 0.4 1830 0 0 18 0 0 0 0 – 0 0 0 0 100 0.07 0.4 18418024 0 0 425 876 116 0 331 93 66250 69 30 0 1 0.27 1.5 42250 0 0 19 0 0 0 0 – 0 0 1 0 99 0.05 0.3 1960 0 0 19 0 0 0 0 – 0 0 0 0 100 0.05 0.3 1970 0 0 19 0 0 0 0 – 0 0 0 0 100 0.05 0.3 19812948 0 0 459 1117 125 0 414 96 6172 65 34 0 1 0.28 1.5 41490 0 0 19 0 0 0 0 – 0 0 0 0 100 0.05 0.3 20100 0 0 19 0 0 0 0 – 0 0 0 0 100 0.05 0.3 19110 0 0 17 0 0 0 0 – 0 0 0 0 100 0.05 0.3 17129500 0 0 537 1278 115 2 391 96 5561 55 43 0 2 0.25 1.4 516130 0 0 19 0 0 0 0 – 0 0 0 0 100 0.05 0.3 20140 0 0 19 0 0 0 0 – 0 0 0 0 100 0.05 0.3 20150 0 0 19 0 0 0 0 – 0 0 0 0 100 0.05 0.3 201615891 0 0 306 724 80 1 297 93 8875 54 45 0 1 0.32 1.8 297170 0 0 19 0 0 0 0 – 0 0 0 0 100 0.06 0.3 20180 0 0 18 0 0 0 0 – 0 0 0 0 100 0.06 0.3 19190 0 0 17 0 0 0 0 – 0 0 0 0 100 0.06 0.3 182011809 0 0 487 1160 109 0 425 96 6827 50 48 0 2 0.23 1.3 484210 0 0 19 0 0 0 0 – 0 0 1 0 99 0.05 0.3 19220 0 0 18 0 0 0 0 – 0 0 0 0 100 0.05 0.3 20230 0 0 19 0 0 0 0 – 0 0 1 0 99 0.05 0.3 202416369 0 0 700 1172 175 1 398 96 9610 54 44 0 1 0.31 1.7 533250 0 0 19 0 0 0 0 – 0 0 0 0 100 0.06 0.3 19260 0 0 19 0 0 0 0 – 0 0 0 0 100 0.06 0.3 19270 0 0 19 0 0 0 0 – 0 0 0 0 100 0.06 0.3 192810775 0 0 248 308 23 0 109 97 4042 68 32 0 0 0.44 2.4 184290 0 0 18 0 0 0 0 – 0 0 0 0 100 0.08 0.4 18300 0 0 18 0 0 0 0 – 0 0 0 0 100 0.08 0.4 18310 0 0 17 0 0 0 0 – 0 0 0 0 100 0.08 0.4 173217188 0 0 390 795 92 0 348 95 5781 66 32 0 1 0.22 1.2 347330 0 0 18 0 0 0 0 – 0 0 0 0 100 0.04 0.2 18340 0 0 17 0 0 0 0 – 0 0 0 0 100 0.04 0.2 17350 0 0 17 0 0 0 0 – 0 0 0 0 100 0.04 0.2 173617666 0 0 432 870 73 0 348 95 5447 67 31 0 2 0.20 1.1 383370 0 0 19 0 0 0 0 – 0 0 1 0 99 0.04 0.2 20380 0 0 18 0 0 0 0 – 0 0 0 0 100 0.04 0.2 18390 0 0 18 0 0 0 0 – 0 0 1 0 99 0.04 0.2 184025199 0 0 357 990 160 1 361 75 5932 59 37 0 4 0.29 1.6 582415707 0 0 188 437 19 0 90 100 511 25 25 0 51 0.10 0.6 2624284 0 0 18 1 0 0 0 100 54 1 2 0 98 0.06 0.3 21430 0 0 17 9 0 0 1 100 5 0 1 0 99 0.06 0.3 214416521 0 0 289 498 48 0 229 95 7464 63 36 0 1 0.32 1.8 271450 0 0 18 0 0 0 0 – 0 0 1 0 99 0.06 0.3 19460 0 0 19 0 0 0 0 – 0 0 0 0 100 0.06 0.3 18470 0 0 18 0 0 0 0 – 0 0 0 0 100 0.06 0.3 184810136 0 1 340 697 71 0 303 95 10628 45 54 0 1 0.22 1.2 325490 0 0 19 0 0 0 0 – 0 0 1 0 99 0.04 0.2 19500 0 0 19 0 0 0 0 – 0 0 0 0 100 0.04 0.2 19510 0 0 19 0 0 0 0 – 0 0 0 0 100 0.04 0.2 19527850 0 0 542 1253 109 0 512 95 3575 55 43 0 2 0.22 1.2 487530 0 0 19 0 0 0 0 – 0 0 0 0 100 0.04 0.2 19540 0 0 19 0 0 0 0 – 0 0 0 0 100 0.04 0.2 19550 0 0 19 0 0 0 0 – 0 0 0 0 100 0.04 0.2 19566305 0 0 200 464 81 0 132 79 2582 38 23 0 39 0.21 1.2 29957241 0 0 105 58 58 1 0 100 6 100 0 0 0 0.60 3.3 3580 0 0 20 2 0 0 1 100 2 0 0 0 100 0.09 0.5 21590 0 0 18 0 0 0 0 – 0 0 0 0 100 0.09 0.5 18608082 0 0 132 411 68 1 131 73 48108 48 43 0 10 0.28 1.5 369613843 0 0 106 72 21 0 3 100 4137 70 12 0 19 0.22 1.2 136620 0 0 18 0 0 0 0 – 0 0 0 0 100 0.07 0.4 18630 0 0 18 0 0 0 0 – 0 0 0 0 100 0.07 0.4 186412474 0 0 379 915 89 0 354 95 29274 47 52 0 1 0.24 1.3 398650 0 0 18 0 0 0 0 – 0 0 1 0 99 0.04 0.2 18660 0 0 18 0 0 0 0 – 0 0 1 0 99 0.04 0.2 18670 0 0 18 0 0 0 0 – 0 0 0 0 100 0.04 0.2 18686916 0 0 537 1157 134 0 219 84 5124 48 46 0 6 0.22 1.2 787691401 0 0 114 261 14 0 49 100 2158 50 15 0 35 0.11 0.6 2437019 0 0 25 11 0 0 0 100 41 1 2 0 97 0.05 0.3 29710 0 0 18 0 0 0 0 – 0 0 0 0 100 0.05 0.3 18U- – – – – – – – – – – – 0 71 10.04 55.8 -ALL246530 0 1 8893 16641 1896 8 5850 0 243484 18 11 0 71 8.61 47.9 9155

这里我们看到CPU的情况就不乐观了，问题应该就是来自于LGWR没有被CPU及时调度了。而我们能看到有一些CPU的idle是100%，而有一批的CPU的idle是0%，而且有些idle为0的CPU的工作状态，还有大部分是分配给了sys的。

比如：

45421 0 0 752 1446 174 1 747 95 4130 68 31 0 1 0.40 2.2 346640 0 0 119 0 0 0 0 – 0 0 48 0 52 0.00 0.0 1196412474 0 0 379 915 89 0 354 95 29274 47 52 0 1 0.24 1.3 398

无论如何，CPU有空闲但是看起来LGWR的进程，并没有被CPU及时的进行调度，所以才产生了当前500ms的logfile sync的等待。3、分析总结

根据现象看，就是LGWR不能及时被CPU调度

解决方案为:

确认Aix的补丁打到了最高的版本，打了最新的Aix补丁，避免是Aix的bug引发的类似问题，已确认为最新补丁。

联系主机侧确认CPU工作状态情况为什么是这样的(只有个别CPU非常忙，其它都不工作)，确认关掉了IBM主机的CPU 折叠的功能可以通过HMC/ASMI设置，关闭操作系统的CPU折叠的功能，关闭CPUfolding

把LGWR的进程直接放在RR的调度方式里：SQL>altersystem set “_high_priority_processes”=’LMS*|LGWR’ sid=’*’scope=spfile;

为了避免Oracle让LGWR进入idle的状态，关掉adaptive log file sync的工作模式，看是否有改进ALTERSYSTEM SET “_use_adaptive_log_file_sync”= scope=spfile sid=’*’;

在ASH里还看到了和log buffer相关的等待，虽然次数不多，但是足以说明我们调整log buffer的大小会优化系统，特别是应用的提交频率不高，这会对log buffer 的大小有更大的要求，可以调整log buffer的大小到32M或者更大。