Goでpprofを使ってメモリリークを特定する方法

初めに

仕事で開発しているシステムでメモリリークが発生していたので、pprofでリーク箇所を特定する方法を調査していました。
本記事は自分のメモも含めています。
他にもっとよいやり方や誤りなどがあるかもしれないので、参考程度に見ていただければと思います。

結論

pprofの-diff_baseを使って、2つのプロファイリング結果の差分からメモリリーク箇所を特定できます。

検証

実際に使用したメモリリークのサンプルコードは次になっています。（関数名などは適当）

goroutineリークの検証も兼ねて、ctx.Done()時にreturnをせず、goroutineをリークされています。

:::detailsサンプルコード

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のリークなども確認できます。
便利ですね。