Tutorial: Using BPF in Cloud Native environments
KubeCon + CloudNativeCon Europe 2020 0日目 のセッションである Tutorial: Using BPF in Cloud Native environments
についてです。
- スライド: https://github.com/kinvolk/cloud-native-bpf-workshop/blob/master/slides.pdf
- Workshop 資料: https://github.com/kinvolk/cloud-native-bpf-workshop
00-Getting_Started
minikube 等のインストール作業。
01-Network-Policy-Advisor
Inspektor Gadget *1 を利用して、 各 Pod に着弾した通信を BPF で capture した情報をもとに、 Microservice 間の通信をロギングするコマンド kubectl-gadget network-policy monitor
と、そのログファイルをもとに NetworkPolicy リソースを自動生成する kubectl-gadget network-policy report
コマンドの紹介でした。
事前にデプロイした Inspektor Gadget DaemonSet が Node の kernel の BPF の情報を取得し、kubectl-gadget コマンドはその Pod を Kubernetes API 経由で叩く CLI になっているそうです。
02-Traceloop
syscall のトレースに ptrace ではなく、 BPF を用いた traceloop *2 というツールを開発したという話と、それを Inspektor Gadget から kubectl-gadget traceloop
コマンドで叩けるようにしたという話でした。
デモでは このリンク先の例 のように、実際に cannot open file
エラーが発生する Pod を run したあとに kubectl-gadget traceloop show
コマンドで syscall のトレース結果を取得して原因がすぐ分かるねという内容でした。
03-Snooping_Operations
BCC (BPF Compiler Collection) *3 の一機能である opensnoop
や execsnoop
を Inspektor Gadget から kubectl-gadget execsnoop
, kubectl-gadget opensnoop
コマンドでそれぞれ叩けるようにしたという話でした。
execsnoop のデモは、 kubectl run
された Pod 内で実行されたコマンドを取得するという内容でした。
opensnoop のデモは、 nginx Pod に対し存在しないファイルの http リクエストをした際に opensnoop から nginx がどのパスのファイルを開こうとしたかを確認できるという内容でした。
04-Tracing
これまでの章は Inspektor Gadget の紹介でしたが、この章では Kubernetes API 経由で bpftrace *4 を実行するツールである kubectl-trace *5 の使い方についての話でした。
kubectl trace run
コマンドで bpftrace と同じ expression で同じ操作ができるそうです。
05-Extras
発表中で触れてないので省略。
感想
どれもトラシュー時に役に立ちそうな機能だったので今すぐにでも導入したいと思いました。 また元々 BPF はなんとなく知ってるけど bpftrace 等のツールは使ったことが無かったという状態でしたがこの発表にてそれらの片鱗を知れたのも良かったです、これから積極的に使っていこうと思います。
社内ISUCONに参加しました
先日、社内 ISUCON である N-ISUCON に出場して惨敗しました。とても悔しいので振り返りの意を込めてブログを書くことにしました。
どんな問題だったか
Niita という 某技術情報共有サービス ポエム投稿サイトをお題とした問題です。
トップページにてWebpackで固められたjsが配送され、そこからバックエンドの API を叩いて得られる記事やユーザ情報のjsonを取得して表示するようなアプリケーションでした。バックエンドの初期実装は Python, Ruby, Go, Node.js があり、フロントエンドはWebpackでビルド済みのhtml, css, jsファイルが各1ファイルずつのみありました。
初期構成は以下のような感じでした。
- Ubuntu 18.04 * 3 台
- vCPU 2 core
- Memory 1.7 GB
なお、自分たちのチームは Go 言語を使用したため、以降は Go 言語を前提として話します。
初期スコア : -200 点くらい
とりあえず点数を見て 「・・・マイナス?🤔」 となりました、ただこの時点ではタイムアウトが頻発した結果だと判断し普段どおりに進めていこうとなりました。
とりあえず初期状態で HTTP 配送サーバが Apache でしたので、使い慣れているnginxに移行しました。また、ボトルネック調査のために ISUCON 恒例の以下の作業を行いました。
- nginx のログフォーマットを ltsv にして alp で解析
- MySQL にスロークエリログを吐かせて pt-query-digest で解析
- アプリケーションに pprof を追加
11:00 ハッシュを標準ライブラリを用いて実装 : -3000 点くらい
pprofを見ると、ユーザ認証で使用する関数内で「生パスワードにソルトを付与してsha256を1000回かける」といった処理をしていた部分が重かったです。当関数内では exec.Command
を使用して外部プロセスで openssl sha256
コマンドを実行していたため、Go言語の sha256 ライブラリを用いて実装をしました。
11:00 は当実装がコミットされた時間ですが、ベンチマーカーが -3000 点という点数を叩き出したため、この後1時間くらいハッシュの実装のプリントデバッグやnginxの移行ミスを疑ったりしてました。ちなみにハッシュの実装に関してはブラウザから実際にログインできるかを確認するだけでよかったと気づいたのは14:30あたりです・・・。
12:00 クエリ改善 : -800 点くらい
自分がハッシュの問題に取り組んでる間に他のチームメンバーが行ってくれました。
/items
のGETのハンドラの処理がとても重く、中を見ると SELECT COUNT(*)
1回で引けるところを SELECT id
を引いて for 文の中で count++
をしていたため、そこの修正を行いました。
なおこの時点ではハッシュ化の実装は当作業ブランチに反映されてません。
13:30 画像ファイルの外出し : -20000 点くらい
ハッシュの実装はまだどこかがサチってるせいだという判断 (今思うと謎判断) で、スロークエリログで一番支配的な箇所であるDBから画像データの取得箇所の改善を行いました。それとこのあたりでDBにインデックスも張りました。
画像データは /users/:username/icon
というパスでアクセスされるため、適当にDBから画像を抜き出す Python スクリプトを書き、/users/:username/icon
へのGETはnginx の try_files
を用いて配送するよう実装しました。また、/users/:username/icon
へのPOSTで画像データがアップロードされるため、当ハンドラで画像データをファイルに書き出す処理を追加しました。
bench 中に dstat を見てると net/total
の send
のカラムで 150~300M という値をずっとウロウロしていて帯域がサチってるのか?となったため、複数台構成にしてみるかとなりました。ここも今思うとそもそもハッシュの実装で -3000 点を出してる時点で問題は別にあると気づくべきでした。ちなみに send が 1Gbps を超えている理由は未だにわかってません (どなたか教えてください🙇)。 追記: GCE は Ingress 10Gbps, Egress 4Gbps (1vCPUあたり 2Gbps) だと教えていただきました! (参考: https://www.slideshare.net/GoogleCloudPlatformJP/cloud-onair-google-networking-deep-dive-201889 の P24)
13:30 - 15:50 お通夜ムード
複数台構成にするとベンチで不整合のエラーが出力されて結局複数台構成には出来ませんでした。後ほどアプリケーションを確認しましたが、ベンチ時にDBのイニシャライズを行う common/db/init.sh
で mysql -h localhost
を指定されていたためこれが原因かもしれません。アプリケーションのsystemdファイルの参照する環境情報ファイルが /home/isucon/.env
だったのでこちらのみを修正して安心しきってました。
その他、アプリケーションを初期バージョンへrevertしてみてどこにバグが混ざったかの確認を行ったりもしました。この時点で既にかなり参っていたため「初期実装が悪いだろーーー」と数回言ったのを覚えています。
15:50 Python実装に切り替え : 208点 (Best Score)
取り敢えず点数出そうと言ってバックエンドの実装を Python に切り替えました。後日スコアサーバを確認したところ上記のスコアでした🙃
感想 (反省)
競技後の懇親会で知りましたが、ベンチの点数が永遠にマイナスな問題はGo言語の初期実装が悪いという「仕様」だったそうです (マニュアルにも、スコアがマイナスになる場合があるがそれは仕様であると書かれてました)。ベンチマーカー的には /users//icon
(/usrs/:username/icon
の :username
が空な場合) は 404 を返す想定だが、今回だと Golang の goji フレームワークのみ /users//icon
は 301 Moved Permanently (/users/icon)
をレスポンスするため無事死亡したみたいです。
個人的には、ベンチのバリデーションチェックが通らない場合は 0点(FAIL) となりエラー原因が出力されましたが、バリデーションチェックに通った場合はエラーしたリクエストの原因が出力されないのが辛かったです。特に上記の /users//icon
のようなリクエストはバリデーションチェック後に来るために競技終了までずっと気づけませんでした・・・。
懇親会にてGo言語を使用した他チームにどうやってこの問題に気づいたかを聞いたところ、kataribe で見たら異様に 301 があったのが怪しかったからと言ってました。自分たちの使用していた alp ではステータスコード出力されてないぞと思い調べてみたら alp がステータスコードを吐くのは v0.4.0 以降だったので、今回の敗因は以下に尽きると思います😇
秘伝のタレ的な初期インストールスクリプトを2年前から使いまわしているせいで alp v0.3.1 をインストールしステータスコードが表示されずに一生 301 に気づけなかったことが本日の敗因です。
— かなた (@kanatakita) September 10, 2019
最後となりますが、とても悔しいですがとても楽しいイベントだったため運営の方々にはとても感謝しています。次回こそ参加者としていい結果を残したいと思いつつ運営もやってみたいなーという気持ちなので次回開催を楽しみにしてます!
ISUCON 9 予選を通過しました!
ISUCON9 予選に 「tmp」 というチーム名で参加し、10,450 点でギリギリ予選を通過することが出来ました。 大学の同期で社会人1年目が2人と修士1年生が1人のチームでした、ISUCON7では学生枠で本戦に出場させてもらいましたが、今回は社会人枠 (?) として予選を通過することが出来たのでとても嬉しいです!
メンバー
最終構成
2台目の Nginx から 1,2,3 台目の App に振り分け、App から 1 台目の MySQL, 3 台目の Redis へそれぞれ振り分けました。AppはGo言語です。
チームでやったこと
以下チームでやったことです。だいたいこの順番でやったはずですが記憶はあいまいです。
序盤
競技が始まってすぐに秘伝のタレと呼ばれる初期設定の反映作業やデプロイツールの配置等を行い、その後は大まかに自分と @ranksai がアプリケーション、@boringsloth がインフラ周りという役割分担でやりました。序盤の流れは学生時代から数回ISUCONの過去問で練習を重ねていたためすんなりと行うことが出来ました。
getNewCategoryItems() の N+1 の改善
getNewCategoryItems()
の中で items の数だけ売り手の情報やカタログの情報を SELECT していた部分が重そうだったので、そこを改善しました。 売り手情報を引っ張ってくる getUserSimpleByID()
の部分は N+1 の 1 のクエリとJOINし、カテゴリ情報を引っ張ってくる getCategoryByID()
の部分は親カテゴリが存在するかを再帰的にチェックする部分を上手くJOINする方法が思いつかなかったため、カテゴリIDからCategoryを引けるmapをキャッシュすることで対応しました。
複数台構成
上記の N+1 を自分と @ranksai がやってる間、@boringsloth が複数台構成にしてくれました。
途中、ポータルサイトの Servers
にベンチ対象となるサーバをすべて登録しないといけない仕様に気付かなかった等いろいろと苦しんでそうだったので、自分はめっちゃ応援 (ひとまかせ) してました!
キャッシュをRedisに
N+1を解消する際にカテゴリをキャッシュしましたが、複数台構成にするにあたりこれをRedisに乗せました。ここは特につまるところなく出来たので個人的に良かったなと思っています。
Index を貼る
ISUCON8の予選でもそうでしたが、今回のベンチは /initialize
に POST が来たときに sql/init.sh
ファイルを別プロセスで実行することでデータベースの初期化を行っていました。
ここで、init.sh
では一度データベースをDropした後にCreateしてデータを注入するため、事前にインデックスが張られていてもベンチが走るたびにインデックスが吹っ飛びます。競技中盤には上記の仕様を把握していたのですが、 sql/init.sh
に足したインデックスを張るコマンドが上手く実行できてない (スクリプトの途中にエラーしてexitしてた?) 問題のせいで競技終了30分前まで思うように点数が伸びなかったです。
競技終了30分前に適切にインデックスを張り、その後30分間でログ出力をやめたりCampaignの値を変えてみたりを行い、最終的に 10,450 点で終了しました。以下は点数の遷移のグラフです。
やれなかったこと
Bcrypt の処理が非常に重いのを観測しましたが、残り時間も少なく特になにも対応できませんでした。競技終了後に感想部屋で、「APIを非同期化する」だったり「複数回benchを回してみて割と決まったユーザからしかログイン要求が来ないので、生パスワードをダンプしてsha256で保存しておく」などのアイデアを見てなるほどなあとなりました。
以下は競技終了直前の pprof です。Bcryptの処理がすごい重い・・・
(pprof) top -cum 30 Showing nodes accounting for 73.48s, 94.29% of 77.93s total Dropped 721 nodes (cum <= 0.39s) Showing top 30 nodes out of 54 flat flat% sum% cum cum% 0.01s 0.013% 0.013% 76.92s 98.70% net/http.(*conn).serve 0 0% 0.013% 76.56s 98.24% goji%2eio.(*Mux).ServeHTTP 0 0% 0.013% 76.56s 98.24% net/http.serverHandler.ServeHTTP 0 0% 0.013% 76.53s 98.20% goji%2eio.dispatch.ServeHTTP 0 0% 0.013% 76.53s 98.20% net/http.HandlerFunc.ServeHTTP 0 0% 0.013% 72.21s 92.66% main.postLogin 0 0% 0.013% 72.03s 92.43% golang.org/x/crypto/bcrypt.CompareHashAndPassword 0 0% 0.013% 72.01s 92.40% golang.org/x/crypto/bcrypt.bcrypt 0.03s 0.038% 0.051% 71.98s 92.36% golang.org/x/crypto/bcrypt.expensiveBlowfishSetup 3.54s 4.54% 4.59% 71.89s 92.25% golang.org/x/crypto/blowfish.ExpandKey 68.42s 87.80% 92.39% 68.42s 87.80% golang.org/x/crypto/blowfish.encryptBlock 0.02s 0.026% 92.42% 1.59s 2.04% main.getNewCategoryItems ...
感想
全体的に「ISUCON」という競技において抑えるところは抑えることが出来たかなと思います。ただここから点数を伸ばすためにはもっと序盤や中盤の実装を早く済ませるための実装力が無いとダメだと個人的に痛感しました。普段からこの手のアプリケーションに触れて、世の中のスーパーなエンジニアを目指しもっと頑張りたいと思います。
余談
もともと競技日は開始30分前に母校の大学に集まってどこかの席を借りてやる予定 (と勝手に思って) ましたが、起床試験にfailした人やらそもそもリモート参加で大学に来ない人やらで朝からわちゃわちゃしてました。開始が10分遅れてくれて結構助かりました・・・。
〆はラーメン (と酒) !