系統(tǒng)和硬件故障導(dǎo)致的三次Redis“詭異”慢查詢

作者：付磊 2024-06-03 10:10:01

本文粗淺分析了在Redis使用過(guò)程中遇到的詭異慢查詢問(wèn)題，其中包含了硬件故障相關(guān)，系統(tǒng)參數(shù)錯(cuò)誤優(yōu)化等問(wèn)題，當(dāng)然實(shí)際在使用和運(yùn)維過(guò)程中可能還有其他詭異情況，需要具體問(wèn)題具體分析。

一、服務(wù)器電源故障造成Redis慢查詢

1、發(fā)現(xiàn)問(wèn)題：

我們和業(yè)務(wù)排查問(wèn)題時(shí)候發(fā)現(xiàn):

每天時(shí)不時(shí)發(fā)生：一些小的get命令，耗時(shí)達(dá)到了40ms（正常是微秒級(jí)別）。
慢查詢集中在1臺(tái)服務(wù)器的全部實(shí)例。

實(shí)例	角色	耗時(shí)(微秒)	命令	value大小
10.xx.xx.xx:yy	master	41,432	get rta_12345xxxx	15字節(jié)
10.xx.xx.xx:yy	master	41,613	get rta_6789yyyyy	15字節(jié)

2、定位問(wèn)題：

(1) 快速定位：

快速定位為服務(wù)器問(wèn)題，因?yàn)橥瑱C(jī)器的其他Redis集群均出現(xiàn)上述情況。

機(jī)器問(wèn)題幾板斧：

分鐘級(jí)核心指標(biāo)：cpu、mem、網(wǎng)絡(luò)、io一通查，沒(méi)有異常。
系統(tǒng)日志：dmesg日志一通查，沒(méi)有異常。
硬件問(wèn)題：內(nèi)存、網(wǎng)卡、CPU均正常，只有一臺(tái)電源異常（當(dāng)前是單路供電）

(2) 深入定位

因?yàn)橹岸ㄎ贿^(guò)類似問(wèn)題，單路供電能會(huì)導(dǎo)致CPU降頻，但是查詢監(jiān)控未發(fā)現(xiàn)有降頻：

圖片

中間又輾轉(zhuǎn)懷疑了很多點(diǎn)，最后排查同學(xué)還是懷疑和電源故障有關(guān)。

添加了CPU主頻秒級(jí)監(jiān)控：發(fā)現(xiàn)一瞬間降頻（從2800MHz 降低到了 120 MHz）時(shí)間點(diǎn)和Redis慢查詢時(shí)間點(diǎn)一致。

圖片

電源故障開(kāi)始時(shí)間和機(jī)器出現(xiàn)異常慢查詢時(shí)間也是一致的。

3、后續(xù)優(yōu)化：

監(jiān)控單服務(wù)器慢查詢數(shù)量：基本上有多個(gè)集群都有慢查詢，機(jī)器可能就有問(wèn)題。
對(duì)于單路電源故障，之前絕對(duì)非高優(yōu)維修，后期需要對(duì)此磊故障增加優(yōu)先級(jí)。
添加對(duì)CPU頻率告警和提供秒級(jí)診斷工具能力。

二、服務(wù)器MCE造成Redis慢查詢

1、發(fā)現(xiàn)問(wèn)題：

某周末晚上，某業(yè)務(wù)在21:55可用性突然報(bào)警，從100%->98%，經(jīng)排查該分鐘該集群的全部實(shí)例出現(xiàn)慢日志(均為小命令)，并且集中在一臺(tái)機(jī)器。

實(shí)例	角色	耗時(shí)(微秒)	命令	value大小
10.xx.xx.xx:yy	master	20,421	incr small_key1	10字節(jié)
10.xx.xx.xx:yy	master	21,324	get small_key2	10字節(jié)

圖片

2、定位問(wèn)題：

(1) 快速定位：

快速定位為服務(wù)器問(wèn)題，因?yàn)橥瑱C(jī)器的其他Redis集群均出現(xiàn)上述情況。

機(jī)器問(wèn)題幾板斧：

分鐘級(jí)核心指標(biāo)：cpu、mem、網(wǎng)絡(luò)、io一通查，沒(méi)有異常。
硬件問(wèn)題：內(nèi)存、網(wǎng)卡、CPU、電源均正常。
系統(tǒng)日志：dmesg有異常日志，初步判斷MCE在做內(nèi)存故障糾錯(cuò)。

May 18 21:55:04 機(jī)器名 kernel: {2}[Hardware Error]: Hardware error from APEI Generic Hardware Error Source: 4
May 18 21:55:04 機(jī)器名 kernel: {2}[Hardware Error]: It has been corrected by h/w and requires no further action
May 18 21:55:04 機(jī)器名 kernel: {2}[Hardware Error]: event severity: corrected
May 18 21:55:04 機(jī)器名 kernel: {2}[Hardware Error]:  Error 0, type: corrected
May 18 21:55:04 機(jī)器名 kernel: {2}[Hardware Error]:  fru_text: A2
May 18 21:55:04 機(jī)器名 kernel: {2}[Hardware Error]:   section_type: memory error
May 18 21:55:04 機(jī)器名 kernel: {2}[Hardware Error]:   error_status: 0x0000000000000400
May 18 21:55:04 機(jī)器名 kernel: {2}[Hardware Error]:   physical_address: 0x00000009f7466ac0
May 18 21:55:04 機(jī)器名 kernel: {2}[Hardware Error]:   node: 0 card: 1 module: 0 rank: 0 bank: 0 row: 18297 column: 936
May 18 21:55:04 機(jī)器名 kernel: {2}[Hardware Error]:   error_type: 2, single-bit ECC
May 18 21:55:04 機(jī)器名 kernel: core: [Hardware Error]: Machine check events logged
May 18 21:55:04 機(jī)器名 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 機(jī)器名 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 機(jī)器名 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 機(jī)器名 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 機(jī)器名 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 機(jī)器名 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 機(jī)器名 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 機(jī)器名 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 機(jī)器名 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 機(jī)器名 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 機(jī)器名 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) 一些基礎(chǔ)知識(shí)(我也是臨時(shí)學(xué)的，如果不對(duì)歡迎來(lái)噴)

什么是MCE？

MCE全稱Machine check exception，英文解釋如下(論文：https://www.halobates.de/mce.pdf)，簡(jiǎn)單說(shuō)有硬件錯(cuò)誤，需要中斷當(dāng)前的進(jìn)程，調(diào)用一個(gè)專用的硬件異常處理handler進(jìn)行處理。

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什么時(shí)候觸發(fā)

通過(guò)修改/sys/devices/system/machinecheck/machinecheck0/check_interval 的值，可以調(diào)整錯(cuò)誤修復(fù)的初始和最大輪詢間隔。

硬件錯(cuò)誤分類

CE，可糾正錯(cuò)誤；（注意這里的CE和MCE也不是一個(gè)東西，corrected exception）
UE，不可糾正錯(cuò)誤，但系統(tǒng)沒(méi)有崩潰（通常進(jìn)程coredump，異常退出）；
Fatal，不可糾正錯(cuò)誤，系統(tǒng)崩潰。

從可用性角度看，似乎最應(yīng)該關(guān)注的是2，3類錯(cuò)誤，但實(shí)際上1類錯(cuò)誤更具有欺騙性，在分布式系統(tǒng)中，確定性要好過(guò)不確定性。

x86處理硬件故障的方式

PCIe AER 是PCIe的新特性，發(fā)生故障時(shí)，通過(guò)中斷報(bào)告故障詳情；
APEI，先通過(guò)SMI進(jìn)入BIOS/firmware，讓BIOS/firmware先處理，其根據(jù)處理情況決定要不要通知OS繼續(xù)處理；
BIOS/firmware 可以通過(guò)MCE中斷，讓OS繼續(xù)處理。

這里重點(diǎn)是SMI中斷（SMI中斷使CPU進(jìn)入SMM），它是Linux無(wú)法感知的，如果BIOS/firmware 處理錯(cuò)誤耗費(fèi)了太長(zhǎng)時(shí)間，可能導(dǎo)致延遲抖動(dòng)，沒(méi)有統(tǒng)一的方法從Linux測(cè)度量。而其它中斷是Linux處理的，其耗時(shí)Linux總是有辦法度量。

(3) 日志分析，幾個(gè)核心點(diǎn)：

CE Memory：可糾正的內(nèi)存錯(cuò)誤

May 18 21:55:04 機(jī)器名 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)

關(guān)鍵日志：

Machine check events logged

內(nèi)存錯(cuò)誤和內(nèi)存信息：

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

3、結(jié)論：

系統(tǒng)發(fā)生硬件錯(cuò)誤會(huì)導(dǎo)致機(jī)器進(jìn)入 MCE中斷，可能會(huì)將大部份內(nèi)核時(shí)間用于處理 MCE中斷(例如本例子CE Memory)。

三、THP造成

這個(gè)就是一個(gè)湊數(shù)的，很早之前遇到的，在《Redis開(kāi)發(fā)與運(yùn)維》一書也提過(guò)，原文如下：

圖片

四、其他案例

1、不可糾正硬件錯(cuò)誤：

Uncorrected hardware memory error ，導(dǎo)致Redis直接core。

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

2、CPU溫度過(guò)高，導(dǎo)致可能降頻：

(1) 日志：

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

(2) 基礎(chǔ)知識(shí)

關(guān)于CPU功耗管理，有以下幾種模式：

performance   運(yùn)行于最大頻率
    powersave     運(yùn)行于最小頻率
    userspace     運(yùn)行于用戶指定的頻率
    ondemand      按需快速動(dòng)態(tài)調(diào)整CPU頻率， 一有cpu計(jì)算量的任務(wù)，就會(huì)立即達(dá)到最                   大頻率運(yùn)行，空閑時(shí)間增加就降低頻率
    conservative  按需快速動(dòng)態(tài)調(diào)整CPU頻率， 比 ondemand 的調(diào)整更保守
    schedutil     基于調(diào)度程序調(diào)整 CPU 頻率

查看當(dāng)前支持模式：

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

查看當(dāng)前使用模式：

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

(3) 代碼分析：

內(nèi)核代碼：cpu溫度超過(guò)閾值會(huì)打印系統(tǒng)日志，但是是否降頻還和 /sys/devices/system/cpu/cpu0/cpufreq/scaling_governor模式有關(guān)。

圖片

五、總結(jié)：

責(zé)任編輯：武曉燕來(lái)源： Redis開(kāi)發(fā)運(yùn)維實(shí)戰(zhàn)

Redis 硬件優(yōu)化