vegetaを使ったgoaの負荷テストとプロファイリング

データプラットフォームグループの富士谷です。主には、機械学習基盤Livesense Brainの開発や運用を行っています。 Goaで作ったAPIに対して、vegetaを使って、実際のアクセスを模倣した負荷テストと、net/http/pprofによるプロファイリングを最近行いました。net/http/pprofの紹介は数あれど、Goaやvegetaと組み合わせたものはなさそうなので、Livesense BrainでのGoaの活用方法と合わせて紹介します。

はじめに

Livesense Brainでは、A/Bテストの実施を補助するWebアプリケーションを開発・運用しています。このアプリケーションでは、Webサイトやネイティブアプリで使う、A/Bのパターン振り分けのエンドポイントの払い出しや結果の可視化ができます。

made.livesense.co.jp

さらに、事前に計算していたユーザや求人に紐づくレコメンドデータを配信することもできます。

speakerdeck.com

これらの配信のためのAPIは、Goのフレームワークである Goaを用いて実装しています。 Goaは、DSLを使ってAPIを設計すると、ツールがコード生成やOpenAPIのスキーマ生成を行ってくれるため、実装したいものに集中できて便利です。 APIは、Google App Engine上で動作し、DBには、Cloud SQL for PostgreSQLを、そのキャッシュとして、Memorystore for Redisを使っています。

レコメンド配信はWebサイト等で使われているため、かなり大量のアクセスがあるのですが、GoやGAEのオートスケール、Redisのキャッシュなどのおかげで、いまのところ十分な速度で動作しています。しかしながら、時として、キャッシュがうまく効いていないことがあったり、（TechAwardの2021のYARAKASHI。このときはアプリケーションログから判明しました）、また、今後の機能拡張や再構築において、十分高速に動作するか確認する必要が出てきたりもするでしょう。そのような背景から、Goaで作ったAPIに対し、負荷テストとプロファイリングをしてみました。

負荷テストツール

今回のAPIは、Redisのキャッシュを使っていることから、単一のアクセスへの大量アクセスを行っても、「たまたまキャッシュがうまく効いているから早い」という可能性もあり、できるだけ実際のアクセスを模倣した負荷テストを行いたいと考えました。負荷テストやベンチマークのためのツールは様々ありますが、ここでは、手軽にURLのリストを元にしたアタックをかけられるvegetaを使います。

Goaへのpprofの導入

Goaのgetting startedで構築できるプログラムを使って、net/http/pprofのGoaへの導入を説明しようと思います。なお、執筆時点でのGoaのバージョンはv3.7.2です。手順通り行えば動作するプログラムが生成できると思いますが、gRPCは使わないので、DesignのGRPC(func() { })は消しておいて大丈夫です。

また、今回は処理時間に着目してプロファイルしてみますが、サンプルそのままでは動作が速すぎて、プロファイル結果がよくわからなくなるので、Multiplyの計算量も適当に増やしておきます。

func (s *calcsrvc) Multiply(ctx context.Context, p *calc.MultiplyPayload) (res int, err error) {
    result := 0
    for i := 0; i < 10000000; i++ {
        result += p.A * p.B
    }
    return result, nil
}

さて、あとは手順通りcalcが動作するのを確認したところで、pprofを使えるようにします。 pprofのドキュメントにあるように単純にimport _ "net/http/pprof"するだけでは動作しないので、一部コードを書き加えます。 http.goに、このようなコードがあるので見つけます（getting startedで言うと、calcsvr.Mountあたりです）。

その直前に以下を記入します。

mux.Handle("GET", "/debug/pprof/", pprof.Index)
mux.Handle("GET", "/debug/pprof/cmdline", pprof.Cmdline)
mux.Handle("GET", "/debug/pprof/profile", pprof.Profile)
mux.Handle("GET", "/debug/pprof/symbol", pprof.Symbol)
mux.Handle("GET", "/debug/pprof/trace", pprof.Trace)
mux.Handle("GET", "/debug/pprof/heap", pprof.Handler("heap").ServeHTTP)
mux.Handle("GET", "/debug/pprof/allocs", pprof.Handler("allocs").ServeHTTP)
mux.Handle("GET", "/debug/pprof/mutex", pprof.Handler("mutex").ServeHTTP)
mux.Handle("GET", "/debug/pprof/block", pprof.Handler("block").ServeHTTP)

このあと、calcをbuildしなおして立ち上げてください。

go build ./cmd/calc && go build ./cmd/calc-cli && ./calc

単一URLに対する負荷テスト

まずは動作確認のため、単一URLへの負荷テストを行います。以下のコマンドを発行し、30秒間、プロファイラを稼働させておきます。

go tool pprof -http=":8081" "http://localhost:8000/debug/pprof/profile?seconds=30"

その間に、vegetaでリクエストを送ります。

echo 'GET http://localhost:8000/multiply/1/2' | vegeta attack -duration=10s -max-workers=10 -rate=10 | tee results.bin | vegeta report

その後、実行結果が確認できます。数msで動いていますね。

Requests      [total, rate, throughput]         100, 10.10, 10.09
Duration      [total, attack, wait]             9.908s, 9.899s, 9.195ms
Latencies     [min, mean, 50, 90, 95, 99, max]  5.696ms, 8.585ms, 8.832ms, 9.18ms, 9.213ms, 11.517ms, 13.116ms
Bytes In      [total, mean]                     900, 9.00
Bytes Out     [total, mean]                     0, 0.00
Success       [ratio]                           100.00%
Status Codes  [code:count]                      200:100
Error Set:

vegetaでレイテンシがどんな推移をしたか、プロットさせることも可能です。

cat results.bin | vegeta plot > plot.html
open plot.html

さて、プロファイラの起動から、30秒が経過すると、自動的にブラウザが開かれ、pprofの結果が表示されます。Multiplyが大きいですね。

VIEW -> Flame Graphを使うとわかりやすく、Multiplyで時間がかかっているのがわかります。

アクセスログを使った負荷テスト

さて、ここからは、実際のアクセスログを元にした負荷テストを行ってみたいと思います。実際のシステムを使っているので、そのあたりは少し改変して書いています。

アクセスログの取得

APIはGAEで動いているので、Cloud Loggingでログが蓄積されています。今回は、GETメソッドを対象にログを取得して、これを順次アクセスしてもらいます。 Cloud Loggingのログエクスプローラーで、このようなクエリを入力し、実行後、JSONでダウンロードします。

resource.type="gae_app"
resource.labels.module_id="optimizer-api"
resource.labels.version_id="v0-0-1"
protoPayload.status=200
protoPayload.method="GET"
protoPayload.resource=~"/dummy/resource"

負荷テスト

GET http://... というような行を並べたファイルを準備し、これをvegetaに渡して順次アクセスしてもらいます。まずは、ダウンロードしたJSONとjqを使って、リクエストのリストを作ります。

$ cat ./downloaded-logs.json | jq -c '.[].protoPayload.resource' | sed 's/\"//g' | sed 's/^/GET http:\/\/localhost:8000/g' > request.txt

中身は例えばこんな感じです。

GET http://localhost:8000/dummy/resource?item=1
GET http://localhost:8000/dummy/resource?item=2
GET http://localhost:8000/dummy/resource?item=3

プロファイリングを取るAPIサーバをローカルで立ち上げます。その後、pprofを立ち上げます。

$ go tool pprof -http=":8081" "http://localhost:8000/debug/pprof/profile?seconds=30"

先程作ったファイルを用いて、vegetaでアタックさせます。与えたリストの上から順番にアクセスして、最後まで行けばもう一度上から順にアクセスします。何度も同じURLにアクセスすることになるので、実際よりも比較的Redisのキャッシュが効くようなアクセス方法ですが、ここは許容します。

$ cat request.txt | vegeta attack -duration=10s -max-workers=10 -rate=10 | tee results.bin | vegeta report

-duration(実行時間)や-rate(秒間のアクセス回数)を調整して実行してみたところ、ある試行では、以下のような結果が表示されました。一部実装はちょっと隠しています。結果を見る限り、RedisとDB関連の処理が中心のようで、今の実装には、大きなボトルネックはなさそうなことがわかりました。