前回の続き
rtnl_mutex でロックを獲得してクリティカルセクションを実行中のタスクを何らかの方法でトレースしたり、時間を計測したいと思って、あれこれ調べたり、試行錯誤していた
最終的に bpftrace でがちゃがちゃと試すまでを記していく
案 A: CONFIG_LOCK_STAT
Kernel の設定で CONFIG_LOCK_STAT を有効にしていると各種ロックの統計を取ることができるようです
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 を使ってみる
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系で試しています )
下記は 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 をトレース対象に含めているあたりが心配である