小伙伴们，大家好。
这次分享一个因为应用连接数暴涨进而导致数据库hang的故障分析处理经验。
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节点实例，均恢复正常。 |
根据问题发生时段数据库预警文件、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 Events TopSQL 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 Name 6n7g6c077brjn803 20.85 CPU + Wait for CPU 9.44 ** Row Source Not Available ** 9.44insert into EVENT_FLOW_DETAIL_... PDBTPH1 6n7g6c077brjn803 20.85 db file sequential read 6.69 ** Row Source Not Available **6.69 insert into EVENT_FLOW_DETAIL_... PDBTPH1 6n7g6c077brjn803 20.85 log buffer space 2.04 ** Row Source Not Available ** 2.04insert into EVENT_FLOW_DETAIL_... PDBTPH1 f8sc80c9z96d6459533022 61 5.38 buffer busy waits 3.99 INDEX - UNIQUE SCAN 3.99select count(*) from READWRITE... PDBTPH1 0npaa07q0pttb74 3.74 log buffer space 2.31 ** Row Source Not Available ** 2.31insert into READWRITE_LOG(data... PDBTPH1 88kr8yruv2gnj39 2.75 buffer busy waits 1.36 ** Row Source Not Available ** 1.36insert into READWRITE_LOG(data... PDBTPH1 gdk0gfjud55cd3141682953 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 2021 Systemconfiguration: lcpu=72 mem=184320MB ent=18.00 kthrmemory page faults cpu ------------------- ------------------------ ----------------------------------- rb p avm fre fi fo pi po fr sr in sy cs us sy id wa pc ec 110 0 18182240 26782687 0 64 0 0 0 0 3077 95404 18331 14 13 74 0 7.3240.6 170 2 18227945 26736960 0 0 0 0 0 0 1708 67546 16123 12 10 77 0 6.1434.1 110 0 18259599 26705274 0 0 0 0 0 0 1668 104636 20241 12 10 79 0 5.9132.8 zzz***Fri Jan 15 14:22:43 BEIST 2021 Systemconfiguration: 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 lcs 011582 0 0 696 1105 116 1 404 94 5318 46 53 0 1 0.37 2.1 466 10 0 0 17 0 0 0 0 - 0 0 0 0 100 0.07 0.4 17 20 0 0 18 0 0 0 0 - 0 0 0 0 100 0.07 0.4 18 30 0 0 18 0 0 0 0 - 0 0 0 0 100 0.07 0.4 18 418024 0 0 425 876 116 0 331 93 66250 69 30 0 1 0.27 1.5 422 50 0 0 19 0 0 0 0 - 0 0 1 0 99 0.05 0.3 19 60 0 0 19 0 0 0 0 - 0 0 0 0 100 0.05 0.3 19 70 0 0 19 0 0 0 0 - 0 0 0 0 100 0.05 0.3 19 812948 0 0 459 1117 125 0 414 96 6172 65 34 0 1 0.28 1.5 414 90 0 0 19 0 0 0 0 - 0 0 0 0 100 0.05 0.3 20 100 0 0 19 0 0 0 0 - 0 0 0 0 100 0.05 0.3 19 110 0 0 17 0 0 0 0 - 0 0 0 0 100 0.05 0.3 17 129500 0 0 537 1278 115 2 391 96 5561 55 43 0 2 0.25 1.4 516 130 0 0 19 0 0 0 0 - 0 0 0 0 100 0.05 0.3 20 140 0 0 19 0 0 0 0 - 0 0 0 0 100 0.05 0.3 20 150 0 0 19 0 0 0 0 - 0 0 0 0 100 0.05 0.3 20 1615891 0 0 306 724 80 1 297 93 8875 54 45 0 1 0.32 1.8 297 170 0 0 19 0 0 0 0 - 0 0 0 0 100 0.06 0.3 20 180 0 0 18 0 0 0 0 - 0 0 0 0 100 0.06 0.3 19 190 0 0 17 0 0 0 0 - 0 0 0 0 100 0.06 0.3 18 2011809 0 0 487 1160 109 0 425 96 6827 50 48 0 2 0.23 1.3 484 210 0 0 19 0 0 0 0 - 0 0 1 0 99 0.05 0.3 19 220 0 0 18 0 0 0 0 - 0 0 0 0 100 0.05 0.3 20 230 0 0 19 0 0 0 0 - 0 0 1 0 99 0.05 0.3 20 2416369 0 0 700 1172 175 1 398 96 9610 54 44 0 1 0.31 1.7 533 250 0 0 19 0 0 0 0 - 0 0 0 0 100 0.06 0.3 19 260 0 0 19 0 0 0 0 - 0 0 0 0 100 0.06 0.3 19 270 0 0 19 0 0 0 0 - 0 0 0 0 100 0.06 0.3 19 2810775 0 0 248 308 23 0 109 97 4042 68 32 0 0 0.44 2.4 184 290 0 0 18 0 0 0 0 - 0 0 0 0 100 0.08 0.4 18 300 0 0 18 0 0 0 0 - 0 0 0 0 100 0.08 0.4 18 310 0 0 17 0 0 0 0 - 0 0 0 0 100 0.08 0.4 17 3217188 0 0 390 795 92 0 348 95 5781 66 32 0 1 0.22 1.2 347 330 0 0 18 0 0 0 0 - 0 0 0 0 100 0.04 0.2 18 340 0 0 17 0 0 0 0 - 0 0 0 0 100 0.04 0.2 17 350 0 0 17 0 0 0 0 - 0 0 0 0 100 0.04 0.2 17 3617666 0 0 432 870 73 0 348 95 5447 67 31 0 2 0.20 1.1 383 370 0 0 19 0 0 0 0 - 0 0 1 0 99 0.04 0.2 20 380 0 0 18 0 0 0 0 - 0 0 0 0 100 0.04 0.2 18 390 0 0 18 0 0 0 0 - 0 0 1 0 99 0.04 0.2 18 4025199 0 0 357 990 160 1 361 75 5932 59 37 0 4 0.29 1.6 582 415707 0 0 188 437 19 0 90 100 511 25 25 0 51 0.10 0.6 262 4284 0 0 18 1 0 0 0 100 54 1 2 0 98 0.06 0.3 21 430 0 0 17 9 0 0 1 100 5 0 1 0 99 0.06 0.3 21 4416521 0 0 289 498 48 0 229 95 7464 63 36 0 1 0.32 1.8 271 450 0 0 18 0 0 0 0 - 0 0 1 0 99 0.06 0.3 19 460 0 0 19 0 0 0 0 - 0 0 0 0 100 0.06 0.3 18 470 0 0 18 0 0 0 0 - 0 0 0 0 100 0.06 0.3 18 4810136 0 1 340 697 71 0 303 95 10628 45 54 0 1 0.22 1.2 325 490 0 0 19 0 0 0 0 - 0 0 1 0 99 0.04 0.2 19 500 0 0 19 0 0 0 0 - 0 0 0 0 100 0.04 0.2 19 510 0 0 19 0 0 0 0 - 0 0 0 0 100 0.04 0.2 19 527850 0 0 542 1253 109 0 512 95 3575 55 43 0 2 0.22 1.2 487 530 0 0 19 0 0 0 0 - 0 0 0 0 100 0.04 0.2 19 540 0 0 19 0 0 0 0 - 0 0 0 0 100 0.04 0.2 19 550 0 0 19 0 0 0 0 - 0 0 0 0 100 0.04 0.2 19 566305 0 0 200 464 81 0 132 79 2582 38 23 0 39 0.21 1.2 299 57241 0 0 105 58 58 1 0 100 6 100 0 0 0 0.60 3.3 3 580 0 0 20 2 0 0 1 100 2 0 0 0 100 0.09 0.5 21 590 0 0 18 0 0 0 0 - 0 0 0 0 100 0.09 0.5 18 608082 0 0 132 411 68 1 131 73 48108 48 43 0 10 0.28 1.5 369 613843 0 0 106 72 21 0 3 100 4137 70 12 0 19 0.22 1.2 136 620 0 0 18 0 0 0 0 - 0 0 0 0 100 0.07 0.4 18 630 0 0 18 0 0 0 0 - 0 0 0 0 100 0.07 0.4 18 6412474 0 0 379 915 89 0 354 95 29274 47 52 0 1 0.24 1.3 398 650 0 0 18 0 0 0 0 - 0 0 1 0 99 0.04 0.2 18 660 0 0 18 0 0 0 0 - 0 0 1 0 99 0.04 0.2 18 670 0 0 18 0 0 0 0 - 0 0 0 0 100 0.04 0.2 18 686916 0 0 537 1157 134 0 219 84 5124 48 46 0 6 0.22 1.2 787 691401 0 0 114 261 14 0 49 100 2158 50 15 0 35 0.11 0.6 243 7019 0 0 25 11 0 0 0 100 41 1 2 0 97 0.05 0.3 29 710 0 0 18 0 0 0 0 - 0 0 0 0 100 0.05 0.3 18 U- - - - - - - - - - - - 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 346 640 0 0 119 0 0 0 0 - 0 0 48 0 52 0.00 0.0 119 6412474 0 0 379 915 89 0 354 95 29274 47 52 0 1 0.24 1.3 398 |
无论如何，CPU有空闲但是看起来LGWR的进程，并没有被CPU及时的进行调度，所以才产生了当前500ms的logfile sync的等待。
根据现象看，就是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"=
在ASH里还看到了和log buffer相关的等待，虽然次数不多，但是足以说明我们调整log buffer的大小会优化系统，特别是应用的提交频率不高，这会对log buffer 的大小有更大的要求，可以调整log buffer的大小到32M或者更大。
文章版权归作者所有，未经允许请勿转载,若此文章存在违规行为，您可以联系管理员删除。
转载请注明本文地址：https://www.ucloud.cn/yun/130004.html
摘要：于是检查时发现，拼写错误，应为。第个问题，是真真切切错误卸载重要软件包，导致系统崩溃，修复系统的方法自然也就是利用原镜像在下把该装的都装回去，前提是日志存在，万幸没有执行过。 首先问题产生的缘由很简单，是我一同事在安装oracle一套软件时，按照要求需要binutils软件包的32位版本，然而在Oracle Linux已经装有64位，按理说是可以安装i686的，我猜应该是32位的版本低...
摘要：问题描述近期项目需要从虚拟机环境迁移到容器环境，其中有一个项目在迁移到容器环境之后的两天之内出现了次死锁的问题，部分关键日志如下日志还是挺明显的，线程获得了锁，等待获取而正好相反，从而导致死锁问题分析以上的错误 问题描述 近期项目需要从虚拟机环境迁移到容器环境，其中有一个项目在迁移到容器环境之后的两天之内出现了2次死锁(deadlock)的问题，部分关键日志如下： Found one ...
摘要：首先先解读下这个报警内容，原因活跃线程数过多，是监听的端口号用来获取虚拟机各项信息，代表着此时的线程数，是设置的报警阈值。 前言 前天，一位21世纪的好好青年正在工位上默念社会主义大法好的时候，钉钉上又报警了（公司项目接入了open-faclon监控，指标不正常会报警给钉钉的机器人），无奈默默流泪挥手告别社会主义大法开始定位线上问题。 报警内容 首先我们先来看下报警信息，为防止泄露公...
阅读 1346·2023-01-11 13:20
阅读 1684·2023-01-11 13:20
阅读 1132·2023-01-11 13:20
阅读 1858·2023-01-11 13:20
阅读 4100·2023-01-11 13:20
阅读 2704·2023-01-11 13:20
阅读 1385·2023-01-11 13:20
阅读 3597·2023-01-11 13:20
