こんにちは。バクラクビジネスカードでエンジニアをしている @onsd_ です。最近はランニングを始めて、皇居周りだったり山だったりいろいろ走っております。Strava 友達募集中です。
この記事は LayerXテックアドカレ 31日目の記事です。 前回はkikuchyさんによる なぜバクラク申請・経費精算はFlutterでアプリの作り直しをしているのか でした。アプリを作り直す理由がLayerXらしいなぁと思いました。興味がある方はぜひそちらもご覧ください！ 次回は ar_tamaさんが担当されます。お楽しみに！
この記事では、アプリケーションサーバで起きた問題について調査した手順を残します。ツールを使って調査を進める方法について参考になれば嬉しいです。
開発環境でのみ起きるOOM
アプリケーションの処理として、ファイルを受け取り S3 にアップロードするという処理があります。
この処理について、まず受け取れるファイルサイズの上限を引き上げる対応をしました。 （※ GraphQLサーバを実装するために、gqlgen を利用しています）
srv.AddTransport(transport.MultipartForm{
- MaxUploadSize: 50 * 1 << 20, // 50MB,
- MaxMemory: 50 * 1 << 20, // 50MB,
+ MaxUploadSize: 80 * 1 << 20, // 80MB,
+ MaxMemory: 80 * 1 << 20, // 80MB,
})
上限を引き上げ、手元でファイルをアップロードしたところ正常に動作していそうでした。 そのため、マージして様子を見ていたところ、たまにECSのタスクが死んでいる事に気づきました。
開発環境でファイルをアップロードしてみると、50MBのファイルでは問題ないのですが、80MBのファイルをアップロードすると 500 が返ってくる、といった挙動を示していました。
コンテナのログをみてみるとOOMでタスクが終了されていた事がわかったので、調査してみることにしました。
調査：誰がメモリを使っている？
メモリの使用率を計測するため、今回は profile を使ってメモリのプロファイリングをすることにしました。
profile は、計測でよく使われる pprof を使いやすいようにラップしたライブラリです。
次のように、import して main関数の一番上で呼び出します。
diff --git a/cmd/api/main.go b/cmd/api/main.go index 024d3e37..7609ffa3 100644 --- a/cmd/api/main.go +++ b/cmd/api/main.go @@ -24,6 +24,7 @@ import ( + "github.com/pkg/profile" ) @@ -32,6 +33,8 @@ import ( func main() { + defer profile.Start(profile.MemProfile).Stop() // メモリの計測をする
この状態でアプリケーションを動作させると、次のように何の計測が有効になっているかと、プロファイリング結果のパスが表示されます。
$ go build ./cmd/api/...
$ ./api
2023/06/21 09:49:12 profile: memory profiling enabled (rate 4096), /var/folders/w4/hsgyyx5508b60xcvtnzhk1hr0000gn/T/profile4014285411/mem.pprof
ここで、80MB のファイルをアップロードしてから、プロファイリング結果をみてみることにしました。
結果の解析には、 go tool pprof コマンドが利用できます。
# go tool pprof <path-to-binary> <path-to-profile-output>
$ go tool pprof api /var/folders/w4/hsgyyx5508b60xcvtnzhk1hr0000gn/T/profile369504276/mem.pprof
File: api
Type: inuse_space
Time: Jun 21, 2023 at 9:53am (JST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 154.14MB, 99.61% of 154.75MB total
Dropped 388 nodes (cum <= 0.77MB)
Showing top 10 nodes out of 37
flat flat% sum% cum cum%
154.14MB 99.61% 99.61% 154.14MB 99.61% io.ReadAll
0 0% 99.61% 60.19MB 38.89% github.com/99designs/gqlgen/graphql/executor.(*Executor).DispatchOperation.func1.1
0 0% 99.61% 60.19MB 38.89% github.com/99designs/gqlgen/graphql/executor.(*Executor).DispatchOperation.func1.1.1
0 0% 99.61% 60.19MB 38.89% github.com/99designs/gqlgen/graphql/executor.aroundRespFunc.InterceptResponse
0 0% 99.61% 60.19MB 38.89% github.com/99designs/gqlgen/graphql/executor.processExtensions.func2
0 0% 99.61% 60.21MB 38.91% github.com/99designs/gqlgen/graphql/executor.processExtensions.func3
0 0% 99.61% 60.21MB 38.91% github.com/99designs/gqlgen/graphql/executor.processExtensions.func4
0 0% 99.61% 60.19MB 38.89% github.com/99designs/gqlgen/graphql/executor.processExtensions.func6
0 0% 99.61% 60.19MB 38.89% github.com/99designs/gqlgen/graphql/executor.processExtensions.func6.1
0 0% 99.61% 154.20MB 99.64% github.com/99designs/gqlgen/graphql/handler.(*Server).ServeHTTP
これをみると、 io.ReadAll がメモリを使っていることがわかりました。
io.ReadAll は、対象のファイルをメモリにすべて読み込みます。では、80MB弱のファイルを読み込んだだけでなぜ 154.14MB 使用したことになってしまうのでしょうか。
ソースコードを io.ReadAll で検索すると、S3 にアップロードする処理で利用していることがわかりました。今回は、s3Manager を利用して、 io.Reader のまま処理する方向で修正しました。
// コード例
func Upload(ctx Context.Context, body io.Reader) (string, error) {
id := ulid.MustNew()
s3Key := "some-path-s3-" + id
- bodyBytes, err := io.ReadAll(body)
+ uploader := s3manager.NewUploaderWithClient(app.GetS3())
+ _, err := uploader.Upload(&s3manager.UploadInput{
+ Body: body,
+ Bucket: &bucket,
+ Key: &s3Key,
+ })
if err != nil {
return "", err
}
- if err := aws.PutS3Object(bucket, s3Key, bytes.NewReader(bodyBytes), contentType); err != nil {
- app.LogError(ctx, err).Send()
- return "", err
- }
return s3Key, nil
}
}
この変更を適応した後、再度ファイルアップロードを行い、計測を行いました。
$ go tool pprof api /var/folders/w4/hsgyyx5508b60xcvtnzhk1hr0000gn/T/profile3099273002/mem.pprof
File: api
Type: inuse_space
Time: Jun 21, 2023 at 10:03am (JST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 75.19MB, 99.44% of 75.61MB total
Dropped 271 nodes (cum <= 0.38MB)
Showing top 10 nodes out of 17
flat flat% sum% cum cum%
75.19MB 99.44% 99.44% 75.19MB 99.44% io.ReadAll
0 0% 99.44% 75.19MB 99.45% github.com/99designs/gqlgen/graphql/handler.(*Server).ServeHTTP
0 0% 99.44% 75.19MB 99.44% github.com/99designs/gqlgen/graphql/handler/transport.MultipartForm.Do
どうやら、他にも io.ReadAll を使っている箇所があるようです。
調査：誰が io.ReadAll を呼んでいる？
この段階で、ソースコード上で io.ReadAll が利用されている箇所はありませんでした。
そういった場合の調査に役立つのが、pprof の -png オプションです。
このオプションをつけて実行することで、関数の呼び出し順が図で表示されます。
$ go tool pprof -png api /var/folders/w4/hsgyyx5508b60xcvtnzhk1hr0000gn/T/profile3099273002/mem.pprof > pprof2.png
この図を見ると、ServeHTTP が呼んでいる MultipartForm.Do のなかで io.ReadAll が呼ばれていることがわかります。
MultipartForm.Doの実装を読むと、 MultipartForm.maxMemory とアップロードされたファイルの Content-Length を比較して挙動が変わるようになっていました。
- Content-Length の方が大きい場合は、一時ファイルを作成してそこに書き込まれます。
- Content-Length の方が小さい場合は、io.ReadAll を利用してメモリにコピーされます。
今回、80MiB まで受け付ける対応をした時に、maxMemory も増やす対応をしていました。
そのため、大きいファイルがメモリへコピーされるようになりましたが、定義されていたECSのタスクのメモリでは小さかったというのがOOMの原因のようでした。
ここまでわかったので、タスクのメモリを増やす対応を行いました。
おわりに
OOMが起きた！というときに、なぜOOMが起きたのか？をプロファイリングツールを利用することで根拠を持って改善ができたのは良い体験でした。 また、コードを追って行くことで理解も深まったため、一石二鳥でした。
ちなみに Fact Base とは、弊社の行動指針です。 こちらにも興味がある方は、ぜひ LayerX 羅針盤 を御覧ください。
ハタラクをバクラクにするプロダクトを一緒に開発していきたい人を大募集中です！ もしご興味ありましたら、ぜひカジュアル面談からお話させてください！
LayerX Casual Night というお酒を飲みながらカジュアル面談よりカジュアルにゆる～く話せるイベントも開催しておりますので、ぜひご参加ください！
