printkのデッドロックが原因でAlibaba Cloud Linuxでダウンタイムの問題が発生した場合はどうすればよいですか。 - Alibaba Cloud Linux

printkデッドロックとは、Linuxカーネルのprintk関数を呼び出してログを印刷するときに、システム内の複数のスレッドが互いにリソースを解放するのを待ち、続行できない状況を指します。 printkデッドロックは、システムアプリケーションおよびサービスの動作に悪影響を及ぼし、カーネルのダウンタイムを引き起こす。したがって、システムの安定性と信頼性を確保するには、最も早い機会にprintkデッドロックを防止および解決することが重要です。このトピックでは、printkデッドロックが原因でAlibaba Cloud Linuxでダウンタイムの問題が発生する理由と、問題を解決する方法について説明します。

問題の説明

Alibaba Cloud Linuxオペレーティングシステムのカーネルでダウンタイムの問題が発生した場合、vmcoreファイルを分析すると、次のような症状が現れます。

説明

ダウンタイムの問題が発生すると、vmcoreという名前のダンプファイルが生成されます。 vmcoreファイル内のカーネルログを表示し、"Call Trace:" で始まるコールトレース情報を取得して原因を分析し、問題のトラブルシューティングを行うことができます。

dmesgコマンドの実行後に表示されるカーネルログには、スケジューリングとwork_queueに関連する警告ログが含まれています。

特定のプロセスのコールトレース情報には、次の特性があります。

最後に呼び出された関数は、_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メカニズムが使用されているときに発生するデッドロックによって発生します。 printkデッドロックは発生する可能性は低いですが、Alibaba Cloud Linux 3のカーネルバージョン5.10.134-16.3で発生する可能性があります。

なぜprintkデッドロックが発生するのですか?
カーネルがwork_queueまたはrunqueue (rq) のスピンロックを保持した後にprintk関数を呼び出してカーネルログを印刷する場合、printkは基盤となるDirect Rendering Manager (DRM) ドライバを呼び出してwork_queueまたはrqを再度ロックしようとします。その結果、システムのダウンタイム問題を引き起こすprintkデッドロックが発生します。
説明
DRMドライバがオブジェクトをロックしようとする方法については、drm/fb-helper: Add fb_deferred_io supportパッチを参照してください。
スケジューリングとwork_queueに関連する警告ログが表示されるのはなぜですか。
カーネルがwork_queueまたはrqのスピンロックを保持し、printk関数を呼び出してログを印刷すると、printkはスケジューリングとwork_queueに関する警告メッセージをカーネルログに印刷します。このため、demesgコマンドの出力には、スケジューリングとwork_queueの警告ログが含まれています。
Alibaba Cloud Linux 3のカーネルバージョン5.10.134-16.3がprintkデッドロックの確率が高いのはなぜですか。
スケジューリングとwork_queueの警告ログは、いくつかのシナリオでのみ出力されます。 Alibaba Cloud Linux 3のカーネルバージョン5.10.134-16.3では、Linuxコミュニティからバックポートされる非同期スロットル解除機能に回帰欠陥があります。この欠陥により、警告ログが印刷される可能性が高まり、Alibaba Cloud Linux 3でprinttkデッドロックが発生する可能性が高くなります。

影響を受けるバージョン

printkデッドロックは、LinuxコミュニティによってリリースされたLinux 4.10のdrm/fb-helper: Add fb_deferred_io support patchで発生する既知の問題です。
問題は、Alibaba Cloud Linuxのカーネルバージョン4.19および5.10に存在します。
Alibaba Cloud Linux 3のカーネルバージョン5.10.134-16.3では、この問題の可能性が高くなります。

解決策

次のコマンドを実行してログレベルを変更し、printk関数が警告ログをシリアルポートに印刷しないようにします。

重要

ジャーナルシステムがシリアルポートでログをキャプチャするが、dmesgコマンドを実行して印刷されたカーネルログはキャプチャしない場合は、ログレベルを変更する際に注意してください。
ログレベルを変更すると、シリアルポートの警告ログが失われますが、dmesgコマンドを使用して出力されるカーネルログの警告ログには影響しません。

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

kernel.printkパラメーターの有効値:

console_loglevel: ログレベルを指定します。 printk関数は、指定されたログレベルよりも高いログレベルを持つログをシリアルポートに出力します。
default_message_loglevel: デフォルトのログレベルを指定します。ログレベルが指定されていない場合、デフォルトレベルのログを印刷するためにprintk関数が呼び出されます。
minimum_console_loglevel: console_loglevelパラメーターの最小値を指定します。
default_console_loglevel: console_loglevelパラメーターのデフォルト値を指定します。

Linuxは、カーネルログの8つのログレベルを定義します。より低いログレベルは、より高い優先度を示す。 警告ログがシリアルポートに出力されないようにするには、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 */