Alibaba Cloud Linux系統出現printk死結導致系統宕機 - Alibaba Cloud Linux

printk死結是指在使用Linux核心中的printk函數列印日誌時，由於某種原因導致系統中兩個或多個線程相互等待對方釋放資源而無法繼續執行的情況。printk死結會影響系統應用程式和業務的正常運行，最終觸發核心宕機，所以預防和及時解決printk死結對於維持系統穩定性和可靠性至關重要。本文介紹Alibaba Cloud Linux系統出現printk死結導致系統宕機的原因及解決方案。

問題描述

在使用Alibaba Cloud Linux發生核心宕機時，分析vmcore檔案存在以下現象：

說明

當系統發生宕機時，會產生轉儲檔案vmcore，您可以通過查看該檔案擷取宕機時的核心日誌，並根據其中的calltrace資訊（通常以"Call Trace:"開頭）來定位問題的發生位置，分析宕機原因，從而進行修複和調試。

核心日誌（dmesg）存在一些warning層級的列印日誌，通常與調度（scheduling）、工作隊列（work_queue）有關。

分析vmcore檔案會發現某個進程的calltrace資訊有如下特徵：

最近的函數是關於擷取自旋鎖的調用，比如_raw_spin_lock、queued_spin_lock_slowpath、raw_spin_rq_lock_netsted等。
函數調用路徑是從printk到console_unlock，再到上述擷取自旋鎖的調用。

calltrace資訊樣本

PID: 99675  TASK: ffff8901818acf80  CPU: 116  COMMAND: "kubelet"
 #0 [fffffe0001ac9e50] crash_nmi_callback at ffffffff81055acb
 #1 [fffffe0001ac9e58] nmi_handle at ffffffff81024892
 #2 [fffffe0001ac9ea0] default_do_nmi at ffffffff81a358d2
 #3 [fffffe0001ac9ec8] exc_nmi at ffffffff81a35adf
 #4 [fffffe0001ac9ef0] end_repeat_nmi at ffffffff81c013eb
    [exception RIP: native_queued_spin_lock_slowpath+65]
    RIP: ffffffff810ff9b1  RSP: ffffc9001da977d8  RFLAGS: 00000002
    RAX: 00000000005c0101  RBX: ffff897e7fb00000  RCX: ffff897e7fb38705
    RDX: 0000000000000000  RSI: 0000000000000000  RDI: ffff897e7fb33600
    RBP: ffff8901efa38000   R8: 0000000000000074   R9: ffff897e7fb32f20
    R10: 0000000000000000  R11: 0000000000000000  R12: 0000000000000000
    R13: 0000000000000002  R14: ffff8901efa38b44  R15: ffff897e7fb33600
    ORIG_RAX: ffffffffffffffff  CS: 0010  SS: 0000
--- <NMI exception stack> ---
 #5 [ffffc9001da977d8] native_queued_spin_lock_slowpath at ffffffff810ff9b1
 #6 [ffffc9001da977d8] _raw_spin_lock at ffffffff81a435ea
 #7 [ffffc9001da977e0] try_to_wake_up at ffffffff810cf3e3
 #8 [ffffc9001da97840] __queue_work at ffffffff810b643f
 #9 [ffffc9001da97888] queue_work_on at ffffffff810b65cc
#10 [ffffc9001da97898] soft_cursor at ffffffff815c1b51
#11 [ffffc9001da978f0] bit_cursor at ffffffff815c1718
#12 [ffffc9001da979c0] hide_cursor at ffffffff816591d4
#13 [ffffc9001da979d0] vt_console_print at ffffffff81659fea
#14 [ffffc9001da97a38] call_console_drivers.constprop.0 at ffffffff81109a32
#15 [ffffc9001da97a60] console_unlock at ffffffff8110a04d
#16 [ffffc9001da97b18] vprintk_emit at ffffffff8110be14
#17 [ffffc9001da97b58] printk at ffffffff819f1053
#18 [ffffc9001da97bb8] show_fault_oops.cold at ffffffff819e9b6b
#19 [ffffc9001da97c10] no_context at ffffffff810714bb
#20 [ffffc9001da97c48] exc_page_fault at ffffffff81a37628
#21 [ffffc9001da97c70] asm_exc_page_fault at ffffffff81c00ace
#22 [ffffc9001da97cf8] __update_load_avg_cfs_rq at ffffffff810f25ee
#23 [ffffc9001da97d60] update_load_avg at ffffffff810d8e7a
#24 [ffffc9001da97d98] task_tick_fair at ffffffff810daeed
#25 [ffffc9001da97dd0] scheduler_tick at ffffffff810ceb9c
#26 [ffffc9001da97df8] update_process_times at ffffffff81132d30
#27 [ffffc9001da97e10] tick_sched_handle at ffffffff81144082
#28 [ffffc9001da97e28] tick_sched_timer at ffffffff81144503
#29 [ffffc9001da97e48] __run_hrtimer at ffffffff81133bbc
#30 [ffffc9001da97e80] __hrtimer_run_queues at ffffffff81133d6d
#31 [ffffc9001da97ec0] hrtimer_interrupt at ffffffff81134250
#32 [ffffc9001da97f20] __sysvec_apic_timer_interrupt at ffffffff81059b51
#33 [ffffc9001da97f38] sysvec_apic_timer_interrupt at ffffffff81a36e01
#34 [ffffc9001da97f50] asm_sysvec_apic_timer_interrupt at ffffffff81c00cc2
    RIP: 0000000000429e3a  RSP: 00007f2e29ffad48  RFLAGS: 00000202
    RAX: 00c00352b0000010  RBX: 00000000075c1048  RCX: 000000c003827800
    RDX: 00c00396e8000003  RSI: 0000000000000000  RDI: 0000000000000002
    RBP: 00007f2e29ffada0   R8: 7ffffffffffb3a07   R9: 0000000000000000
    R10: 000000c000091e98  R11: 0000000000000340  R12: 0000000000000000
    R13: 0000000000000e96  R14: 0000000000000000  R15: 0000000000000000
    ORIG_RAX: ffffffffffffffff  CS: 0033  SS: 002b

問題原因

系統宕機是由Linux社區的printk機制長期存在死結的問題導致的，且是已知問題，該問題出現機率較低，但在Alibaba Cloud Linux 3的5.10.134-16.3核心版本出現該問題的機率偏高。

為什麼會出現printk死結？
核心在持有work_queue（工作隊列）或runqueue（運行隊列，簡稱rq）的自旋鎖後，如果調用printk函數列印核心日誌，printk的底層實現會去調用drm驅動程式，而drm驅動程式由於自身的實現原因又會去嘗試對work_queue或rq進行加鎖，導致printk死結，最終導致系統宕機。
說明
drm驅動嘗試加鎖的詳細資料，請參考drm/fb-helper: Add fb_deferred_io support補丁。
為什麼調度（scheduling）和工作隊列（work_queue）會出現warning日誌？
由於核心持有work_queue或rq的自旋鎖並使用printk函數列印日誌的情境，又通常發生在調度（scheduling）和工作隊列（work_queue）實現代碼的warning路徑上，所以可以觀察到核心的dmesg資訊中出現調度（scheduling）和工作隊列（work_queue）相關的警示資訊。
為什麼Alibaba Cloud Linux 3的5.10.134-16.3核心版本出現該問題的機率偏高？
事實上，調度（scheduling）和工作隊列（work_queue）列印warning日誌的情況並不多，但是在Alibaba Cloud Linux 3的5.10.134-16.3核心版本中，從Linux上遊社區回合的非同步unthrottle特性存在迴歸缺陷，增大了觸發列印warning日誌的機率，從而導致Alibaba Cloud Linux 3中出現該問題的機率偏高。

影響範圍

該問題目前是Linux社區共性問題，且觸發該問題的補丁drm/fb-helper: Add fb_deferred_io support是在Linux上遊社區的v4.10版本引入。
在Alibaba Cloud Linux的4.19和5.10核心版本存在該問題。
在Alibaba Cloud Linux 3的5.10.134-16.3核心版本中出現該問題的機率更高。

解決方案

當您發現此類問題時，可以通過以下命令調整printk的列印等級，阻止warning層級的日誌列印到串口的方式避開該問題。

重要

如果您的日誌系統是依賴捕獲串口輸出而非核心日誌（dmesg）資訊，請謹慎評估後使用。
該方法會導致串口中的warning日誌缺失，但不會影響核心日誌（dmesg）中的warning日誌。

sysctl -w kernel.printk="<console_loglevel> <default_message_loglevel> <minimum_console_loglevel> <default_console_loglevel>" >> /etc/sysctl.conf

其中kernel.printk的四個值說明如下：

console_loglevel：表示高於（不含）此優先順序的資訊會被列印至串口。
default_message_loglevel：如果在printk時未指定列印等級，則預設使用該等級。
minimum_console_loglevel：表示console_loglevel可以被設定的最小值。
default_console_loglevel：表示console_loglevel的預設值。

由於Linux將核心的日誌列印等級分為8個，等級越低，優先順序越高。因此需要阻止warning層級的日誌列印到串口，則console_loglevel最大設定為4才合理。命令樣本如下：

sysctl -w kernel.printk="4 4 1 7" >> /etc/sysctl.conf

說明

日誌列印等級說明：

#define LOGLEVEL_EMERG		0	/* system is unusable */
#define LOGLEVEL_ALERT		1	/* action must be taken immediately */
#define LOGLEVEL_CRIT		2	/* critical conditions */
#define LOGLEVEL_ERR		3	/* error conditions */
#define LOGLEVEL_WARNING	4	/* warning conditions */
#define LOGLEVEL_NOTICE		5	/* normal but significant condition */
#define LOGLEVEL_INFO		6	/* informational */
#define LOGLEVEL_DEBUG		7	/* debug-level messages */