はじめに - 可観測性とは？
クラウドネイティブなシステムでは可観測性を確保することが必須である、という話題を最近よく聞きます。可観測性はもともと制御理論で用いられていたワードでしたが、クラウドネイティブな業界では「システムという複雑な系から、その内部状態に関する情報を取得できる性質」と定義されます。可観測性が高ければ高いほど、システムの健康状態や可用性の正確な把握、また障害分析からの早期復旧が見込める度合いが強くなると言えます。可観測性を担保するうえで主要な3つのデータソースがメトリクス、ログ、トレーシングでありこれらの情報を効果的にモニタリングすることが重要になってきます。
モニタリングとデバッギング
Cindy氏は Monitoring in the time of Cloud Native というタイトルのブログの中で可観測性を構成する要素としてプロアクティブな部分とリアクティブな部分を分けて、プロアクティブな部分はオーバービューとアラートといういわゆるモニタリング、リアクティブな部分はデバッキング、プロファイリング、依存性分析であると述べています。モニタリング基盤としてPrometheusやELK, 分散トレーシングを駆使して障害発生のレイヤまでは特定しても、そのサーバの中で何が起こってるかわからず原因不明で終わってしまう障害は少なからず存在します。こういった場合にデバッギングをはじめとした分析が必要となります。
こうしたデバッグの技術は、多くの企業がそのシステムに長い経験を持つ職人エンジニアに頼ることも多く、またスタックトレースやstraceなど本番環境では負荷が高くて実施できず、時間が取れず原因調査を断念せざるを得ないということも現場ではたびたび発生します。
デバッグを本番環境でも安全に低負荷で行う方法があれば可観測性も上がり結果的に職人エンジニアの負荷も下げることが可能になります。
eBPF is 何？
eBPF は extended Berkeley Packet Filterの略で1992年に発表された「The BSD Packet Filter:A New Architecture for User-level Packet Capture」という論文で発表されたネットワークのパケットキャプチャツールに端を発しています。これはユーザー空間でカーネル内の任意の操作を安全に実行するためのフレームワークでネットワークパケットのフィルタや集計をユーザー空間からの操作でカーネル内で行い必要な結果だけをユーザー空間に戻すことができました。tcpdumpもBPFの仕組みを内部で使っています。eBPFはこれをネットワークパケット以外にも拡張したものでユーザープログラムから様々なカーネルのイベントをフックして情報をフィルタしたり集計された結果をユーザー空間に戻すことが可能です。
eBPFの特徴としては、
- 内部にverifierという機構がありループなどの危ない処理は実行できないようになっている
- 計算量が少なくリソースオーバーヘッドが少ない
ということがあげられます。
ここではeBPF自体の詳細な仕組みの説明はいたしませんが、Linuxカーネルに命令を送る新しい安全なインターフェースができたことでソフトウェアの作り方まで変わりうる革命的な出来事であると言われています。
このあたりを知りたい方はBredan Gregg氏がUbuntu Matstersの基調講演であるA new type of softwareをあたってください。
eBPFのユースケースはネットワークのトレーサビリティ、セキュリティ、パフォーマンス分析などにも広がりeBPFをベースとした新しいツールやベンダも次々に出現しています。
本記事ではeBPFのユースケースの中の一つであるパフォーマンス分析ツールとしての用途を紹介します。
これらはLinux Observabilityとも呼ばれ、まさにデバッグで活躍する道具になります。
bcc, bpftrace
eBPFはフレームワークなのでもちろん自分で実装することができるのですが、バイトコードレベルでの実装になるため、いきなりだと実装の敷居が非常に高いです。そこでBCCやbpftraceといった形でユーザーからはバイトコードを意識しない形で使えるツール群が作られています。
bcc
bccはeBPFの仕組みを使って開発されたツール群の総称でそのほどんとのツールはLinux カーネル4.1以上を必要とします。LinuxのCLI形式でまとめられていて2019年12月現在83個のツールがあります。
下図にあるようにシステムのあらゆるレイヤの分析を可能にするツール群が揃っています。
bpftrace
bpftraceはeBPF技術に基づいた高レベルのフロントエンド言語です。2018年にAlastair Robertsonによって公開されました。
SystemTapやDTraceの後継版だと思っていればおおよそイメージ合ってると思います。
bpftrceは複数のprobeを計測対象（下図）としてその結果について処理を行います。シンプルなものであれば下記のようにワンライナーで書くことができます。指定したプローブで発生したイベントをフックすると、フィルタで指定した条件で、アクションを実行するというかたちで動きます。
使ってみた
Brendan氏がgithubで公開しているWorkshopの内容を実践する形でLinuxのObservabilityを体感してみます。
このworkshopにあるlab001をまずはコードを見ずに実行してみます。
なお、下記のコマンド操作はAWS上でFerora 31を使って実行しました。
$gcc -O0 -o lab001 lab001.c
$./lab001 &
調査スタート
まずはbcc, eBPFを使わずに従来の方法で調査をしてみます。
# vmstat 1 10
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
r b swpd free buff cache si so bi bo in cs us sy id wa st
0 1 0 5693392 168812 1907500 0 0 7 1621 383 835 1 1 76 22 0
0 1 0 5693396 168812 1907508 0 0 0 532 246 501 0 0 50 50 0
0 1 0 5693396 168812 1907508 0 0 0 2544 228 460 0 0 50 50 0
0 1 0 5693396 168812 1907508 0 0 0 536 234 497 0 0 50 50 0
0 1 0 5693396 168812 1907508 0 0 0 532 237 486 0 0 50 50 0
iowaitがCPU50%程度を占めています。
次にコアごとに見てみます。
# mpstat -P ALL 1
Linux 5.3.7-301.fc31.x86_64 (ip-10-7-0-39) 12/22/2019 _x86_64_ (2 CPU)
04:58:28 AM CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
04:58:29 AM all 0.00 0.00 0.00 50.00 0.00 0.00 0.00 0.00 0.00 50.00
04:58:29 AM 0 0.00 0.00 0.00 33.00 0.00 0.00 0.00 0.00 0.00 67.00
04:58:29 AM 1 0.00 0.00 0.00 67.00 0.00 0.00 0.00 0.00 0.00 33.00
04:58:29 AM CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
04:58:30 AM all 0.00 0.00 0.00 49.75 0.00 0.00 0.00 0.00 0.00 50.25
04:58:30 AM 0 0.00 0.00 0.00 33.33 0.00 0.00 0.00 0.00 0.00 66.67
04:58:30 AM 1 0.00 0.00 0.00 66.00 0.00 0.00 0.00 0.00 0.00 34.00
04:58:30 AM CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
04:58:31 AM all 0.00 0.00 0.00 50.00 0.00 0.00 0.00 0.00 0.00 50.00
04:58:31 AM 0 0.00 0.00 0.00 38.38 0.00 0.00 0.00 0.00 0.00 61.62
04:58:31 AM 1 0.00 0.00 0.00 61.62 0.00 0.00 0.00 0.00 0.00 38.38
ここまで見てlab001のプログラムが原因かはわかりませんが、マルチCPUコアを使ってIOを大量にしてそうだ、という状況まではわかりました。
次にプロセスごとのIOを見てみます。
# pidstat -d 1 5 -l
Linux 5.3.7-301.fc31.x86_64 (ip-10-7-0-39) 12/22/2019 _x86_64_ (2 CPU)
06:04:21 AM UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command
06:04:22 AM 0 395 0.00 0.00 0.00 67 jbd2/nvme1n1p1-
06:04:22 AM 0 14461 0.00 136.00 0.00 34 ./lab001
06:04:22 AM UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command
06:04:23 AM 0 395 0.00 0.00 0.00 65 jbd2/nvme1n1p1-
06:04:23 AM 0 14461 0.00 132.00 0.00 32 ./lab001
06:04:23 AM UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command
06:04:24 AM 0 395 0.00 0.00 0.00 67 jbd2/nvme1n1p1-
06:04:24 AM 0 14461 0.00 136.00 0.00 33 ./lab001
06:04:24 AM UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command
06:04:25 AM 0 395 0.00 0.00 0.00 67 jbd2/nvme1n1p1-
06:04:25 AM 0 14461 0.00 132.00 0.00 34 ./lab001
06:04:25 AM UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command
06:04:26 AM 0 395 0.00 0.00 0.00 61 jbd2/nvme1n1p1-
06:04:26 AM 0 14461 0.00 2172.00 0.00 38 ./lab001
Average: UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command
Average: 0 395 0.00 0.00 0.00 65 jbd2/nvme1n1p1-
Average: 0 14461 0.00 541.60 0.00 34 ./lab001
これを見るとlab001が何やら書き込みを（しかもずっと観察していると6秒に1度程度大量の書き込み）をしていることがわかります。
従来の方法だと本番環境でこれ以上の調査をするのは、なかなか難しいかなと思います。
次にeBPFの仕組みを使ったbccを使って調査をしてみます。
# ./biosnoop.py
TIME(s) COMM PID DISK T SECTOR BYTES LAT(ms)
0.000000 jbd2/nvme1n1p1 396 nvme1n1 W 3716912 8192 10.13
0.009870 jbd2/nvme1n1p1 396 nvme1n1 W 3716928 4096 9.78
0.020079 jbd2/nvme1n1p1 396 nvme1n1 W 3672064 4096 10.16
0.029849 lab001 14461 nvme1n1 W 2525368 4096 9.70
0.030500 jbd2/nvme1n1p1 396 nvme1n1 W 3716936 32768 0.58
0.030971 jbd2/nvme1n1p1 396 nvme1n1 W 3717000 4096 0.39
0.039843 lab001 14461 nvme1n1 W 2525376 4096 8.82
0.049854 jbd2/nvme1n1p1 396 nvme1n1 W 3717008 8192 9.96
0.059852 jbd2/nvme1n1p1 396 nvme1n1 W 3717024 4096 9.92
0.069824 lab001 14461 nvme1n1 W 2525376 4096 9.91
0.079877 jbd2/nvme1n1p1 396 nvme1n1 W 3717032 8192 9.99
・・・・
biosnoop はブロックデバイスI/OをIOごとに出力するbccのツールです。これを実行すると上記のように
書き込みI/O が短い間隔でひたすらされていることがわかります。
jdb2/はカーネルプロセスなので、おそらくlab001からの処理を行っているI/O系のプロセスでしょう。
次に、これらのI/Oがどのファイルに対して行われているかをfileslowerというツールで調べてみます。
引数にある0はmsのレイテンシを指定します。
今回は0ms以上で指定しましたが、ここは任意の値を指定でき、指定した時間以上のみ表示することができます。
# ./fileslower.py 0 -p 14461
Tracing sync read/writes slower than 0 ms
TIME(s) COMM TID D BYTES LAT(ms) FILENAME
0.012 lab001 14461 W 128 0.01 lab001.log
0.040 lab001 14461 W 128 0.02 lab001.log
0.071 lab001 14461 W 128 0.02 lab001.log
0.101 lab001 14461 W 128 0.02 lab001.log
0.131 lab001 14461 W 128 0.02 lab001.log
0.161 lab001 14461 W 128 0.02 lab001.log
0.190 lab001 14461 W 128 0.02 lab001.log
0.221 lab001 14461 W 128 0.02 lab001.log
0.251 lab001 14461 W 2097152 0.54 lab001.log
0.361 lab001 14461 W 128 0.01 lab001.log
0.391 lab001 14461 W 128 0.01 lab001.log
0.420 lab001 14461 W 128 0.01 lab001.log
0.450 lab001 14461 W 128 0.01 lab001.log
0.480 lab001 14461 W 128 0.01 lab001.log
0.511 lab001 14461 W 128 0.01 lab001.log
0.541 lab001 14461 W 128 0.01 lab001.log
0.571 lab001 14461 W 128 0.01 lab001.log
0.600 lab001 14461 W 128 0.01 lab001.log
0.630 lab001 14461 W 128 0.01 lab001.log
・・・
fileslowerはカーネルの中のvfs_read(), vfs_write()関数が行うファイルの読み取り/書き込みイベントをトレースします。
lab001は短い時間にlab001.logファイルに大量の書き込みをしていることがわかりました。
また実際のコードも確認してみてください。
上記の例ではごくごく簡単な例でしたが、実際本番環境のプロダクションコードでデバッグが必要な状況を想定すると、その威力は容易に想像できるのはないでしょうか。このディスクI/O以外の例でもCPU、メモリ、ネットワークなどのレイヤで同じような詳細な分析が可能になっています。
まとめ
- クラウドネイティブでは可観測性が大事
- 可観測性にはモニタリングとデバッギングがある
- eBPFの仕組みを使うことでLinux上で安全で低負荷にデバッキングができる