系統和硬件故障導致的三次Redis“詭異”慢查詢
作者：付磊
本文粗淺分析了在Redis使用過程中遇到的詭異慢查詢問題，其中包含了硬件故障相關，系統參數錯誤優化等問題，當然實際在使用和運維過程中可能還有其他詭異情況，需要具體問題具體分析。
一、服務器電源故障造成Redis慢查詢
1、發現問題：
我們和業務排查問題時候發現:
- 每天時不時發生：一些小的get命令，耗時達到了40ms（正常是微秒級別）。
- 慢查詢集中在1臺服務器的全部實例。
實例 | 角色 | 耗時(微秒) | 命令 | value大小 |
10.xx.xx.xx:yy | master | 41,432 | get rta_12345xxxx | 15字節 |
10.xx.xx.xx:yy | master | 41,613 | get rta_6789yyyyy | 15字節 |
2、定位問題：
(1) 快速定位：
快速定位為服務器問題，因為同機器的其他Redis集群均出現上述情況。
機器問題幾板斧：
- 分鐘級核心指標：cpu、mem、網絡、io一通查，沒有異常。
- 系統日志：dmesg日志一通查，沒有異常。
- 硬件問題：內存、網卡、CPU均正常，只有一臺電源異常（當前是單路供電）
(2) 深入定位
因為之前定位過類似問題，單路供電能會導致CPU降頻，但是查詢監控未發現有降頻：
圖片
中間又輾轉懷疑了很多點，最后排查同學還是懷疑和電源故障有關。
- 添加了CPU主頻秒級監控：發現一瞬間降頻（從2800MHz 降低到了 120 MHz）時間點和Redis慢查詢時間點一致。
圖片
- 電源故障開始時間和機器出現異常慢查詢時間也是一致的。
3、后續優化：
- 監控單服務器慢查詢數量：基本上有多個集群都有慢查詢，機器可能就有問題。
- 對于單路電源故障，之前絕對非高優維修，后期需要對此磊故障增加優先級。
- 添加對CPU頻率告警和提供秒級診斷工具能力。
二、服務器MCE造成Redis慢查詢
1、發現問題：
某周末晚上，某業務在21:55可用性突然報警，從100%->98%，經排查該分鐘該集群的全部實例出現慢日志(均為小命令)，并且集中在一臺機器。
實例 | 角色 | 耗時(微秒) | 命令 | value大小 |
10.xx.xx.xx:yy | master | 20,421 | incr small_key1 | 10字節 |
10.xx.xx.xx:yy | master | 21,324 | get small_key2 | 10字節 |
圖片
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 的值，可以調整錯誤修復的初始和最大輪詢間隔。
- 硬件錯誤分類
- CE，可糾正錯誤；（注意這里的CE和MCE也不是一個東西，corrected exception）
- UE，不可糾正錯誤，但系統沒有崩潰（通常進程coredump，異常退出）；
- Fatal，不可糾正錯誤，系統崩潰。
從可用性角度看，似乎最應該關注的是2，3類錯誤，但實際上1類錯誤更具有欺騙性，在分布式系統中，確定性要好過不確定性。
- x86處理硬件故障的方式
- PCIe AER 是PCIe的新特性，發生故障時，通過中斷報告故障詳情；
- APEI，先通過SMI進入BIOS/firmware，讓BIOS/firmware先處理，其根據處理情況決定要不要通知OS繼續處理；
- 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 ECC3、結論：
系統發生硬件錯誤會導致機器進入 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 7f392cb4a9c02、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使用過程中遇到的詭異慢查詢問題，其中包含了硬件故障相關，系統參數錯誤優化等問題，當然實際在使用和運維過程中可能還有其他詭異情況，需要具體問題具體分析。
責任編輯：武曉燕
來源：
Redis開發運維實戰
