利用 perf top找出 sys%高的原因
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找到内核调用，真的非常棒。
