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 */