こんにちは、株式会社モリサワのシステム開発部門の田中（さ）です。
Morisawa Fontsというフォントライセンスサービスの開発を担当しています。
Morisawa FontsのBackendはGoで実装しています。先日、Goで発生したメモリリークを解決するために、プロファイラ pprof を使ってみました。その方法を紹介します。
メモリリーク発生
とある日のデプロイ後にこんなことがありました。
以下はCloudWatchのグラフです。デプロイ作業を実施後、Backend HTTPサーバーのメモリ使用量が増加し続けて止まらない事象が発生しました。
データベースの情報をインメモリにキャッシュしているため、デプロイ直後はメモリ使用量がゼロになり、その後40%程度で止まるはずでした。これは想定外です。
利用者へ悪影響が出る前に対策は実施しましたが、さらに根本解決のために原因を調査します。
Goのプロファイラ
これはどこかでメモリリークしている可能性が高そうです。Goにはガベージコレクション(GC)がありますが、参照がどこかに残っていると、当然ながらシステムはメモリを解放しません。
Goには標準ライブラリに pprof というプロファイラが用意されています。これを使ってメモリを計測します。
pprof には下の2つのパッケージがあります。今回はHTTPサーバーになるため後者を利用します。
-
runtime/pprof（任意のプログラムで動かす用） -
net/http/pprof（HTTPサーバーで動かす用）
pprofを動かす
適当にメモリリークさせるサンプルコードを書きます。
下のコードは http://localhost:8000/ にアクセスすると "Hello" と表示されますが、実は裏でメモリがリークするプログラムです。
package main
import (
"fmt"
"net/http"
_ "net/http/pprof" // pprof を使うためのおまじない
)
var arr []int
func handler(w http.ResponseWriter, r *http.Request) {
// なんかよくわからない処理
for n := 0; n < 100000; n++ {
arr = append(arr, n)
}
// Helloと表示する
fmt.Fprintf(w, "Hello")
}
func main() {
http.HandleFunc("/", handler)
err := http.ListenAndServe("localhost:8000", nil)
if err != nil {
panic(err)
}
}
Go標準のHTTPサーバーで pprof を動かすにはパッケージを import するだけ [1] で使えます。
サーバーを起動してアクセスすると、 "Hello" が返ってきました。
% curl http://localhost:8000/
Hello
このままブラウザで http://localhost:8000/debug/pprof/ にアクセスすると、下のような画面が表示されます。
メモリの状態を見たいので heap の画面を開きます。
これは人の目で見るものではなさそうです。。
コマンドラインのツールを使う
コマンドラインでは go tool pprof を使います。オプションを省略すると対話モードになります。ここでは非対話モードで使います。
下のように -top オプションを指定して叩くと、メモリを使用している順に表示します。出力された表の flat の値が実際に使っているメモリの量になります。
また、 ~/pprof 以下にプロファイル結果 *.pb.gz を保存してくれます。こちらのファイルは後ほど比較で使います。
% go tool pprof -top http://localhost:8000/debug/pprof/heap
Fetching profile over HTTP from http://localhost:8000/debug/pprof/heap
Saved profile in /Users/stanaka/pprof/pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.001.pb.gz
Type: inuse_space
Time: Nov 29, 2022 at 5:13pm (JST)
Showing nodes accounting for 3622.04kB, 100% of 3622.04kB total
flat flat% sum% cum cum%
1537.69kB 42.45% 42.45% 1537.69kB 42.45% runtime.allocm
1060.10kB 29.27% 71.72% 1060.10kB 29.27% main.handler
512.20kB 14.14% 85.86% 512.20kB 14.14% runtime.malg
512.05kB 14.14% 100% 512.05kB 14.14% runtime.main
（以下省略）
シェルで for を使って、サーバーを100回叩きます。
$ for ((i=0; i<100; i++)); do curl http://localhost:8000/; done
HelloHelloHelloHelloHelloHelloHelloHelloHelloHelloHelloHell......
もう一度、 go tool pprof を叩くと結果が変わりました！
100回アクセスしただけで、メモリを90MBも使っています。
$ go tool pprof -top http://localhost:8000/debug/pprof/heap
Fetching profile over HTTP from http://localhost:8000/debug/pprof/heap
Saved profile in /Users/stanaka/pprof/pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.002.pb.gz
Type: inuse_space
Time: Nov 29, 2022 at 5:14pm (JST)
Showing nodes accounting for 90.11MB, 100% of 90.11MB total
flat flat% sum% cum cum%
86.61MB 96.11% 96.11% 86.61MB 96.11% main.handler
2.50MB 2.78% 98.89% 2.50MB 2.78% runtime.allocm
0.50MB 0.56% 99.45% 0.50MB 0.56% runtime.malg
0.50MB 0.55% 100% 0.50MB 0.55% runtime.main
（以下省略）
これはシンプルなプログラムなので原因がどこかは自明ですが、上で保存した2つのプロファイル結果 *.pb.gz を -diff_base オプションで指定すると差分を表示できます。
% go tool pprof -top -diff_base pprof/pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.001.pb.gz pprof/pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.002.pb.gz
Type: inuse_space
Time: Nov 29, 2022 at 5:13pm (JST)
Showing nodes accounting for 86.58MB, 2447.60% of 3.54MB total
flat flat% sum% cum cum%
85.57MB 2419.30% 2419.30% 85.57MB 2419.30% main.handler
（以下省略）
main.handler 関数が悪さをしているようですね。
さらに -list (関数名) オプションを使うと、コードのどこでメモリを確保しているかを指摘してくれます。
% go tool pprof -list main.handler -diff_base pprof/pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.001.pb.gz pprof/pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.002.pb.gz
Total: 3.54MB
ROUTINE ======================== main.handler in /Users/stanaka/project/go/sample/main.go
85.57MB 85.57MB (flat, cum) 2419.30% of Total
. . 9:var arr []int
. . 10:
. . 11:func handler(w http.ResponseWriter, r *http.Request) {
. . 12: // なんかよくわからない処理
. . 13: for n := 0; n < 100000; n++ {
85.57MB 85.57MB 14: arr = append(arr, n)
. . 15: }
. . 16:
. . 17: // Helloと表示する
. . 18: fmt.Fprintf(w, "Hello")
. . 19:}
最初のコードの14行目 arr = append(arr, n) でメモリを大量に確保したまま解放されていないことが判明しました！
おわりに
pprof を使ってGoのプログラムのメモリを計測して、メモリリークしている箇所を見つける方法について紹介しました。pprofはメモリの他にもCPUやgoroutineの状態など、さまざまなパフォーマンス情報を収集できます。
なお、元々のメモリリークの原因はサードパーティーのライブラリをバージョンアップしたことによるエンバグでした。メモリリークの原因を探し出すのは大変でしたが、Go標準で提供してくれているツールのおかげで助かりました。
同様の現象で困っている方々の参考になれば幸いです。
おまけ
ChatGPTくんに上のコードの問題点を尋ねたら一瞬で解決しました🤖
-
ginなどのフレームワークを使っている場合にはこれだけでは不十分なことがあります。例えば、ginであれば
github.com/gin-contrib/pprofというミドルウェアが用意されています。 ↩︎
Discussion