1. 故障背景
同事在客户现场进行POC测试,测试过程不太顺利,节点1的GRID集群自动重启。为了排除隐患,需要找到集群重启的原因。
数据库环境: 12.2.0.1 两节点RAC,安装了最新的PSU补丁。
2. 故障原因分析
(1). 查看节点1的asm日志。
2024-07-18T18:16:25.925231+08:00
Process m000 died, see its trace file
2024-07-18T18:16:29.138658+08:00
Instance termination initiated by instance 2 with reason 1.
2024-07-18T18:16:29.213929+08:00
Received an instance abort message from instance 2
可以看出,节点1是被节点2驱逐的。
(2).查看lmon日志。
*** 2024-07-18T18:16:22.790193+08:00
ConnReq: id 1 timeout 20 secs options x1
ConnReq: 0x7ffff1b476a8 in pending (3) queue w/ state 0x0
ConnReq: time submit at 0x6698eb61 start 0x6698eb62 expire 0x6698eb76
ConnReq: inst initmap: 1 2
ConnReq: inst nrsptmap: 1
ConnReq id 1 hist:
inst 2 state 0x3 reqtm 1721297762 acktm 1721297762
kjxgm_conn: reqid 1 status 2 nonresp 1 master 1
kjxgm_conn: action 4 nonresp map: 1
kjxgm_conn: issue an IMR
2024-07-18 18:16:22.790 : kjxgrcomerr: Comm reconfig to inst 1 by ospid 27721 inc (8,8)
2024-07-18 18:16:22.795 : kjxgrrcfg: done (device ok) - ret = 3 hist 0x1679a (initial rsn: 3, cachd rsn: 0)
kjxgrrcfgchk: Initiating reconfig, reason=3
reason=3,通常可能的原因大致如下:a. 网络异常。 b. 主机资源耗尽。 c. 数据库争用。 d. 数据库BUG。
(3). 查看osw日志。
发现故障点之前的几分钟内,CPU空闲率基本为0,其中sys%高达70%。
(4). 至此,故障原因基本上有点线索了,CPU耗尽,导致集群间通信异常,所以节点2将节点1驱逐。那为什么sys%这么高呢? 从现场的同事反馈得知,故障可以复现,能复现就好办,让同事用perf工具抓取数据,同时让故障复现。
(5).继续查看osw相关日志。
此时,又发现其他异常。a. 故障之前的几分钟内,swap free迅速下降为0。 b. 故障之前的几分钟,消耗CPU最多的进程是kswapd进程。
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
492 root 20 0 0 0 0 R 100.0 0.0 7:02.23 kswapd3:0
490 root 20 0 0 0 0 R 96.8 0.0 9:36.64 kswapd1:0
489 root 20 0 0 0 0 S 75.4 0.0 6:53.02 kswapd0:0
491 root 20 0 0 0 0 S 50.8 0.0 9:11.47 kswapd2:0
看到这里,真正导致故障的原因,原来是内存耗尽,导致大量的页交换所至。
(6).同时,现场的同事也复现了故障,分析抓取的perf信息。page_vma_mapped_walk函数排一第一位,遥遥领先。 看这个函数名大概也能猜出是虚拟内存页相关。
(7). 这两条证据链,都指向了内存相关。 让现场的同事检查数据库的内存设置情况,果然发现异常。 合理设置数据库相关内存后,故障消失。
3. 通过这个案例,其实主要是想介绍perf工具。在这个案例中,其实完全不需要perf也能找出故障原因。 但在一些复杂的案例中,尤其sys%占比非常高的情况下,用perf找到内核调用,真的非常棒。
标签:perf,16,top,故障,sys%,节点,07 From: https://www.cnblogs.com/missyou-shiyh/p/18310473