系统和硬件故障导致的三次Redis“诡异”慢查询

一、服务器电源故障造成Redis慢查询

1、发现问题：

我们和业务排查问题时候发现:

• 每天时不时发生：一些小的get命令，耗时达到了40ms（正常是微秒级别）。
• 慢查询集中在1台服务器的全部实例。

2、定位问题：

(1) 快速定位：

快速定位为服务器问题，因为同机器的其他Redis集群均出现上述情况。

机器问题几板斧：

• 分钟级核心指标：cpu、mem、网络、io一通查，没有异常。
• 系统日志：dmesg日志一通查，没有异常。
• 硬件问题：内存、网卡、CPU均正常，只有一台电源异常（当前是单路供电）

(2) 深入定位

因为之前定位过类似问题，单路供电能会导致CPU降频，但是查询监控未发现有降频：

图片

中间又辗转怀疑了很多点，最后排查同学还是怀疑和电源故障有关。

• 添加了CPU主频秒级监控：发现一瞬间降频（从2800MHz 降低到了 120 MHz）时间点和Redis慢查询时间点一致。

图片

• 电源故障开始时间和机器出现异常慢查询时间也是一致的。

3、后续优化：

• 监控单服务器慢查询数量：基本上有多个集群都有慢查询，机器可能就有问题。
• 对于单路电源故障，之前绝对非高优维修，后期需要对此磊故障增加优先级。
• 添加对CPU频率告警和提供秒级诊断工具能力。

二、服务器MCE造成Redis慢查询

1、发现问题：

某周末晚上，某业务在21:55可用性突然报警，从100%->98%，经排查该分钟该集群的全部实例出现慢日志(均为小命令)，并且集中在一台机器。

图片

2、定位问题：

(1) 快速定位：

快速定位为服务器问题，因为同机器的其他Redis集群均出现上述情况。

机器问题几板斧：

• 分钟级核心指标：cpu、mem、网络、io一通查，没有异常。
• 硬件问题：内存、网卡、CPU、电源均正常。
• 系统日志：dmesg有异常日志，初步判断MCE在做内存故障纠错。

May 18 21:55:04 机器名 kernel: {2}[Hardware Error]: Hardware error from APEI Generic Hardware Error Source: 4
May 18 21:55:04 机器名 kernel: {2}[Hardware Error]: It has been corrected by h/w and requires no further action
May 18 21:55:04 机器名 kernel: {2}[Hardware Error]: event severity: corrected
May 18 21:55:04 机器名 kernel: {2}[Hardware Error]:  Error 0, type: corrected
May 18 21:55:04 机器名 kernel: {2}[Hardware Error]:  fru_text: A2
May 18 21:55:04 机器名 kernel: {2}[Hardware Error]:   section_type: memory error
May 18 21:55:04 机器名 kernel: {2}[Hardware Error]:   error_status: 0x0000000000000400
May 18 21:55:04 机器名 kernel: {2}[Hardware Error]:   physical_address: 0x00000009f7466ac0
May 18 21:55:04 机器名 kernel: {2}[Hardware Error]:   node: 0 card: 1 module: 0 rank: 0 bank: 0 row: 18297 column: 936
May 18 21:55:04 机器名 kernel: {2}[Hardware Error]:   error_type: 2, single-bit ECC
May 18 21:55:04 机器名 kernel: core: [Hardware Error]: Machine check events logged
May 18 21:55:04 机器名 kernel: EDAC MC0: 0 CE memory read error on CPU_SrcID#0_Ha#0_Chan#1_DIMM#0 (channel:1 slot:0 page:0x9f7466 offset:0xac0 grain:32 syndrome:0x0 -  area:DRAM err_code:0000:009f socket:0 ha:0 channel_mask:2 rank:0)
May 18 21:55:04 机器名 kernel: EDAC MC0: 0 CE memory read error on CPU_SrcID#0_Ha#0_Chan#1_DIMM#0 (channel:1 slot:0 page:0x9f7467 offset:0x5c0 grain:32 syndrome:0x0 -  area:DRAM err_code:0000:009f socket:0 ha:0 channel_mask:2 rank:0)
May 18 21:55:04 机器名 kernel: EDAC MC0: 0 CE memory read error on CPU_SrcID#0_Ha#0_Chan#1_DIMM#0 (channel:1 slot:0 page:0x9f7441 offset:0xa40 grain:32 syndrome:0x0 -  area:DRAM err_code:0000:009f socket:0 ha:0 channel_mask:2 rank:0)
May 18 21:55:04 机器名 kernel: EDAC MC0: 0 CE memory read error on CPU_SrcID#0_Ha#0_Chan#1_DIMM#0 (channel:1 slot:0 page:0x9f7447 offset:0x140 grain:32 syndrome:0x0 -  area:DRAM err_code:0000:009f socket:0 ha:0 channel_mask:2 rank:0)
May 18 21:55:05 机器名 kernel: EDAC MC0: 0 CE memory read error on CPU_SrcID#0_Ha#0_Chan#1_DIMM#0 (channel:1 slot:0 page:0x9f7443 offset:0x640 grain:32 syndrome:0x0 -  area:DRAM err_code:0000:009f socket:0 ha:0 channel_mask:2 rank:0)
May 18 21:55:05 机器名 kernel: EDAC MC0: 0 CE memory read error on CPU_SrcID#0_Ha#0_Chan#1_DIMM#0 (channel:1 slot:0 page:0x9f7444 offset:0x240 grain:32 syndrome:0x0 -  area:DRAM err_code:0000:009f socket:0 ha:0 channel_mask:2 rank:0)
May 18 21:55:06 机器名 kernel: EDAC MC0: 0 CE memory read error on CPU_SrcID#0_Ha#0_Chan#1_DIMM#0 (channel:1 slot:0 page:0x9f74e5 offset:0x3c0 grain:32 syndrome:0x0 -  area:DRAM err_code:0000:009f socket:0 ha:0 channel_mask:2 rank:0)
May 18 21:55:06 机器名 kernel: EDAC MC0: 0 CE memory read error on CPU_SrcID#0_Ha#0_Chan#1_DIMM#0 (channel:1 slot:0 page:0x9f7461 offset:0xac0 grain:32 syndrome:0x0 -  area:DRAM err_code:0000:009f socket:0 ha:0 channel_mask:2 rank:0)
May 18 21:55:06 机器名 kernel: EDAC MC0: 0 CE memory read error on CPU_SrcID#0_Ha#0_Chan#1_DIMM#0 (channel:1 slot:0 page:0x9f7460 offset:0x3c0 grain:32 syndrome:0x0 -  area:DRAM err_code:0000:009f socket:0 ha:0 channel_mask:2 rank:0)
May 18 21:55:06 机器名 kernel: EDAC MC0: 0 CE memory read error on CPU_SrcID#0_Ha#0_Chan#1_DIMM#0 (channel:1 slot:0 page:0x9f7464 offset:0x2c0 grain:32 syndrome:0x0 -  area:DRAM err_code:0000:009f socket:0 ha:0 channel_mask:2 rank:0)
May 18 21:55:07 机器名 kernel: EDAC MC0: 0 CE memory read error on CPU_SrcID#0_Ha#0_Chan#1_DIMM#0 (channel:1 slot:0 page:0x9f7440 offset:0x340 grain:32 syndrome:0x0 -  area:DRAM err_code:0000:009f socket:0 ha:0 channel_mask:2 rank:0)

(2) 一些基础知识(我也是临时学的，如果不对欢迎来喷)

• 什么是MCE？

MCE全称Machine check exception，英文解释如下(论文：https://www.halobates.de/mce.pdf)，简单说有硬件错误，需要中断当前的进程，调用一个专用的硬件异常处理handler进行处理。

A machine check exception happens when there is an error that the hardware cannot correct. It will cause the CPU to interrupt the current program and call a special exception handler.
With a silent machine check the hardware was abl

• MCE什么时候触发

通过修改/sys/devices/system/machinecheck/machinecheck0/check_interval 的值，可以调整错误修复的初始和最大轮询间隔。

• 硬件错误分类

1. CE，可纠正错误；（注意这里的CE和MCE也不是一个东西，corrected exception）
2. UE，不可纠正错误，但系统没有崩溃（通常进程coredump，异常退出）；
3. Fatal，不可纠正错误，系统崩溃。

从可用性角度看，似乎最应该关注的是2，3类错误，但实际上1类错误更具有欺骗性，在分布式系统中，确定性要好过不确定性。

• x86处理硬件故障的方式

1. PCIe AER 是PCIe的新特性，发生故障时，通过中断报告故障详情；
2. APEI，先通过SMI进入BIOS/firmware，让BIOS/firmware先处理，其根据处理情况决定要不要通知OS继续处理；
3. BIOS/firmware 可以通过MCE中断，让OS继续处理。

这里重点是SMI中断（SMI中断使CPU进入SMM），它是Linux无法感知的，如果BIOS/firmware 处理错误耗费了太长时间，可能导致延迟抖动，没有统一的方法从Linux测度量。而其它中断是Linux处理的，其耗时Linux总是有办法度量。

(3) 日志分析，几个核心点：

• CE Memory：可纠正的内存错误

May 18 21:55:04 机器名 kernel: EDAC MC0: 0 CE memory read error on CPU_SrcID#0_Ha#0_Chan#1_DIMM#0 (channel:1 slot:0 page:0x9f7466 offset:0xac0 grain:32 syndrome:0x0 -  area:DRAM err_code:0000:009f socket:0 ha:0 channel_mask:2 rank:0)

• 关键日志：

Machine check events logged

• 内存错误和内存信息：

May 18 21:55:04 机器名 kernel: {2}[Hardware Error]:  fru_text: A2
May 18 21:55:04 机器名 kernel: {2}[Hardware Error]:   section_type: memory error
May 18 21:55:04 机器名 kernel: {2}[Hardware Error]:   error_status: 0x0000000000000400
May 18 21:55:04 机器名 kernel: {2}[Hardware Error]:   physical_address: 0x00000009f7466ac0
May 18 21:55:04 机器名 kernel: {2}[Hardware Error]:   node: 0 card: 1 module: 0 rank: 0 bank: 0 row: 18297 column: 936
May 18 21:55:04 机器名 kernel: {2}[Hardware Error]:   error_type: 2, single-bit ECC

3、结论：

系统发生硬件错误会导致机器进入 MCE中断，可能会将大部份内核时间用于处理 MCE中断(例如本例子CE Memory)。

三、THP造成

这个就是一个凑数的，很早之前遇到的，在《Redis开发与运维》一书也提过，原文如下：

图片

四、其他案例

1、不可纠正硬件错误：

Uncorrected hardware memory error ，导致Redis直接core。

May 27 15:48:58 机器名 kernel: core: Uncorrected hardware memory error in user-access at 1a1f914a80
May 27 15:48:58 机器名 kernel: core: [Hardware Error]: Machine check events logged
May 27 15:48:58 机器名 mcelog: Hardware event. This is not a software error.
May 27 15:48:58 机器名 mcelog: MCE 0
May 27 15:48:58 机器名 mcelog: CPU 15 BANK 1 TSC e7a1f64e03e47a
May 27 15:48:58 机器名 mcelog: RIP 33:465af1
May 27 15:48:58 机器名 mcelog: MISC 86 ADDR 1a1f914a80
May 27 15:48:58 机器名 mcelog: TIME 1716796138 Mon May 27 15:48:58 2024
May 27 15:48:58 机器名 mcelog: MCG status:RIPV EIPV MCIP LMCE
May 27 15:48:58 机器名 mcelog: MCi status:
May 27 15:48:58 机器名 mcelog: Uncorrected error
May 27 15:48:58 机器名 mcelog: Error enabled
May 27 15:48:58 机器名 mcelog: MCi_MISC register valid
May 27 15:48:58 机器名 mcelog: MCi_ADDR register valid
May 27 15:48:58 机器名 mcelog: SRAR
May 27 15:48:58 机器名 mcelog: MCA: Data CACHE Level-0 Data-Read Error
May 27 15:48:58 机器名 mcelog: STATUS bd80000000100134 MCGSTATUS f
May 27 15:48:58 机器名 mcelog: MCGCAP f000c14 APICID 1e SOCKETID 0
May 27 15:48:58 机器名 mcelog: PPIN 2c6b0193f6fb1bb7
May 27 15:48:58 机器名 mcelog: CPUID Vendor Intel Family 6 Model 85
May 27 15:48:58 机器名 mcelog: warning: 8 bytes ignored in each record
May 27 15:48:58 机器名 mcelog: consider an update
May 27 15:48:58 机器名 kernel: Memory failure: 0x1a1f914: Killing redis-server:44454 due to hardware memory corruption
May 27 15:48:58 机器名 kernel: Memory failure: 0x1a1f914: recovery action for dirty LRU page: Recovered
May 27 15:48:58 机器名 kernel: MCE: Killing redis-server:44454 due to hardware memory corruption fault at 7f392cb4a9c0

2、CPU温度过高，导致可能降频：

(1) 日志：

Jun  2 20:13:29 机器名 kernel: CPU20: Core temperature above threshold, cpu clock throttled (total events = 176720)
Jun  2 20:13:30 机器名 kernel: CPU48: Core temperature above threshold, cpu clock throttled (total events = 176498)
Jun  2 20:17:30 机器名 kernel: CPU50: Core temperature above threshold, cpu clock throttled (total events = 177150)
Jun  2 20:17:30 机器名 kernel: CPU22: Core temperature above threshold, cpu clock throttled (total events = 177136)
Jun  2 20:20:57 机器名 kernel: CPU44: Core temperature above threshold, cpu clock throttled (total events = 269866)
Jun  2 20:20:58 机器名 kernel: CPU16: Core temperature above threshold, cpu clock throttled (total events = 269730)
Jun  2 20:37:29 机器名 kernel: CPU54: Core temperature above threshold, cpu clock throttled (total events = 33630)
Jun  2 20:37:30 机器名 kernel: CPU26: Core temperature above threshold, cpu clock throttled (total events = 33635)
Jun  2 20:45:29 机器名 kernel: CPU17: Core temperature above threshold, cpu clock throttled (total events = 214231)
Jun  2 20:45:30 机器名 kernel: CPU45: Core temperature above threshold, cpu clock throttled (total events = 214140)

(2) 基础知识

关于CPU功耗管理，有以下几种模式：

performance   运行于最大频率
    powersave     运行于最小频率
    userspace     运行于用户指定的频率
    ondemand      按需快速动态调整CPU频率， 一有cpu计算量的任务，就会立即达到最                   大频率运行，空闲时间增加就降低频率
    conservative  按需快速动态调整CPU频率， 比 ondemand 的调整更保守
    schedutil     基于调度程序调整 CPU 频率

查看当前支持模式：

$ cat /sys/devices/system/cpu/cpu0/cpufreq/scaling_available_governors
performance powersave

查看当前使用模式：

$ cat /sys/devices/system/cpu/cpu0/cpufreq/scaling_governor
performance

(3) 代码分析：

内核代码：cpu温度超过阈值会打印系统日志，但是是否降频还和 /sys/devices/system/cpu/cpu0/cpufreq/scaling_governor模式有关。

图片

五、总结：

本文粗浅分析了在Redis使用过程中遇到的诡异慢查询问题，其中包含了硬件故障相关，系统参数错误优化等问题，当然实际在使用和运维过程中可能还有其他诡异情况，需要具体问题具体分析。

原文地址：https://mp.weixin.qq.com/s/L6Get0C_uWn2UWn-lXa2yA