Um deadlock de printk ocorre quando várias threads do kernel ficam bloqueadas, aguardando a liberação de locks umas das outras enquanto a função printk imprime mensagens de log. Esse deadlock impede o progresso do kernel e causa uma falha no sistema. Este tópico explica como identificar esse tipo de falha, entender sua causa raiz e aplicar uma solução alternativa.
Identificar a falha
Quando o sistema falha, um arquivo de dump chamado vmcore é gerado. Visualize os logs do kernel no arquivo vmcore, obtenha as informações de rastreamento de chamadas iniciadas com Call Trace: para analisar a causa e solucionar o problema.
Dois sintomas combinados indicam um deadlock de printk:
A saída do
dmesgcontém logs dewarningrelacionados a agendamento e workqueue.O rastreamento de chamadas de um processo afetado termina em funções de aquisição de spinlock — especificamente
_raw_spin_lock,queued_spin_lock_slowpathouraw_spin_rq_lock_netsted— alcançadas pela sequênciaprintk→console_unlock→ função de spinlock.
Exemplo de rastreamento de chamadas
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: 002bCausa raiz
O deadlock ocorre na seguinte sequência:
O kernel adquire o spinlock de uma workqueue ou fila de execução (rq).
Enquanto retém esse lock, o kernel chama
printkpara registrar uma mensagem.A função
printkchamaconsole_unlock, que invoca o driver subjacente do Direct Rendering Manager (DRM).O driver DRM tenta adquirir o mesmo spinlock da workqueue ou rq, já retido. O kernel trava e o deadlock causa uma falha.
Para obter detalhes sobre como o driver DRM adquire o lock, consulte o patch drm/fb-helper: Add fb_deferred_io support.
**Por que logs de warning aparecem no dmesg?**
A impressão de mensagens de log durante a retenção de um spinlock de workqueue ou rq aciona avisos de agendamento e workqueue. Esses avisos aparecem na saída do dmesg porque o próprio printk os emite como parte da sequência de deadlock.
**Por que a versão do kernel 5.10.134-16.3 é mais suscetível a esse problema?**
Na versão 5.10.134-16.3 do kernel do Alibaba Cloud Linux 3, um defeito de regressão no recurso de unthrottle assíncrono portado retroativamente aumenta significativamente a frequência de mensagens de log de warning de agendamento e workqueue. Logs de aviso mais frequentes elevam a probabilidade de ocorrência da sequência de deadlock.
Versões afetadas
O deadlock de printk foi introduzido pelo patch
drm/fb-helper: Add fb_deferred_io supportno Linux 4.10.Esse problema afeta as versões
4.19e5.10do kernel do Alibaba Cloud Linux.A probabilidade de ocorrência é alta na versão
5.10.134-16.3do kernel do Alibaba Cloud Linux 3.
Solução
Reduza o console_loglevel para que o printk pare de enviar logs de warning para a porta serial. Isso interrompe a condição de gatilho do deadlock.
Benefício: O deadlock deixa de ocorrer porque as mensagens de nível warning são suprimidas na porta serial.
Limitação: Os logs de warning não aparecem mais na porta serial. Os logs do kernel impressos pelo dmesg não são afetados e permanecem disponíveis para análise pós-falha.
Se o seu sistema de journal capturar logs da porta serial em vez do
dmesg, suprimir logs dewarningna porta serial significa que esses logs não aparecerão no seu journal. Revise sua configuração de logging antes de aplicar essa alteração em produção.Essa alteração não afeta os logs de
warningno buffer circular do kernel — a saída dodmesgpermanece inalterada.
Aplicar a correção
Execute o comando a seguir para definir o console_loglevel como 4 e persistir a alteração entre reinicializações:
sysctl -w kernel.printk="4 4 1 7" >> /etc/sysctl.confPara usar um valor diferente, substitua os parâmetros:
sysctl -w kernel.printk="<console_loglevel> <default_message_loglevel> <minimum_console_loglevel> <default_console_loglevel>" >> /etc/sysctl.confO parâmetro kernel.printk aceita quatro valores nesta ordem:
|
Posição |
Parâmetro |
Descrição |
|
1 |
|
A função printk imprime na porta serial logs cujos níveis são superiores a este valor. |
|
2 |
|
Nível de log padrão aplicado quando uma mensagem não possui nível explícito. |
|
3 |
|
Valor mínimo permitido para |
|
4 |
|
Valor padrão para |
O Linux define oito níveis de log. Um número menor indica maior prioridade.
#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 */Defina <console_loglevel> como 4 ou inferior para impedir que logs de warning cheguem à porta serial.