Linux Kernel: カーネルモードで CPU 掴んでるタスクのバックトレースをとりたい

Linux

表題の通りなのだが、結論からいうと sysrq-trigger を使うのがいいみたい

「特定のタスクがクリティカルセクションを実行していてボトルネックとなっているが、どのタスクなのか分からない」という事象を正確に観測したくて、このテーマで調べました

カーネルモードで CPU 掴んでるタスクを作る

まず実験用にカーネルモジュールをこしらえた

github.com

debugfs 上のファイルを read(2) したタスクが spinlock を掴んだまま無限ループに突入する、という単にバグってるカーネルモジュールになる. これでカーネルモードで刺さっているタスクを擬似的に再現する

実験

上記のカーネルモジュールをインストールすると /sys/kernel/debug/foreverspin が生えるので、これを cat する

vagrant@bionic:/ $ sudo cat /sys/kernel/debug/foreverspin

cat プロセスがカーネルモードで CPU を掴みっぱなしになり、 %system CPU がグンっと上がる

f:id:hiboma:20191108124701p:plain

このプロセスを観察してみましょう

/proc/$pid/stack を見てみる

この状態で /proc/$pid/stack を見ても バックトレースは採取できない

vagrant@bionic:/ $ sudo cat /proc/$( pgrep cat )/stack
[<0>] entry_SYSCALL_64_after_hwframe+0x3d/0xa2
[<0>] 0xffffffffffffffff

無念!!!1

strace

strace でトレースしても何もトレースできないし、Ctrl + C による SIGINT シグナルもブロックされる ( これはシステムコール実行中にシグナルをブロックするという strace の挙動かな ? )

vagrant@bionic:/ $ sudo strace -p $(pgrep cat)
strace: Process 2182 attached
^C^C^C

システムコール呼んでないですしね。何にもとれないですよね。ユーザランドのトレースツールだもんね

無念!!!

echo l > /proc/sysrq-trigger

sysrq-trigger でバックトレースを採取する. wikipedia にちょうどいい解説が載っています

ja.wikipedia.org

設定を有効にして

root@bionic:~# sysctl kernel.sysrq=1
kernel.sysrq = 1

えいっ

root@bionic:~# echo l > /proc/sysrq-trigger

dmesg に以下のようなログが出るはずです

[Thu Nov  7 08:15:34 2019] sysrq: SysRq : Show backtrace of all active CPUs
[Thu Nov  7 08:15:34 2019] NMI backtrace for cpu 3
[Thu Nov  7 08:15:34 2019] CPU: 3 PID: 1846 Comm: bash Tainted: G           OE    4.15.0-29-generic #31-Ubuntu
[Thu Nov  7 08:15:34 2019] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006
[Thu Nov  7 08:15:34 2019] Call Trace:
[Thu Nov  7 08:15:34 2019]  dump_stack+0x63/0x8b
[Thu Nov  7 08:15:34 2019]  nmi_cpu_backtrace+0xca/0xd0
[Thu Nov  7 08:15:34 2019]  ? lapic_can_unplug_cpu+0xb0/0xb0
[Thu Nov  7 08:15:34 2019]  nmi_trigger_cpumask_backtrace+0xe6/0x130
[Thu Nov  7 08:15:34 2019]  arch_trigger_cpumask_backtrace+0x19/0x20
[Thu Nov  7 08:15:34 2019]  sysrq_handle_showallcpus+0x17/0x20
[Thu Nov  7 08:15:34 2019]  __handle_sysrq+0x9f/0x170
[Thu Nov  7 08:15:34 2019]  write_sysrq_trigger+0x34/0x40
[Thu Nov  7 08:15:34 2019]  proc_reg_write+0x45/0x70
[Thu Nov  7 08:15:34 2019]  __vfs_write+0x1b/0x40
[Thu Nov  7 08:15:34 2019]  vfs_write+0xb1/0x1a0
[Thu Nov  7 08:15:34 2019]  SyS_write+0x55/0xc0
[Thu Nov  7 08:15:34 2019]  do_syscall_64+0x73/0x130
[Thu Nov  7 08:15:34 2019]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
[Thu Nov  7 08:15:34 2019] RIP: 0033:0x7f14c47b7154
[Thu Nov  7 08:15:34 2019] RSP: 002b:00007ffffe191ff8 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[Thu Nov  7 08:15:34 2019] RAX: ffffffffffffffda RBX: 0000000000000002 RCX: 00007f14c47b7154
[Thu Nov  7 08:15:34 2019] RDX: 0000000000000002 RSI: 0000558e776dc940 RDI: 0000000000000001
[Thu Nov  7 08:15:34 2019] RBP: 0000558e776dc940 R08: 000000000000000a R09: 0000000000000001
[Thu Nov  7 08:15:34 2019] R10: 000000000000000a R11: 0000000000000246 R12: 00007f14c4a93760
[Thu Nov  7 08:15:34 2019] R13: 0000000000000002 R14: 00007f14c4a8f2a0 R15: 00007f14c4a8e760
[Thu Nov  7 08:15:34 2019] Sending NMI from CPU 3 to CPUs 0-2:
[Thu Nov  7 08:15:34 2019] NMI backtrace for cpu 0
[Thu Nov  7 08:15:34 2019] CPU: 0 PID: 1872 Comm: cat Tainted: G           OE    4.15.0-29-generic #31-Ubuntu
[Thu Nov  7 08:15:34 2019] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006
[Thu Nov  7 08:15:34 2019] RIP: 🔥 0010:debugfs_foreverspin_read+0x15/0x17 [foreverspin] 
[Thu Nov  7 08:15:34 2019] RSP: 0018:ffffa7b9c11ffe58 EFLAGS: 00000246
[Thu Nov  7 08:15:34 2019] RAX: 0000000000000000 RBX: 0000000000000000 RCX: ffffa7b9c11ffef8
[Thu Nov  7 08:15:34 2019] RDX: 0000000000000001 RSI: 00007efc03883000 RDI: ffffffffc0948448
[Thu Nov  7 08:15:34 2019] RBP: ffffa7b9c11ffe58 R08: ffff92d344a69100 R09: 0000000000000000
[Thu Nov  7 08:15:34 2019] R10: 0000000000000000 R11: 0000000000000000 R12: ffff92d346ca2f00
[Thu Nov  7 08:15:34 2019] R13: ffff92d34351f100 R14: 0000000000020000 R15: ffffa7b9c11ffef8
[Thu Nov  7 08:15:34 2019] FS:  00007efc038a5540(0000) GS:ffff92d353c00000(0000) knlGS:0000000000000000
[Thu Nov  7 08:15:34 2019] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[Thu Nov  7 08:15:34 2019] CR2: 00007efc03882000 CR3: 0000000207b3a006 CR4: 00000000000606f0
[Thu Nov  7 08:15:34 2019] Call Trace:
[Thu Nov  7 08:15:34 2019]  full_proxy_read+0x5c/0x90 👈
[Thu Nov  7 08:15:34 2019]  __vfs_read+0x1b/0x40 👈
[Thu Nov  7 08:15:34 2019]  vfs_read+0x8e/0x130 👈
[Thu Nov  7 08:15:34 2019]  SyS_read+0x55/0xc0 👈
[Thu Nov  7 08:15:34 2019]  do_syscall_64+0x73/0x130 👈
[Thu Nov  7 08:15:34 2019]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2 👈
[Thu Nov  7 08:15:34 2019] RIP: 0033:0x7efc033aa081
[Thu Nov  7 08:15:34 2019] RSP: 002b:00007ffdd251fe78 EFLAGS: 00000246 ORIG_RAX: 0000000000000000
[Thu Nov  7 08:15:34 2019] RAX: ffffffffffffffda RBX: 0000000000020000 RCX: 00007efc033aa081
[Thu Nov  7 08:15:34 2019] RDX: 0000000000020000 RSI: 00007efc03883000 RDI: 0000000000000003
[Thu Nov  7 08:15:34 2019] RBP: 0000000000020000 R08: 00000000ffffffff R09: 0000000000000000
[Thu Nov  7 08:15:34 2019] R10: 0000000000000022 R11: 0000000000000246 R12: 00007efc03883000
[Thu Nov  7 08:15:34 2019] R13: 0000000000000003 R14: 00007efc0388300f R15: 0000000000020000
[Thu Nov  7 08:15:34 2019] Code: <eb> fe 55 48 8b 3d 21 24 00 00 48 89 e5 e8 69 ce 05 dd 5d c3 00 00 
[Thu Nov  7 08:15:34 2019] NMI backtrace for cpu 1 skipped: idling at native_safe_halt+0x6/0x10
[Thu Nov  7 08:15:34 2019] NMI backtrace for cpu 2 skipped: idling at native_safe_halt+0x6/0x10

👈 で確認できますね! やったー

まとめ

  • Proof of Cocenprt は達成できたかな
  • リアルな障害の調査に役立てたい
  • どうも NMI で割り込んでバックとレースを取っているっぽいけど、どういう仕組みなのかはまた別の機会に調べます