What do I do if a downtime issue occurs in Alibaba Cloud Linux due to a printk deadlock? - Alibaba Cloud Linux

A printk deadlock occurs when multiple kernel threads stall waiting for each other to release locks while the printk function is printing log messages. The deadlock prevents the kernel from making progress and causes a system crash. This topic explains how to identify this crash type, understand its root cause, and apply a workaround.

Identify the crash

When the system crashes, a dump file named vmcore is generated. You can view kernel logs in the vmcore file, obtain the call trace information that starts with Call Trace: to analyze the cause, and then troubleshoot the issue.

Two symptoms together indicate a printk deadlock:

The dmesg output contains warning logs related to scheduling and workqueue.
The call trace of an affected process ends in spinlock-acquisition functions — specifically _raw_spin_lock, queued_spin_lock_slowpath, or raw_spin_rq_lock_netsted — reached through the sequence printk → console_unlock → spinlock function.

Sample call trace

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

Root cause

The deadlock occurs through the following sequence:

The kernel acquires the spinlock of a workqueue or run queue (rq).
While holding that lock, the kernel calls printk to log a message.
printk calls console_unlock, which invokes the underlying Direct Rendering Manager (DRM) driver.
The DRM driver attempts to acquire the same workqueue or rq spinlock — which is already held. The kernel stalls, and the deadlock causes a crash.

For details on how the DRM driver acquires the lock, see the drm/fb-helper: Add fb_deferred_io support patch.

Why do warning logs appear in dmesg?

Printing log messages while holding a workqueue or rq spinlock triggers scheduling and workqueue warning messages. These warnings appear in dmesg output because printk itself emits them as part of the deadlock sequence.

Why is kernel version 5.10.134-16.3 more prone to this issue?

In kernel version 5.10.134-16.3 of Alibaba Cloud Linux 3, a regression defect in the backported asynchronous unthrottle feature significantly increases the frequency of scheduling and workqueue warning log messages. More frequent warning logs mean more opportunities for the deadlock sequence to occur.

Affected versions

The printk deadlock was introduced by the drm/fb-helper: Add fb_deferred_io support patch in Linux 4.10.
The issue affects kernel versions 4.19 and 5.10 of Alibaba Cloud Linux.
The probability of the issue is high in kernel version 5.10.134-16.3 of Alibaba Cloud Linux 3.

Solution

Lower the console_loglevel so that printk stops sending warning logs to the serial port. This breaks the trigger condition for the deadlock.

What you gain: The deadlock no longer occurs because warning-level messages are suppressed on the serial port.

What you lose: warning logs no longer appear on the serial port. Kernel logs printed by dmesg are not affected — those remain available for post-crash analysis.

Important

If your journal system captures logs from the serial port rather than from dmesg, suppressing warning logs on the serial port means those logs will not appear in your journal. Review your logging setup before applying this change in production.
This change does not affect warning logs in the kernel ring buffer — dmesg output is unchanged.

Apply the fix

Run the following command to set console_loglevel to 4 and persist the change across reboots:

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

To use a different value, replace the parameters:

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

The kernel.printk parameter accepts four values in order:

Position	Parameter	Description
1	`console_loglevel`	The printk function prints logs whose log levels are higher than this value to the serial port.
2	`default_message_loglevel`	Default log level applied when a message has no explicit level.
3	`minimum_console_loglevel`	Minimum allowed value for `console_loglevel`.
4	`default_console_loglevel`	Default value for `console_loglevel` at boot.

Linux defines eight log levels. A lower number means higher priority.

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

Set <console_loglevel> to 4 or lower to prevent warning logs from reaching the serial port.