pprof で見つけた OOM の真相 #layerxgo

https://layerx.connpass.com/event/319314/ の登壇資料です

P8,9 の説明が誤っていたので修正しました。
おりさのさん、ご指摘ありがとうございました。とても勉強になりました。
(https://x.com/onsd_/status/1809052937693581615)

Transcript

1. © LayerX Inc. pprof で見つけたOOMの真相 2024/07/04 layerx.go #1 Takamichi Omori @onsd_
2. © LayerX Inc. 2 X: たか @onsd_ 画像を入れてね 自己紹介 Takamichi Omori バクラク事業部 バクラクビジネスカード ->AI-UX開発チーム　エンジニア Go / TypeScript でプロダクト開発をやっています 趣味 - バスケットボール 🏀 - フリースタイルスキー 🎿 - リアル脱出ゲーム・謎解き 🤯
3. © LayerX Inc. 3 - プロファイリングツールを使ってアプリケーションのOOMの原因を調査する方法をご紹介 - この話はブログ記事が元になっております - pprof を使って Fact Base に改善を行った話 - LayerX Engineer Blog - https://tech.layerx.co.jp/entry/2023/12/08/123529 今日話すこと はじめに
4. © LayerX Inc. 4 背景 はじめに - バクラクビジネスカードは 99designs/gqlgen を使ってGraphQLサーバを実装している - ユーザからファイルを受け取り、S3にアップロードする機能がある - タスク：ファイルサイズの上限が 50MB だったところ、80MB にしたい - ちなみに、ファイル上限サイズのデフォルトは32MB srv.AddTransport(transport.MultipartForm{ - MaxUploadSize: 50 * 1 << 20, // 50MB, - MaxMemory: 50 * 1 << 20, // 50MB, + MaxUploadSize: 80 * 1 << 20, // 80MB, + MaxMemory: 80 * 1 << 20, // 80MB, })
5. © LayerX Inc. 5 背景 はじめに - 手元で動作確認して、良さそうだったのでマージ - 様子を見ていたところ、たまに500レスポンスを返していることが判明 - 80MB弱のファイルをアップロードすると500が返ってくる... - コンテナのログをみると、OOMで死んでいた - OOMの原因を pprof をつかって調査することに
6. © LayerX Inc. 6 pprof とは 調査１：どこでメモリが使われている？ - パフォーマンス分析や最適化に利用されるプロファイリングツール - https://github.com/google/pprof - 分析できるもの - CPUの使用状況 - メモリの使用状況 - ゴルーチンの動作状況など - 利用方法 - runtime/pprof パッケージを使ってプロファイルデータをファイルに出力 - net/http/pprof パッケージを使って HTTP 経由でプロファイルデータを取得 - go tool pprof コマンドを使ってプロファイルデータの解析・可視化ができる - プロファイルデータは protobuf のフォーマットで保存される - https://github.com/google/pprof/blob/main/proto/profile.proto
7. © LayerX Inc. 7 調査１：どこでメモリが使われている？ 調査１：どこでメモリが使われている？ - どこでメモリを使っているかの調査のため、 プロファイリングツールを使って計測することにした - プロファイリングツールとしてはnet/http/pprof を利用 - この状態で実行すると、各種プロファイリングが始まる import ( + _ "net/http/pprof" ) func main() { + go func() { + log.Println(http.ListenAndServe("localhost:6060", nil)) + }() + // 既存のアプリケーションの処理 ︙ }
8. © LayerX Inc. 8 メモリの使用量をみる 調査１：どこでメモリが使われている？ - メモリを多く使っている関数から見たかったので -top を指定 ❯ go tool pprof -top http://localhost:6060/debug/pprof/heap Fetching profile over HTTP from http://localhost:6060/debug/pprof/heap Saved profile in /Users/takamichi.omori/pprof/pprof.main.alloc_objects.alloc_space.inuse_objects.inuse_space.002.pb.gz File: main Type: inuse_space Time: Jun 27, 2024 at 6:10pm (JST) Showing nodes accounting for 130.82MB, 96.61% of 135.42MB total Dropped 67 nodes (cum <= 0.68MB) 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
9. © LayerX Inc. 9 io.ReadAll を使っている場所の修正 調査１：どこでメモリが使われている？ - 受け取ったファイルをメモリ上に展開し、S3 に対して put していた - aws-sdk-go の s3manager を利用するように修正 - 余分にバッファコピーしてメモリを消費することを防ぐ // コード例（修正前） func UploadToS3(ctx Context.Context, body io.Reader) (string, error) { id := ulid.MustNew() s3Key := "some-path-s3-" + id - bodyBytes, err := io.ReadAll(body) - 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 }
10. © LayerX Inc. 10 io.ReadAll を使っている場所の修正 調査１：どこでメモリが使われている？ - 受け取ったファイルをメモリ上に展開し、S3 に対して put していた - aws-sdk-go の s3manager を利用するように修正 - 余分にバッファコピーしてメモリを消費することを防ぐ // コード例（修正後） func UploadToS3(ctx Context.Context, body io.Reader) (string, error) { id := ulid.MustNew() s3Key := "some-path-s3-" + id + uploader := s3manager.NewUploaderWithClient(app.GetS3()) + if _, err := uploader.Upload(&s3manager.UploadInput{ + Body: body, + Bucket: &bucket, + Key: &s3Key, + }); err != nil { + return “”, err + } return s3Key, nil }
11. © LayerX Inc. 11 変更後のメモリの使用量は？ 調査１：どこでメモリが使われている？ - io.ReadAll を使わないようにしたあと、再度計測 ❯ go tool pprof -top http://localhost:6060/debug/pprof/heap Fetching profile over HTTP from http://localhost:6060/debug/pprof/heap Saved profile in /Users/takamichi.omori/pprof/pprof.main.alloc_objects.alloc_space.inuse_objects.inuse_space.002.pb.gz File: main Type: inuse_space Time: Jun 27, 2024 at 6:10pm (JST) Showing nodes accounting for 130.82MB, 96.61% of 135.42MB total 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
12. © LayerX Inc. 12 調査2：だれが io.ReadAll を呼んでいる？ 調査2：だれが io.ReadAll を呼んでいる？ - まだ io.ReadAll が呼ばれているらしいので、どこで呼んでいるか調査 - この時点でソースコード上に io.ReadAll は存在しない - 視覚的に呼び出しを追うために、pprof の -png オプションを使う - 関数の呼び出し順を示した図が出力される ❯ go tool pprof -png http://localhost:6060/debug/pprof/heap Fetching profile over HTTP from http://localhost:6060/debug/pprof/heap Saved profile in /Users//pprof/pprof.main.alloc_objects.alloc_space.inuse_objects.inuse_space.004.pb.gz Generating report in profile001.png
13. © LayerX Inc. 13 go tool pprof -png 調査2：だれが io.ReadAll を呼んでいる？ io ReadAll 75.19MB(99.44%) transport MultiPartForm Do handler (*Server) ServeHTTP
14. © LayerX Inc. 14 MultiPartForm.Do 調査2：だれが io.ReadAll を呼んでいる？ - io.ReadAll を呼んでいたのは gqlgen の MultiPartForm.Do - 内部で MultipartForm.maxMemory とファイルサイズを比較し、挙動が変わる - ファイルサイズのほうが大きい場合 - 一時ファイルを作成し、そこに保存 - ファイルサイズのほうが小さい場合 - io.ReadAll を利用してメモリにコピー - 80MBまで受け付ける対応をしたときに、maxMemory も　８０MBに変更した - これに対して、ECSのメモリが小さかったのがOOMの原因 - ここまでわかったのでメモリを増やす対応をした io ReadAll 75.19MB(99.44%) transport MultiPartForm Do handler (*Server) ServeHTTP
15. © LayerX Inc. 15 - OOMがおきた！メモリを増やそう！ではなく、どこがメモリを使っているのか？をきちんと調査して 対応することができた - プロファイリングツールを使うことで、根拠を持った改善ができた - 調査後、fgprof というツールを教えてもらいました - こちらは、pprof では測定できない Off-CPU(I/Oなど) の測定ができるツール - DBアクセス含めたパフォーマンスチューニングをするときに試したい - 利用しているライブラリのコードを読むことで、理解が深まったので一石二鳥だった おわりに おわりに
16. © LayerX Inc. 16 We are hiring!