バックエンドサーバーのメモリリークに遭遇
ある日CloudRunのログでこんなエラーに遭遇しました。
Memory limit of 512 MiB exceeded with 518 MiB used. Consider increasing the memory limit, see https://cloud.google.com/run/docs/configuring/memory-limits
なんだこれ？と思ってメモリ使用率の推移を見てみると、、、
メモリ使用量が徐々に増えていって、100%に到達した時点でガクンと下がっています。これぞメモリリーク！っていう動きをしていますね。
幸い即時に対応せずとも問題ないバックエンドサーバーだったので、落ち着いて調査を進めていくことにしました。
みなさんもメモリリークの調査を体験しませんか？
ではどこでメモリリークをしているのか？それを知る必要があります。
この記事ではそれの具体的な調査方法を説明します。
みなさんにもこの調査を追体験していただけるけるように、この記事で使っているサンプルコードをGitHubに置いておきます。 良かったら試してみてください！
メモリリークするコードとプロファイリング設定の例
サンプルコードではHTTPリクエストのハンドラーとして以下を実装しています
func leakTestHandler(w http.ResponseWriter, r *http.Request) {
ctx := r.Context()
app, err := firebase.NewApp(ctx, nil)
if err != nil {
log.Fatalf("error initializing app: %v\n", err)
}
_, err = app.Auth(ctx)
if err != nil {
log.Fatalf("error initializing auth client: %v\n", err)
}
// do something
w.WriteHeader(http.StatusOK)
w.Write([]byte("OK"))
}
ほぼネタバレ状態なので言ってしまうと、app.Auth()が今回のメモリリークの原因です。
ではどういった方法で app.Auth() がメモリリーク箇所だと判断するか？ですね。
Goにはこういった問題のための "net/http/pprof" というプロファイリングツールが用意されています。
これを有効にするために、main関数は以下のように実装しました。
func main() {
http.HandleFunc("/leak-test", leakTestHandler)
http.HandleFunc("/debug", pprof.Index)
// Start the HTTP server
log.Println("Starting server on :8080")
if err := http.ListenAndServe(":8080", nil); err != nil {
log.Fatalf("Failed to start server: %v", err)
}
}
※詳細はサンプルコードを御覧ください
メモリリークを発生させる
調査のためにメモリリークを発生させます。
まずはバックエンドサーバーの起動です。
ローカルで起動できるので、以下の様にコマンドを実行します。
-> % go run main.go
2025/05/12 13:18:47 Starting server on :8080
次にメモリリークを起こすエンドポイントに大量のリクエストを送信します。
-> % for ((i=0; i<1000; i++)); do curl -X POST http://localhost:8080/leak-test -i; done
HTTP/1.1 200 OK
Date: Mon, 12 May 2025 04:51:21 GMT
Content-Length: 2
Content-Type: text/plain; charset=utf-8
OKHTTP/1.1 200 OK
Date: Mon, 12 May 2025 04:51:21 GMT
Content-Length: 2
Content-Type: text/plain; charset=utf-8
~~ 以下略 ~~
これで開放されないメモリが溜まり続ける状態になっているはずです。
調査開始！！
やっと準備が整ったのでメモリリークの調査を開始します！
どのくらいメモリが占有されているか見てみましょう。
以下のコマンドで計測されたメモリの使用状況を leak-test.prof というファイルに出力します。
-> % curl -o leak-test.prof http://localhost:8080/debug/pprof/heap
このファイルを分析するために以下のコマンド実行します。
-> % go tool pprof leak-test.prof
File: main
Type: inuse_space
Time: 2025-05-12 13:55:21 JST
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)
この状態で top と打つと、メモリ使用量の多い関数が表示されます
(pprof) top
Showing nodes accounting for 9223.68kB, 85.72% of 10759.77kB total
Showing top 10 nodes out of 61
flat flat% sum% cum cum%
2052kB 19.07% 19.07% 2052kB 19.07% runtime.allocm
1536.12kB 14.28% 33.35% 1536.12kB 14.28% go.opentelemetry.io/otel/internal/global.(*meter).Int64Counter
1024.09kB 9.52% 42.87% 1024.09kB 9.52% runtime.acquireSudog
1024.08kB 9.52% 52.38% 1024.08kB 9.52% go.opentelemetry.io/otel/internal/global.(*meter).Float64Histogram
1024.03kB 9.52% 61.90% 4096.23kB 38.07% go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp.(*Transport).createMeasures
513kB 4.77% 66.67% 513kB 4.77% cloud.google.com/go/monitoring/apiv3/v2/monitoringpb.init
513kB 4.77% 71.44% 513kB 4.77% github.com/envoyproxy/go-control-plane/envoy/service/status/v3.init
512.88kB 4.77% 76.20% 512.88kB 4.77% google.golang.org/protobuf/internal/filedesc.(*File).initDecls (inline)
512.25kB 4.76% 80.96% 512.25kB 4.76% cloud.google.com/go/internal/btree.init
512.23kB 4.76% 85.72% 1025.11kB 9.53% google.golang.org/protobuf/internal/filedesc.newRawFile
runtime.allocm はGoランタイム内部で使用されているメモリに関する情報のようなので、それ以外に着目します。
すると go.opentelemetry.io/otel/internal/global.(*meter).Int64Counter というのがメモリを多く使用している事が分かります。
サンプルコードではこの様なメソッドを実装していません。
go.opentelemetry.io とある通り、外部のパッケージのとある関数がメモリを使用しているようです。
メモリを使用している関数がどこから呼ばれているか確認
では go.opentelemetry.io/otel/internal/global.(*meter).Int64Counter がどこから呼ばれているのか確認しましょう。
先ほどの続きに traces .Int64Counter と打つと以下のように表示されます。
(pprof) traces .Int64Counter
File: main
Type: inuse_space
Time: 2025-05-12 13:55:21 JST
-----------+-------------------------------------------------------
bytes: 80B
512.04kB go.opentelemetry.io/otel/internal/global.(*meter).Int64Counter
go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp.(*Transport).createMeasures
go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp.NewTransport
google.golang.org/api/transport/http.addOpenTelemetryTransport (inline)
google.golang.org/api/transport/http.newTransport
google.golang.org/api/transport/http.NewClient
google.golang.org/api/transport.NewHTTPClient (inline)
firebase.google.com/go/v4/auth.NewClient
firebase.google.com/go/v4.(*App).Auth
main.leakTestHandler
net/http.HandlerFunc.ServeHTTP
net/http.(*ServeMux).ServeHTTP
net/http.serverHandler.ServeHTTP
net/http.(*conn).serve
-----------+-------------------------------------------------------
見知った関数名が見えますね
firebase.google.com/go/v4.(*App).Auth
main.leakTestHandler
これでメモリリークの原因が leakTestHandler() 内で呼ばれている app.Auth() だと判明しました。
メモリリークの原因箇所を修正した結果
以上のように、今回のメモリリークの原因は app.Auth() ということが分かりました。
この関数は auth.Client を生成する機能を持っていますが、HTTPリクエストのたびに呼び出す使い方に問題があったようです。
そのためバックエンドサーバーを起動するタイミングで app.Auth() を使い、リクエスト間で auth.Client を共有する実装にしました。
こうすれば app.Auth() を呼び出すのは1回で済むので、メモリリークの問題は解決します。
実際に修正を加えた後のメモリ使用量を確認すると、10%未満で推移しています。
開放されないメモリの蓄積がなくなり、メモリリークが解消していることが分かります。
まとめ
今回は "net/http/pprof" を使うことで、メモリリークの原因が自分たちのコードのどこなのか特定する方法をご紹介しました。
私もこのような調査をやったのは今回が始めてでした。
始めは "net/http/pprof" の使い方もよくわからず、疑心暗鬼になりながら調査を進めていました。
ですが一度やってしまえば、今後は効率よく調査を進められそうです。
みなさんも一度体験して、このツールの使い方をしっかり抑えておけばどこかで役立つはず！
サンプルコードもあるので、皆さんのローカルでも是非試してみてください！
Discussion