11/2(土) 〜11/4(月) で松本に二泊三日して、あちこちの山を走ってきた。その1日目
小渕沢から霧ヶ峰にのぼって松本まで走った. 山梨・長野は秋も最高だ
走行距離 97km 獲得標高 1668m
続きを読むcgroup v1 の memory コントローラーで memory.kmem.limit_in_bytes
を制限すると slab_out_of_memory を起こすことができるので、それを調べたり観察したエントリです
不具合・バグの調査ではないです
ソースやコマンドの結果を大量に貼り付けているので めんどうな人は流し読みしてください
vagrant@bionic:~$ uname -a Linux bionic 4.15.0-66-generic #75-Ubuntu SMP Tue Oct 1 05:24:09 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux
root@bionic:~# echo $$ > /sys/fs/cgroup/memory/000/tasks root@bionic:~# echo 100M > /sys/fs/cgroup/memory/000/memory.kmem.limit_in_bytes
memory.kmem.limit_in_bytes に制限を課したプロセスで、存在しないパスに stat(2) を呼び出しをして negative dentry (slab) を大量に生成します
# # https://hiboma.hatenadiary.jp/entry/20140212/1392131530 # root@bionic:~# perl -e 'stat "/$_" for 1..10000000' ^C続きを読む
表題の通りなのだが、結論からいうと sysrq-trigger を使うのがいいみたい
「特定のタスクがクリティカルセクションを実行していてボトルネックとなっているが、どのタスクなのか分からない」という事象を正確に観測したくて、このテーマで調べました
まず実験用にカーネルモジュールをこしらえた
debugfs 上のファイルを read(2) したタスクが spinlock を掴んだまま無限ループに突入する、という単にバグってるカーネルモジュールになる. これでカーネルモードで刺さっているタスクを擬似的に再現する
上記のカーネルモジュールをインストールすると /sys/kernel/debug/foreverspin
が生えるので、これを cat する
vagrant@bionic:/ $ sudo cat /sys/kernel/debug/foreverspin
cat プロセスがカーネルモードで CPU を掴みっぱなしになり、 %system CPU がグンっと上がる
このプロセスを観察してみましょう
この状態で /proc/$pid/stack
を見ても バックトレースは採取できない
vagrant@bionic:/ $ sudo cat /proc/$( pgrep cat )/stack [<0>] entry_SYSCALL_64_after_hwframe+0x3d/0xa2 [<0>] 0xffffffffffffffff
無念!!!1
strace でトレースしても何もトレースできないし、Ctrl + C による SIGINT シグナルもブロックされる ( これはシステムコール実行中にシグナルをブロックするという strace の挙動かな ? )
vagrant@bionic:/ $ sudo strace -p $(pgrep cat) strace: Process 2182 attached ^C^C^C
システムコール呼んでないですしね。何にもとれないですよね。ユーザランドのトレースツールだもんね
無念!!!
sysrq-trigger でバックトレースを採取する. wikipedia にちょうどいい解説が載っています
設定を有効にして
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
👈 で確認できますね! やったー
前回の続き
rtnl_mutex でロックを獲得してクリティカルセクションを実行中のタスクを何らかの方法でトレースしたり、時間を計測したいと思って、あれこれ調べたり、試行錯誤していた
最終的に bpftrace でがちゃがちゃと試すまでを記していく
続きを読むstrace 5.2 で追加された -z -Z オプションが面白かったので書いておきます (注意: この記事を書いた時点では 5.3 が最新です )
失敗したシステムコールだけフィルターしてくれるオプション
root@xenial:~/strace-5.3# ./strace -Z ls >/dev/null access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory) access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory) access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory) access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory) access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory) access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory) access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory) statfs("/sys/fs/selinux", 0x7ffe56406c30) = -1 ENOENT (No such file or directory) statfs("/selinux", 0x7ffe56406c30) = -1 ENOENT (No such file or directory) ioctl(1, TCGETS, 0x7ffe56406890) = -1 ENOTTY (Inappropriate ioctl for device) ioctl(1, TIOCGWINSZ, 0x7ffe56406950) = -1 ENOTTY (Inappropriate ioctl for device) ioctl(1, TCGETS, 0x7ffe56404350) = -1 ENOTTY (Inappropriate ioctl for device) +++ exited with 0 +++
膨大なシステムコールの中から失敗したものだけに着目したいというユースケースはよくあるので、便利そうです
成功したシステムコールだけフィルターしてくれるオプション. でも通常の実行と区別がつきにくいかな?
root@xenial:~/strace-5.3# ./strace -z ls >/dev/null execve("/bin/ls", ["ls"], 0x7ffcc2dff938 /* 17 vars */) = 0 brk(NULL) = 0x161e000 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=46096, ...}) = 0 mmap(NULL, 46096, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f7723d73000 close(3) = 0 open("/lib/x86_64-linux-gnu/libselinux.so.1", O_RDONLY|O_CLOEXEC) = 3 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\260Z\0\0\0\0\0\0"..., 832) = 832 fstat(3, {st_mode=S_IFREG|0644, st_size=130224, ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7723d72000 mmap(NULL, 2234080, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f7723938000 mprotect(0x7f7723957000, 2093056, PROT_NONE) = 0 mmap(0x7f7723b56000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1e000) = 0x7f7723b56000 mmap(0x7f7723b58000, 5856, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f7723b58000 close(3) = 0 ...
失敗したシステムコールが多くて (例: Perl や Ruby なんかでライブラリを探す際に stat(2), lstat(2) あたり が ENOENT を大量に出す場合など ) ノイズになる場合に使えそう