Apa yang harus saya lakukan jika terjadi masalah downtime di Alibaba Cloud Linux karena deadlock printk? - Alibaba Cloud Linux

Deadlock printk mengacu pada situasi di mana beberapa thread dalam sistem menunggu satu sama lain untuk melepaskan sumber daya dan tidak dapat melanjutkan ketika fungsi printk di kernel Linux dipanggil untuk mencetak log. Deadlock printk secara negatif memengaruhi operasi aplikasi dan layanan sistem serta menyebabkan downtime kernel. Oleh karena itu, pencegahan dan penyelesaian deadlock printk secepat mungkin sangat penting untuk memastikan stabilitas dan keandalan sistem. Topik ini menjelaskan penyebab masalah downtime di Alibaba Cloud Linux akibat deadlock printk dan cara menyelesaikannya.

Deskripsi masalah

Ketika masalah downtime terjadi di kernel sistem operasi Alibaba Cloud Linux, analisis file vmcore mengungkapkan gejala berikut:

Catatan

Ketika masalah downtime terjadi, file dump bernama vmcore dibuat. Anda dapat melihat log kernel di file vmcore, memperoleh informasi calltrace yang dimulai dengan "Call Trace:" untuk menganalisis penyebabnya, dan kemudian menyelesaikan masalah.

Log kernel yang ditampilkan setelah perintah dmesg dijalankan berisi log peringatan yang terkait dengan penjadwalan dan work_queue.

Informasi calltrace dari proses tertentu memiliki karakteristik berikut:

Fungsi-fungsi yang terakhir dipanggil bertujuan untuk mendapatkan spinlock, seperti fungsi _raw_spin_lock, queued_spin_lock_slowpath, dan raw_spin_rq_lock_netsted.
Sistem memanggil fungsi printk, fungsi console_unlock, dan fungsi-fungsi sebelumnya yang mendapatkan spinlock secara berurutan.

Contoh Informasi 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

Penyebab

Masalah ini disebabkan oleh deadlock yang terjadi saat mekanisme printk dari komunitas Linux digunakan. Deadlock printk jarang terjadi, tetapi mungkin terjadi di versi kernel 5.10.134-16.3 dari Alibaba Cloud Linux 3.

Mengapa deadlock printk terjadi?
Jika fungsi printk dipanggil untuk mencetak log kernel setelah kernel memegang spinlock work_queue atau runqueue (rq), printk memanggil driver Direct Rendering Manager (DRM) tingkat rendah untuk mencoba mengunci work_queue atau rq lagi. Akibatnya, deadlock printk terjadi, yang menyebabkan masalah downtime sistem.
Catatan
Untuk informasi tentang bagaimana driver DRM mencoba mengunci objek, lihat patch drm/fb-helper: Add fb_deferred_io support.
Mengapa log peringatan terkait penjadwalan dan work_queue muncul?
Ketika kernel memegang spinlock work_queue atau rq dan memanggil fungsi printk untuk mencetak log, printk mencetak pesan peringatan tentang penjadwalan dan work_queue ke log kernel. Inilah alasan mengapa output perintah demesg berisi log peringatan untuk penjadwalan dan work_queue.
Mengapa versi kernel 5.10.134-16.3 dari Alibaba Cloud Linux 3 memiliki probabilitas deadlock printk yang lebih tinggi?
Log peringatan untuk penjadwalan dan work_queue hanya dicetak dalam beberapa skenario. Di versi kernel 5.10.134-16.3 dari Alibaba Cloud Linux 3, fitur asynchronous unthrottle yang di-backport dari komunitas Linux memiliki cacat regresi. Cacat ini meningkatkan probabilitas pencetakan log peringatan dan menghasilkan probabilitas tinggi deadlock printk di Alibaba Cloud Linux 3.

Versi yang terpengaruh

Deadlock printk adalah masalah yang dikenal diperkenalkan dalam patch drm/fb-helper: Add fb_deferred_io support di Linux 4.10 yang dirilis oleh komunitas Linux.
Masalah ini ada di versi kernel 4.19 dan 5.10 dari Alibaba Cloud Linux.
Probabilitas masalah ini tinggi di versi kernel 5.10.134-16.3 dari Alibaba Cloud Linux 3.

Solusi

Jalankan perintah berikut untuk mengubah level log guna mencegah fungsi printk mencetak log peringatan ke port serial.

Penting

Jika sistem jurnal Anda menangkap log di port serial tetapi tidak menangkap log kernel yang dicetak dengan menjalankan perintah dmesg, berhati-hatilah saat Anda mengubah level log.
Perubahan level log menyebabkan log peringatan di port serial hilang, tetapi tidak memengaruhi log peringatan di log kernel yang dicetak dengan menggunakan perintah dmesg.

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

Nilai valid parameter kernel.printk:

console_loglevel: menentukan level log. Fungsi printk mencetak log yang level lognya lebih tinggi dari level log yang ditentukan di port serial.
default_message_loglevel: menentukan level log default. Jika tidak ada level log yang ditentukan, fungsi printk dipanggil untuk mencetak log level default.
minimum_console_loglevel: menentukan nilai minimum parameter console_loglevel.
default_console_loglevel: menentukan nilai default parameter console_loglevel.

Linux mendefinisikan delapan level log dari log kernel. Level log yang lebih rendah menunjukkan prioritas yang lebih tinggi. Untuk mencegah log peringatan dicetak di port serial, kami sarankan Anda mengatur parameter console_loglevel ke nilai kurang dari atau sama dengan 4. Contoh perintah:

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

Catatan

Level log berikut tersedia:

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