Goでpprofを使ってメモリリークを特定する方法
初めに
仕事で開発しているシステムでメモリリークが発生していたので、pprofでリーク箇所を特定する方法を調査していました。
本記事は自分のメモも含めています。
他にもっと良いやり方や誤りなどがあるかもしれないので、参考程度に見ていただければと思います。
結論
pprofの-diff_baseを使って、2つのプロファイリング結果の差分からメモリリーク箇所を特定できます。
検証
実際に使用したメモリリークのサンプルコードは次になっています。（関数名などは適当）
サンプルコード
package main
import (
"context"
"log"
"net/http"
_ "net/http/pprof"
"time"
)
var m []byte
func watchFile(ctx context.Context) {
for i := 0; i < 1048576; i++ {
m = append(m, 65)
}
log.Println("start watching file")
defer log.Println("end watching file")
ticker := time.NewTicker(1 * time.Second)
for {
select {
case time := <-ticker.C:
println("check file's timestamp", time.Local().Format("2006/01/02 15:04:05"))
case <-ctx.Done():
ticker.Stop()
}
}
}
func main() {
http.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) {
ctx, cancel := context.WithCancel(context.Background())
go watchFile(ctx)
time.AfterFunc(3*time.Second, func() {
cancel()
})
})
log.Println("start http server :8080")
log.Fatal(http.ListenAndServe(":8080", nil))
}
検証結果
次のコマンドを2回実行します。
2回目の実行は初回のログ出力が止まったら行います。
for i in {1..10};do curl localhost:8080; done
初回のコマンド実行した時点のメモリ使用量は9489.30kBになっています。
skanehira@godzilla github.com/skanehira/go-memory-leak-example $ go tool pprof /Users/skanehira/pprof/pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.016.pb.gz
toType: inuse_space
Time: Mar 28, 2022 at 11:44pm (JST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 12564.15kB, 100% of 12564.15kB total
Showing top 10 nodes out of 19
flat flat% sum% cum cum%
9489.30kB 75.53% 75.53% 9489.30kB 75.53% main.watchFile
2562.81kB 20.40% 95.92% 2562.81kB 20.40% runtime.allocm
512.04kB 4.08% 100% 512.04kB 4.08% runtime.bgscavenge
0 0% 100% 512.56kB 4.08% runtime.gopreempt_m
0 0% 100% 512.56kB 4.08% runtime.goschedImpl
0 0% 100% 512.56kB 4.08% runtime.handoffp
0 0% 100% 1025.12kB 8.16% runtime.mcall
0 0% 100% 512.56kB 4.08% runtime.morestack
0 0% 100% 1025.12kB 8.16% runtime.mstart
0 0% 100% 1025.12kB 8.16% runtime.mstart0
2回目コマンド実行した時点のメモリ使用量は23208kBになっています。
skanehira@godzilla github.com/skanehira/go-memory-leak-example $ go tool pprof /Users/skanehira/pprof/pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.017.pb.gz
Type: inuse_space
Time: Mar 28, 2022 at 11:44pm (JST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 27819.46kB, 100% of 27819.46kB total
Showing top 10 nodes out of 25
flat flat% sum% cum cum%
23208kB 83.42% 83.42% 23208kB 83.42% main.watchFile
2562.81kB 9.21% 92.64% 2562.81kB 9.21% runtime.allocm
1536.61kB 5.52% 98.16% 1536.61kB 5.52% time.goFunc
512.04kB 1.84% 100% 512.04kB 1.84% runtime.bgscavenge
0 0% 100% 1536.61kB 5.52% runtime.checkTimers
0 0% 100% 1536.61kB 5.52% runtime.findrunnable
0 0% 100% 512.56kB 1.84% runtime.gopreempt_m
0 0% 100% 512.56kB 1.84% runtime.goschedImpl
0 0% 100% 512.56kB 1.84% runtime.handoffp
0 0% 100% 2561.73kB 9.21% runtime.mcall
(pprof)
-diff_baseを使って差分を確認してみると、初回と2回目の差が13.40MBになっていて、
23208kB(2回目) - 9489.30kB(1回目) = 13718.7kB(13.397168MB) なので、flat値と一致していますね。
つまり、-diff_baseを使って2つの結果を比較した場合のflatが実際に増えたメモリ使用量ということがわかります。
skanehira@godzilla github.com/skanehira/go-memory-leak-example $ go tool pprof -diff_base /Users/skanehira/pprof/pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.016.pb.gz /Users/skanehira/pprof/pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.017.pb.gz
Type: inuse_space
Time: Mar 28, 2022 at 11:44pm (JST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 14.90MB, 121.42% of 12.27MB total
flat flat% sum% cum cum%
13.40MB 109.19% 109.19% 13.40MB 109.19% main.watchFile
1.50MB 12.23% 121.42% 1.50MB 12.23% time.goFunc
0 0% 121.42% 1.50MB 12.23% runtime.checkTimers
0 0% 121.42% 1.50MB 12.23% runtime.findrunnable
0 0% 121.42% 1.50MB 12.23% runtime.mcall
0 0% 121.42% 1.50MB 12.23% runtime.park_m
0 0% 121.42% 1.50MB 12.23% runtime.runOneTimer
0 0% 121.42% 1.50MB 12.23% runtime.runtimer
0 0% 121.42% 1.50MB 12.23% runtime.schedule
0 0% 121.42% 1.50MB 12.23% runtime.stealWork
(pprof)
最後に
-diff_baseはメモリに限らず、2つのprofileを比較してくれるオプションなので、goroutineのリークなども確認できます。
便利ですね。
Author And Source
この問題について(Goでpprofを使ってメモリリークを特定する方法), 我々は、より多くの情報をここで見つけました https://zenn.dev/skanehira/articles/2022-03-29-go-investigation-memory-leak著者帰属：元の著者の情報は、元のURLに含まれています。著作権は原作者に属する。
Collection and Share based on the CC protocol