CentOS7.5 の perf probe / perf record のバグと思われる挙動を調べ中

(2018/6/16 14:15 追記) VM を作り直したら systemd が segmentaion fault するもののカーネルパニックは再現しなくなったので、私の VM がおかしかった可能性があります . 中途半端な検証ですいません. 引き続き調べています

Dynamically Obtain Shared Object Library Data with uprobes - Wind River Knowledge Library

ここを参照しながら perf probe と perf record を試していたのだが、 CentOS7.5 - 3.10.0-862.3.2.el7.x86_64 でバグと思われる挙動に遭遇した. 調べている途中だが、記録を書き出す

Enviroment

VirtualBox
CentOS7 3.10.0-862.3.2.el7.x86_64
perf-3.10.0-862.3.2.el7.x86_64
glibc-2.17-222.el7.x86_64

(追記)

3.10.0-862.2.3.el7.x86_64
3.10.0-862.3.2.el7.x86_64

の２つで再現しています.

3.10.0-862.el7.x86_64

は問題ないようです

Steps to reproduce

カーネルのバージョンを確かめましょう

-bash-4.2$ uname -a
Linux localhost.localdomain 3.10.0-862.3.2.el7.x86_64 #1 SMP Mon May 21 23:36:36 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux

probe を仕込みます

-bash-4.2$ sudo perf probe -x /usr/lib64/libc.so.6 malloc
Added new event:
  probe_libc:malloc    (on malloc in /usr/lib64/libc-2.17.so)

You can now use it in all perf tools, such as:

    perf record -e probe_libc:malloc -aR sleep 1

perf record すると ... oh ...

-bash-4.2$ sudo perf record -e probe_libc:malloc -aR sleep 1
perf: Segmentation fault 🔥
Connection to 127.0.0.1 closed by remote host.
Connection to 127.0.0.1 closed.

ホストのコンソールログには systemd が Segmentation fault でしんでカーネルパニックを起こしているのが記録された

localhost login: [  683.916129] systemd[1]: segfault at 1 ip 0000000000000001 sp 00007ffe78725378 error 14 in systemd[55e987a3b000+160000]
[  684.138858] systemd[1] bad frame in rt_sigreturn frame:00007ffe78724ae0 ip:16 sp:170f12001a131100 orax:ffffffffffffffff in systemd[55e987a3b000+160000]
[  684.259509] Kernel panic - not syncing: Attempted to kill init! exitcode=0x0000000b
[  684.259509] 
[  684.273370] CPU: 0 PID: 1 Comm: systemd Kdump: loaded Tainted: G           OE  ------------   3.10.0-862.3.2.el7.x86_64 #1
[  684.295776] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006
[  684.308762] Call Trace:
[  684.311479]  [<ffffffff8250e78e>] dump_stack+0x19/0x1b
[  684.319751]  [<ffffffff82508a90>] panic+0xe8/0x21f
[  684.327169]  [<ffffffff81e98206>] do_exit+0xa36/0xa40
[  684.335682]  [<ffffffff81ea57b3>] ? __sigqueue_free.part.12+0x33/0x40
[  684.346157]  [<ffffffff81e9828f>] do_group_exit+0x3f/0xa0
[  684.356210]  [<ffffffff81ea8b3e>] get_signal_to_deliver+0x1ce/0x5e0
[  684.370055]  [<ffffffff81e2a527>] do_signal+0x57/0x6e0
[  684.377694]  [<ffffffff81e94b29>] ? vprintk_default+0x29/0x40
[  684.383936]  [<ffffffff81ea77c6>] ? force_sig+0x16/0x20
[  684.392863]  [<ffffffff81e2aca4>] ? signal_fault+0x34/0xf0
[  684.401379]  [<ffffffff81e2ac22>] do_notify_resume+0x72/0xc0
[  684.407929]  [<ffffffff82520b8f>] int_signal+0x12/0x17

segfault at 1 ip 0000000000000001 が明らかに変な数値

切り分け (1)

malloc の代わりに、適当に getrusage など指定すると再現しない

$ sudo perf probe -x /usr/lib64/libc.so.6 getrusage
Added new event:
  probe_libc:getrusage (on getrusage in /usr/lib64/libc-2.17.so)

You can now use it in all perf tools, such as:

    perf record -e probe_libc:getrusage -aR sleep 1

$ sudo perf record -e probe_libc:getrusage -aR sleep 1
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.183 MB perf.data ]

getrusage を選んだのは、これを呼びだすプロセスが少なかろうという見込み

切り分け (2)

getrusage を呼び出すバイナリを perf record する

#include <sys/time.h> 
#include <sys/resource.h>
#include <linux/resource.h>

int main() { 
    struct rusage usage;
    getrusage(RUSAGE_SELF, &usage);
}

-bash-4.2$ gcc getrusage.c -o getrusage
-bash-4.2$ sudo perf record -e probe_libc:getrusage -aR $PWD/getrusage
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.189 MB perf.data (1 samples) ]
Illegal instruction 💀

今度は illegal instruction を出す 💀. dmesg にもログが残る

[  662.144863] traps: getrusage[1656] trap invalid opcode ip:7f9ceb0be051 sp:7ffc3d838ac8 error:0 in libc-2.17.so[7f9ceafc9000+1c3000]

推測

最初の probe_libc:malloc のケースでは

perf probe で malloc(3) の uprobe が仕込まれる
perf や systemd が malloc(3) を呼び出す際に uprobe を踏むが、「何かがおかしい」ので Segumentaion Fault する
systemd は init process なので、SIGSEGV を受けると Kernel panic - not syncing: Attempted to kill init! のカーネルパニックを起こす

切り分け(2) の probe_libc:getursage のケースでも uprobe の仕込み方が「おかしい」とはわかるが、具体的に何がどうとは分からない. 変な opcode を突っ込んでるのだろうか

カーネルバージョンによる切り分け

CentOS7.4 - 3.10.0-693.21.1.el7.x86_64 にカーネルをダウングレードしたり、Ubuntu Xenial 4.4.0-128 だったりでは再現しなかった. CentOS7.5 のバグかな〜〜?

CentOS7.4 3.10.0-693.21.1.el7.x86_64 での結果

-bash-4.2$ uname -a
Linux localhost.localdomain 3.10.0-693.21.1.el7.x86_64 #1 SMP Wed Mar 7 19:03:37 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux

-bash-4.2$ sudo perf probe -x /usr/lib64/libc.so.6 malloc
Added new event:
  probe_libc:malloc    (on malloc in /usr/lib64/libc-2.17.so)

You can now use it in all perf tools, such as:

    perf record -e probe_libc:malloc -aR sleep 1

-bash-4.2$ sudo perf record -e probe_libc:malloc -aR sleep 1
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.183 MB perf.data (34 samples) ]

感想

まさか systemd が吹っ飛ぶとは思わないから production なんかで踏むと最悪だー!
何がおかしいのか、もうちょっと深追いして見る予定