Linux Kernel: rtnl_mutex を長時間 ロックして刺さった状態を観察する (2) with bpftrace

前回の続き

hiboma.hatenadiary.jp

rtnl_mutex でロックを獲得してクリティカルセクションを実行中のタスクを何らかの方法でトレースしたり、時間を計測したいと思って、あれこれ調べたり、試行錯誤していた

最終的に bpftrace でがちゃがちゃと試すまでを記していく

案 A: CONFIG_LOCK_STAT

Kernel の設定で CONFIG_LOCK_STAT を有効にしていると各種ロックの統計を取ることができるようです

sites.google.com

CONFIG_LOCK_STAT は CONFIG_DEBUG_KERNEL に依存した設定なので、production 環境なワークロード化で導入するのはなかなか難しそうかな?

CONFIG_LOCK_STAT の設定を Ubuntu (Vagrant) で確認したけど有効でないな (Ubuntuデバッグカーネルあるんだっけ?)

vagrant@bionic:~$ sudo grep -R CONFIG_LOCK_STAT /boot/
/boot/config-4.15.0-29-generic:# CONFIG_LOCK_STAT is not set
/boot/config-5.0.0-32-generic:# CONFIG_LOCK_STAT is not set

これは別のエントリで調べて試してみよう

案 B: perf-tools

Brendan Gregg が公開してくれている perf-tools の functrace を使ってみる

github.com

functrace で rtnl_*lock をトレースする

vagrant@bionic:~/perf-tools$ sudo ./bin/functrace rtnl_*lock
Tracing "rtnl_*lock"... Ctrl-C to end.
     kworker/1:2-3369  [001] .... 21605.208741: rtnl_lock <-addrconf_verify_work
     kworker/1:2-3369  [001] .... 21605.208762: rtnl_unlock <-addrconf_verify_work
          vminfo-1121  [001] .... 21608.695803: rtnl_lock <-dev_ioctl
          vminfo-1121  [001] .... 21608.695821: rtnl_unlock <-dev_ioctl
          vminfo-1121  [001] .... 21608.695830: rtnl_lock <-devinet_ioctl
          vminfo-1121  [001] .... 21608.695831: rtnl_unlock <-devinet_ioctl
          vminfo-1121  [001] .... 21608.695833: rtnl_lock <-devinet_ioctl
          vminfo-1121  [001] .... 21608.695833: rtnl_unlock <-devinet_ioctl
         unshare-4140  [003] .... 21611.807192: rtnl_lock <-register_netdev
         unshare-4140  [003] .... 21611.807443: rtnl_unlock <-register_netdev
         unshare-4140  [003] .... 21611.807672: rtnl_lock <-copy_net_ns
         unshare-4140  [003] .... 21611.808039: rtnl_unlock <-copy_net_ns

perf-tools は git clone してすぐにシュッと使えるのがいいですね.

トレースを採取できたんだが、フォーマットを自由に書き換えたり、バックとレースを出したり、 ... ともっと欲がでます.

案 C: bptrace

次に試したのは bpftrace. ( Ubuntu Bionic で Kernel 4.15系で試しています )

github.com

下記は rtnl_lock() と rtnl_unlock() の probe に printf を仕込むスクリプトです. 素朴に pid と comm を printf します

kprobe:rtnl_lock {
  printf("> %d %s\n", pid, comm)
}

kretprobe:rtnl_unlock {
  printf("< %d %s\n", pid, comm)
}

スクリプトを実行しつつ別の SSH セッションで rtnl_lock() を呼ぶプロセス (例 sudo unshare -n bash -c exit ) を実行すると以下のようなトレースが採取できる

vagrant@bionic:~$ sudo bpftrace 000.bt
Attaching 2 probes...
> 1682 unshare
< 1682 unshare
> 1682 unshare
< 1682 unshare
> 103 kworker/u8:3
< 103 kworker/u8:3
> 103 kworker/u8:3
< 103 kworker/u8:3

うむ! これでやりたいことを達成できたようだが ... 試しているうちにトレースできていない関数があることに気が付く

rtnl_lock() を使わず mutex_lock() で rtnl_mutex を掴むのがいる

自分で書いた過去エントリを見直すと rtnl_mutex を rtnl_lock(), rtnl_unlock() を使わずに mutex_lock() , mutex_unlock() で直接ロックしている箇所があり、それらの呼び出しをトレースできていなかった.

例えば以下の __netlink_dump_start() が該当する

int __netlink_dump_start(struct sock *ssk, struct sk_buff *skb,
             const struct nlmsghdr *nlh,
             struct netlink_dump_control *control)
{
    struct netlink_callback *cb;
    struct sock *sk;
    struct netlink_sock *nlk;
    int ret;

    nlk = nlk_sk(sk);
    mutex_lock(nlk->cb_mutex); 👈
    /* A dump is in progress... */
    if (nlk->cb_running) {
        ret = -EBUSY;
        goto error_unlock;
    }

... 略

加えて rtnl_try_lock() という trylock を試みる派生の関数もあったりで これらも考慮する必要があった

int rtnl_trylock(void)
{
    return mutex_trylock(&rtnl_mutex);
}
EXPORT_SYMBOL(rtnl_trylock);

さて、どうしよう?

案C-1: bpftrace で mutex_lock() , mutex_unlock() をトレースする

ソースコードを眺めなて、 mutex_lock() , mutex_unlock() の probe を引っ掛けるという案を思いつくが、別の問題も浮上する

probe 多過ぎ

素朴に mutex_lock(), mutex_unlock() を probe としてトレースしてしまうと rtnl_mutex 以外の mutex をロックする箇所も引っかけてしまう. 4.15 のソースで確認したら 3942 の箇所で呼び出されていた

linux-4.15 $ global -r mutex_lock | wc -l
    3942

素朴にやってみたら bpftrace が bpftrace の mutex_lock を拾っちゃって user mode で CPU ぶん回して止まらなくなった!

vagrant@bionic:~$ sudo bpftrace -e 'kprobe:mutex_lock { printf("%d %s\n", pid, comm) }'
Attaching 1 probe...
1747 bpftrace
1747 bpftrace
1747 bpftrace
1747 bpftrace
1747 bpftrace
1747 bpftrace
1747 bpftrace
1747 bpftrace

...

1747 bpftrace
Lost 3 events
1747 bpftrace
Lost 3 events
1747 bpftrace
Lost 3 events
1747 bpftrace
Lost 3 events
1747 bpftrace
Lost 3 events
1747 bpftrace
Lost 3 events
1747 bpftrace
^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C

comm != bpftrace のフィルターを追加してみたけど、出力が膨大すぎて使い物にならなさそう

vagrant@bionic:~$ sudo bpftrace -e 'kprobe:mutex_lock /comm != "bpftrace"/ { printf("%d %s\n", pid, comm) }'
Attaching 1 probe...
435 systemd-journal
435 systemd-journal
435 systemd-journal
435 systemd-journal
1772 kworker/u8:3
1772 kworker/u8:3
1772 kworker/u8:3
1772 kworker/u8:3
1772 kworker/u8:3
1772 kworker/u8:3
1772 kworker/u8:3
1772 kworker/u8:3
1772 kworker/u8:3
1772 kworker/u8:3
1772 kworker/u8:3
1772 kworker/u8:3
1772 kworker/u8:3
1772 kworker/u8:3
1772 kworker/u8:3
1772 kworker/u8:3
1772 kworker/u8:3
1772 kworker/u8:3
1772 kworker/u8:3
1772 kworker/u8:3

... 延々と続く

トレース対象を rtnl_mutex だけに絞り込みたい

bpftrace のマニュアルを読みながら以下の作戦を閃いた

1. rtnl_mutex のシンボルを解決してアドレスを得る

  • bpftrace には kaddr(char )* でシンボルのアドレスを解決するメソッドが実装されている
  • /proc/kallsym で rtnl_mutex のシンボルとアドレスが列挙されているので、 kaddr() で解決出来そうとアタリをつけた
vagrant@bionic:~$ sudo grep rtnl_mutex /proc/kallsyms
ffffffff97fe6260 d rtnl_mutex

2. mutex_lock(), mutex_unlock() の引数が 1 で解決したアドレスであるかどうかでフィルターを作る

  • bpftrace で kprobe の引数を参照するには arg0, arg1, ... を用いる
  • フィルターは awk みたいなフォーマットで書ける
kprobe:mutex_lock /arg0 == kaddr("rtnl_mutex")/

こんなフィルターである

3. いろいろ試行錯誤したすえに 変更をいれたスクリプトは以下のようになった

kprobe:mutex_lock /arg0 == kaddr("rtnl_mutex")/ {
  printf("> %d %s\n", pid, comm);
}

// kretprobe では Warning が出てしまった!!!
//
// The arg0 builtin can only be used with 'kprobes', 'uprobes' and 'usdt' probes
// kretprobe:mutex_unlock /arg0 == kaddr("rtnl_mutex")/ {
//
kprobe:mutex_unlock /arg0 == kaddr("rtnl_mutex")/ {
  printf("< %d %s\n", pid, comm);
}

📝 arg0 は kretprobe の中では扱えない」という旨のエラーに遭遇し kprobe:mutex_unlock に置換して扱っている. ( kretprobe で引数を参照できない = kretprobe は関数のスタックを解放した後に実行されるんかな? )

上記のスクリプトでトレースすると以下のような出力を得ることができる

vagrant@bionic:~$ cp /vagrant/001.bt .; sudo bpftrace 001.bt
Attaching 2 probes...
> 2157 ss
< 2157 ss
> 2157 ss
< 2157 ss
> 2157 ss
< 2157 ss
> 2158 ip
< 2158 ip

よさそうな感じである

結局 mutex_lock, mutex_unlock 全部の probe に仕込んでるので、ちょいとパフォーマンスの懸念があるが、計測できていない

案C-2: 改良する

次に以下のように改良を重ねていった

  • フィルターの条件を改良して kretprobe:mutex_lock を計測のポイントとした
  • mutex_lock() を呼び出してから mutex_unlock() を追えるまでの時間を計測できるようにもした
kprobe:mutex_lock /arg0 == kaddr("rtnl_mutex")/ {
  @locked[tid] = nsecs;
  printf("> %d %s\n", pid, comm);
}

kretprobe:mutex_unlock /@locked[tid]/ {
  printf("< %d %s %d\n", pid, comm, nsecs - @locked[tid]);
  delete(@locked[tid]);
}

上記でトレースすると以下のような出力を得る

vagrant@bionic:~$ cp /vagrant/002.bt .; sudo bpftrace 002.bt
Attaching 2 probes...
> 2800 unshare
< 2800 unshare 63660       # 単位は nanosecond
> 2800 unshare
< 2800 unshare 37036
> 2762 kworker/u8:3
< 2762 kworker/u8:3 13548
> 2762 kworker/u8:3
< 2762 kworker/u8:3 40131
> 2762 kworker/u8:3
< 2762 kworker/u8:3 9814

案C-3: バックトレースを出す

mutex_lock(), mutex_unlock() 呼び出し際のスタックトレース/バックトレース を出したいよなぁとなり、さらに変更をいれていった

ロックの位置が特定しやすいよういバックトレース/コールトレース を出すようにした

 kprobe:mutex_lock /arg0 == kaddr("rtnl_mutex")/ {
  @locked[tid] = nsecs;
  printf("> %d %s\n%s\n", pid, comm, kstack);
}

kretprobe:mutex_unlock /@locked[tid]/ {
  printf("< %d %s %d\n%s\n", pid, comm, nsecs - @locked[tid], kstack);
  delete(@locked[tid]);
}

下記のような出力を得る

vagrant@bionic:~$ cp /vagrant/003.bt .; sudo bpftrace 003.bt
Attaching 2 probes...
> 3196 unshare

        mutex_lock+1
        register_netdev+18
        loopback_net_init+77
        ops_init+68
        setup_net+155
        copy_net_ns+209
        create_new_namespaces+287
        unshare_nsproxy_namespaces+94
        sys_unshare+531
        do_syscall_64+115
        entry_SYSCALL_64_after_hwframe+61

< 3196 unshare 54326

        kretprobe_trampoline+0
        __alloc_percpu_gfp+18
        loopback_dev_init+37
        register_netdevice+151
        register_netdev+26
        loopback_net_init+77
        ops_init+68
        setup_net+155
        copy_net_ns+209
        create_new_namespaces+287
        unshare_nsproxy_namespaces+94
        sys_unshare+531
        do_syscall_64+115
        entry_SYSCALL_64_after_hwframe+61

> 3196 unshare

        mutex_lock+1
        copy_net_ns+461
        create_new_namespaces+287
        unshare_nsproxy_namespaces+94
        sys_unshare+531
        do_syscall_64+115
        entry_SYSCALL_64_after_hwframe+61

案C-4: mutex をとろうとしてブロックした時間、クリティカルセクションの時間を出す

  • あるタスクがロックを取ろうとしたがブロックしてしまった時間
  • あるタスクがクリティカルセクションを実行していた時間

も採取できるようにした. もうちょいすっきりかけないかなぁというスクリプトになっている

// rtnl_mutex を獲得しようとしたプロセス
kprobe:mutex_lock /arg0 == kaddr("rtnl_mutex") && @mutex_lock_in[tid] == 0/ {
  @mutex_lock_in[tid] = nsecs;
  printf("@ %d %s\n", pid, comm);
}

// rtnl_mutex を獲得しているプロセス
// クリティカルセクション実行中なので 1プロセスに限定される
kretprobe:mutex_lock /@mutex_lock_in[tid]/ {
  @mutex_lock_out[tid] = nsecs;
  printf("+ %d %s\n", pid, comm);
  printf("%s\n", kstack);
}

// rtnl_mutex を解放したプロセス
kretprobe:mutex_unlock /@mutex_lock_out[tid]/ {

  printf("- %d %s ", pid, comm);

  $lock_section     = nsecs - @mutex_lock_in[tid];
  $critical_section = nsecs - @mutex_lock_out[tid];
  $blocked          = $lock_section - $critical_section;

  printf("locked:%ld\tcritical_section:%ld\tblocked:%ld\n", $lock_section, $critical_section, $blocked);

  delete(@mutex_lock_in[tid]);
  delete(@mutex_lock_out[tid]);
}

下記のような出力を得ることができる

@ 3366 unshare
+ 3366 unshare

        kretprobe_trampoline+0
        copy_net_ns+461
        create_new_namespaces+287
        unshare_nsproxy_namespaces+94
        SyS_unshare+531
        do_syscall_64+115
        entry_SYSCALL_64_after_hwframe+61

- 3366 unshare locked:15967    critical_section:8976   blocked:6991
@ 3337 kworker/u8:1
+ 3337 kworker/u8:1

        kretprobe_trampoline+0
        cleanup_net+153
        process_one_work+478
        worker_thread+50
        kthread+289
        ret_from_fork+53

- 3337 kworker/u8:1 locked:27987   critical_section:12349  blocked:15638
@ 3337 kworker/u8:1
+ 3337 kworker/u8:1

        kretprobe_trampoline+0
        ppp_exit_net+81
        ops_exit_list.isra.8+59
        cleanup_net+458
        process_one_work+478
        worker_thread+50
        kthread+289
        ret_from_fork+53

- 3337 kworker/u8:1 locked:329171  critical_section:27076  blocked:302095

もうちょい見やすいフォーマットにできるといいんだが、まぁ 今は気にしない

⚠️ kprobe:mutex_lock が二回呼び出されている箇所があり、謎い. うーん???

@ 3366 unshare
+ 3366 unshare

        kretprobe_trampoline+0
        register_netdev+18
        loopback_net_init+77
        ops_init+68
        setup_net+155
        copy_net_ns+209
        create_new_namespaces+287
        unshare_nsproxy_namespaces+94
        SyS_unshare+531
        do_syscall_64+115
        entry_SYSCALL_64_after_hwframe+61

+ 3366 unshare

        kretprobe_trampoline+0
        __alloc_percpu_gfp+18
        loopback_dev_init+37
        register_netdevice+151
        register_netdev+26
        loopback_net_init+77
        ops_init+68
        setup_net+155
        copy_net_ns+209
        create_new_namespaces+287
        unshare_nsproxy_namespaces+94
        SyS_unshare+531
        do_syscall_64+115
        entry_SYSCALL_64_after_hwframe+61

- 3366 unshare locked:38180    critical_section:9259   blocked:28921

まとめ

  • Proof of Concept なところは達成できたと思う ( production な環境では試していない )
  • 全ての mutex_lock, mutex_unlock をトレース対象に含めているあたりが心配である