Kubernetes 環境で negative dentry をトレースする

この記事は Kubernetes Advent Calendar 2019 の6日目の記事です。

はじめに

昨今、カーネルの機能・ツールをコンテナや Kubernetes 環境に様々な形で活用する事例が増えてきた(体感)。たとえば、 KubeCon + CloudNativeCon North America 2019 でも、 DNS の障害解析や Kube-proxyの iptables の代替手段として eBPF が紹介されている。しかし、ネットワーク周りのデバッグ・改善に絡む話以外では、カーネルツール活用事例が大きく取り上げられていないようにも感じた。
そこで本記事では、太古の昔記事 aws sdkを使っているとslabキャッシュが増大化していく と同様の解析を Kubernetes 環境上で実現する方法を紹介し、ネットワーク系以外の問題解析に対してもカーネルツールが役に立つことを示す。加えてプリミティブな技術だけで色々できることも示したいので、 Kubernetes 上のアプリにサイドカーを配置したり、特別なツールを導入しないで解析する。
ちなみに元ネタは5年以上前の記事になるが、negative dentry でググってみると今でも時々話題にあがるネタであることがわかった。

検証環境

検証環境は下記の通り。

• Ubuntu 18.04(x86_64, kernel : 5.0.0-32-generic)
• Kubernetes : v1.15.2

本検証では ftrace を tracefs から直接使ってトレースする。そのため、 tracefs をマウント出来ていれば、その他に必要なツールはない。なお tracefs は、 /sys/kernel/debug/tracing にマウントされているものとする。

ftrace の設定

negative dentry についてはネットで検索するだけで良い情報に辿り着けるようになってきたので割愛させていただき、代わりに ftrace の設定方法について紹介したい。
今回カーネルから取得したい情報は、「1. negative dentry の大量発生源になっているプロセス」、「２．negative dentry 発生要因のファイル名(つまり存在しないファイル名)」である。そこで、これらの取得方法を説明する。

negative dentry の大量発生源になっているプロセスを特定

ftrace のヒストグラムを使う。詳細についてはカーネルバージョン毎のドキュメントを参照してほしいが、一言で言うとカーネル側で簡易的なヒストグラムを生成してくれる機能である。今回はこの機能を活用して、PID 単位で存在しないファイルを参照しまくっているプロセスを降順に表示してみよう。
設定は下記のようになる。

# echo 'p:ndprobe d_splice_alias inode=%di' > /sys/kernel/debug/tracing/kprobe_events
# echo 'hist:keys=common_pid.execname:vals=hitcount,inode:sort=hitcount.descending:size=2048 if inode == 0' > /sys/kernel/debug/tracing/events/kprobes/ndprobe/trigger
# echo '1' > /sys/kernel/debug/tracing/events/kprobes/ndprobe/enable

詳細についてはカーネルのドキュメントを参照してもらいたいが、注意点を解説する。
まず一行目では d_splice_alias 関数の第一引数の値を変数 inode に設定している。第一引数の値は、たとえば、Linux(x86_64) の calling convention では rdi になる。なお、新しいカーネルではアーキテクチャ依存な設定をなくすような改善が進んでいる。
次に二行目では一行目で設定した変数を使い、 inode のポインタが NULL になっているプロセスをカウントするようヒストグラムを設定する。
最後に三行目でトレースを開始する。

negative dentry 発生要因のファイル名(つまり存在しないファイル名)を取得

ヒストグラムによって危ないプロセスを発見することができるが、あわせてどのようなファイル名が呼び出されているのかも知りたい。そのためには、下記のように設定する。

# echo 'p:ndprobe d_splice_alias inode=%di d_iname=+56(%si):string' > /sys/kernel/debug/tracing/kprobe_events
# echo "inode == 0" > /sys/kernel/debug/tracing/events/kprobes/ndprobe/filter
# echo '1' > /sys/kernel/debug/tracing/events/kprobes/ndprobe/enable

ここでも注意点を解説する。
一行目では、変数 inode に加えてファイル名(今回は簡単に d_iname を表示)を取得する。rsi レジスタに格納された dentry のアドレスから d_iname までのオフセットを計算し、そのオフセットを設定する。ここでのハマりどころがカーネルの randomize layout 機能である。

Randomizing structure layout

randomize layout によって、カーネルビルド時に構造体のオフセットが決まるので注意が必要である。

解析

ホスト上から解析

[マスタ]
今回は何らかの Pod に対して外部から無駄なstatをするワンライナーを実行する。

# kubectl exec -it sample-pod -- perl -e 'stat "/nonexist/$_" for 1..100000000'

[ノード]
ノード上で ftrace を設定した結果を表示する。

• negative dentry の大量発生源になっているプロセスを特定

(事前準備)
# echo 'p:ndprobe d_splice_alias inode=%di' > /sys/kernel/debug/tracing/kprobe_events
# echo 'hist:keys=common_pid.execname:vals=hitcount,inode:sort=hitcount.descending:size=2048 if inode == 0' > /sys/kernel/debug/tracing/events/kprobes/ndprobe/trigger
# echo '1' > /sys/kernel/debug/tracing/events/kprobes/ndprobe/enable

(マスタで外部コマンド実行)
# head -n 10 /sys/kernel/debug/tracing/events/kprobes/ndprobe/hist
# event histogram
#
# trigger info: hist:keys=common_pid.execname:vals=hitcount,inode:sort=hitcount.descending:size=2048 if inode == 0 [active]
#

{ common_pid: perl            [     31631] } hitcount:   10299276  inode:          0
{ common_pid: iptables-restor [     31393] } hitcount:         58  inode:          0
{ common_pid: runc:[2:INIT]   [     31498] } hitcount:         56  inode:          0
{ common_pid: iptables-save   [     31391] } hitcount:         49  inode:          0
{ common_pid: flanneld        [     31306] } hitcount:         46  inode:          0

大量に negative dentry を発生させているプロセスを確認することができた。この PID からコンテナを特定できる。
次にバッファなどをいったんクリアして、無駄に stat されているファイル名を表示してみる。

• negative dentry 発生要因のファイル名(つまり存在しないファイル名)を取得

(事前準備)
# echo 'p:ndprobe d_splice_alias inode=%di d_iname=+56(%si):string' > /sys/kernel/debug/tracing/kprobe_events
# echo "inode == 0" > /sys/kernel/debug/tracing/events/kprobes/ndprobe/filter
# echo '1' > /sys/kernel/debug/tracing/events/kprobes/ndprobe/enable

(マスタで外部コマンド実行)
# tail -n 10 /sys/kernel/debug/tracing/trace
root@k8s-20190810-node2:/home/k8s# tail -n 10 /sys/kernel/debug/tracing/trace
            perl-31631 [001] ....  3254.986576: ndprobe: (d_splice_alias+0x0/0x430) inode=0x0 d_iname="nonexist17558057"
            perl-31631 [001] ....  3254.986581: ndprobe: (d_splice_alias+0x0/0x430) inode=0x0 d_iname="nonexist17558057"
            perl-31631 [001] ....  3254.986585: ndprobe: (d_splice_alias+0x0/0x430) inode=0x0 d_iname="nonexist17558057"
            perl-31631 [001] ....  3254.986587: ndprobe: (d_splice_alias+0x0/0x430) inode=0x0 d_iname="nonexist17558057"
            perl-31631 [001] ....  3254.986598: ndprobe: (d_splice_alias+0x0/0x430) inode=0x0 d_iname="nonexist17558058"
            perl-31631 [001] ....  3254.986608: ndprobe: (d_splice_alias+0x0/0x430) inode=0x0 d_iname="nonexist17558058"
            perl-31631 [001] ....  3254.986614: ndprobe: (d_splice_alias+0x0/0x430) inode=0x0 d_iname="nonexist17558058"
            perl-31631 [001] ....  3254.986619: ndprobe: (d_splice_alias+0x0/0x430) inode=0x0 d_iname="nonexist17558058"
            perl-31631 [001] ....  3254.986621: ndprobe: (d_splice_alias+0x0/0x430) inode=0x0 d_iname="nonexist17558058"
            perl-31631 [001] ....  3254.986632: ndprobe: (d_splice_alias+0x0/0x430) inode=0x0 d_iname="nonexist17558059"

nonexist(番号)という存在しないファイル名が stat されていることも確認できた。

コンテナ単位で解析

ホスト上からシステム全体の negtive dentry の状態を解析することはできた。さらに OCI hooks を用いてコンテナ単位でコンテナ起動時からコンテナ内部のプロセスをトレースすることも可能である。この際、 negative dentry 以外の情報も出力させることで、より詳細な解析をすることができる。というか、そこまでをゴールにするつもりだったが時間の関係で到達できなかった。大変申し訳ないが、続きは下記を参照して設定してほしい。反響があれば続編として検討する。

• Debug-application-inside-Kubernetes-using-Linux-Kernel-tools : OCI hooks を使って、コンテナ起動時にコンテナの initial PID を取得する方法を説明している。
• ftrace を使ったコンテナ内デバッグの準備 : コンテナ単位で ftrace のバッファを分割する方法を説明している。

おわりに

ftrace を活用することで、 Kubernetes 上のアプリにサイドカーを配置したり、特別なツールを導入することなく、コンテナ内のプロセスが発生させる大量の negative dentry の原因を調査した。
巷では eBPF 大ブームな状況であり、 Falco は独自のカーネルモジュールを導入できない環境(Google の Container-Optimized OS（COS）等)に対応するために eBPF を活用している。しかし、 eBPF は新しいカーネルバージョンが要求されたり、特権が必要だったり、clang が必要だったり、まだまだ制約が多い(余談だが、 eBPF と PREEMPT_RT が現状共存できない問題もある)。
そこで今後しばらくは、本記事のような過去のノウハウやスクリプトを bcc でも使えるようにしていきつつ、逆に bcc でよく使われるスクリプトを ftrace でも使えるようにしてレガシーな環境もデバッグできるようにしていきたい。

参考情報

• ftrace ベースのrootlessでシステムコールトレースを行うツール
• [ftrace - Function Tracer]
  (https://www.kernel.org/doc/Documentation/trace/ftrace.txt "ftrace - Function Tracer")
• [Liberating Kubernetes From Kube-proxy and Iptables]
  (https://kccncna19.sched.com/event/Uaam/liberating-kubernetes-from-kube-proxy-and-iptables-martynas-pumputis-cilium "Liberating Kubernetes From Kube-proxy and Iptables")
• [Sysdig and Falco now powered by eBPF]
  (https://sysdig.com/blog/sysdig-and-falco-now-powered-by-ebpf "Sysdig and Falco now powered by eBPF")
• [Lightning Talk: Is Your Kubernetes Cluster's DNS Working?]
  (https://kccncna19.sched.com/event/UafQ/lightning-talk-is-your-kubernetes-clusters-dns-working-jonathan-perry-flowmill "Lightning Talk: Is Your Kubernetes Cluster's DNS Working?")
• [Tracing the Containers (mainly about eBPF)]
  (https://speakerdeck.com/udzura/tracing-the-containers-mainly-about-ebpf "Tracing the Containers (mainly about eBPF)")