系統(tǒng)和硬件故障導(dǎo)致的三次Redis“詭異”慢查詢
一、服務(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)維》一書(shū)也提過(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é):
本文粗淺分析了在Redis使用過(guò)程中遇到的詭異慢查詢問(wèn)題,其中包含了硬件故障相關(guān),系統(tǒng)參數(shù)錯(cuò)誤優(yōu)化等問(wèn)題,當(dāng)然實(shí)際在使用和運(yùn)維過(guò)程中可能還有其他詭異情況,需要具體問(wèn)題具體分析。