Go에서 pprof를 사용하여 메모리 유출을 확인하는 방법

개시하다

업무 개발 시스템에서 메모리 유출이 발생했기 때문에 pprof에서 유출 위치를 확인하는 방법을 조사했다.
이 기사에도 자신의 필기가 포함되어 있다.
다른 더 좋은 방법과 오류가 있을지도 모르니 참고하세요.

결론

pprof 중-diff_base을 사용하면 두 분석 결과의 차이에 따라 메모리 유출 위치를 확정할 수 있다.

확인

실제 사용된 메모리 유출의 샘플 코드는 다음과 같다.(함수 이름 등)
!
고로틴 유출 검증도 겸하고 ctx.Done()시 리턴을 하지 않아 고로틴이 유출됐다.
샘플 코드

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))
}

검증 결과

다음 명령을 두 번 실행합니다.
두 번째 실행은 첫 번째 로그 출력이 멈춘 후에 진행됩니다.

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

두 번째 명령을 실행할 때의 메모리 사용량은 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를 사용하여 차분을 확인한 후 첫 번째와 두 번째 차이13.40MB23208kB(2回目)-9489.30kB(1回目)=13718.7kB(13.397168MB)이기 때문에flat값과 일치합니다.
즉 -diff_base를 사용하여 두 결과를 비교했을 때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는 메모리뿐만 아니라 두 개profile를 비교하는 옵션이기 때문에 goroutine의 유출 등도 확인할 수 있다.
편하네.