More than 3 years have passed since last update.

[Go] pprofでのプロファイル(計測)のやり方を改めて整理した

Last updated at 2021-06-12Posted at 2020-08-09

はじめに

Go言語でのプロファイリングといえばgo tool pprofです。

プロファイルのステップとして

計測
分析

の2つがありますが、特に1つ目の計測方法に関してわかりづらく感じていたので不明瞭だった点をまとめました。

TL;DR

プロファイリング方法として1. go testのベンチマークで取る方法と、2. コードに追記する方法がある。
1. コードに追記する方法の中に以下の2つがある。
- 2-1. "runtime/pprof" (バッチプログラムやCLIツールを計測)
- 2-2. "net/http/pprof"(HTTPサーバプログラムを計測)

プロファイリングのやり方 (計測)

1. go testのベンチマークを取る方法

go testでサポートされているGoのベンチマークでプロファイル用のオプションをつけるとプロファイル結果ファイルが生成されます。

ベンチマークなテストファイルがあるディレクトリにて以下のように使います。

$ ls -1
bench_test.go
main.go

$ go test -cpuprofile cpu.prof -memprofile mem.prof -bench .
goos: darwin
goarch: amd64
BenchmarkVar-4            302041              3462 ns/op
BenchmarkPointer-4        113582             10360 ns/op
PASS
ok      _/Users/shintaro/.ghq/github.com/momotaro98/go-codes-for-learning/go-comparison/var_vs_pointer  2.881s

$ ls -1
bench_test.go
cpu.prof
main.go
mem.prof
dirname.test

ちなみに、-bench BenchmarkVarとすることでプロファイルしたいテスト関数のみを指定できます。

2. コードに追記する方法

2-1. "runtime/pprof" の利用 (バッチプログラムなどを計測するケース)

runtime/pprofではプロファイルで分析したい処理セグメントに対してStartCPUProfile関数とStopCPUProfile関数で挟んで利用します。

runtime.pprof.go

package main

import (
	"os"
	"runtime/pprof"
	"time"
)

func run() error {
	f, err := os.Create("cpu.pprof")
	if err != nil {
		return err
	}

	if err := pprof.StartCPUProfile(f); err != nil {
		return err
	}
	defer pprof.StopCPUProfile()

	process := func() {
		time.Sleep(time.Second * 5)
	}
	process()

	return nil
}

func main() {
	if err := run(); err != nil {
		panic(err)
	}
}

$ go run runtime.pprof.go
$ ls -1
cpu.pprof
runtime.pprof.go

runtime/pprofの公式ドキュメントを見るとラベリングをしたりする機能もあるようです。

2-2. "net/http/pprof" の利用 (HTTPサーバを計測するケース)

HTTPサーバなど定常的に動いているプログラムに対して一定時間の間プロファイルしたい場合はnet/http/pprofを利用します。

importに_ net/http/pprofを追加し、対象の定常的なプログラムに

        go func() {
                log.Println(http.ListenAndServe("localhost:6060", nil))
        }()

を追加することで、http://localhost:6060/debug/pprofというエンドポイントが開放されます。

特にhttp://localhost:6060/debug/pprof/profileが一番良く利用されるエンドポイントで、下記のようなpprofコマンドを叩いた時点からプロファイルを開始します。デフォルトでは30秒間プロファイルを実施し、終了すると結果ファイルを出力します。秒間は指定することが可能です。

プログラム開始

$ go run net.http.pprof.go
awaiting signal
working with &{st:test}
working with &{st:test}
working with &{st:test}

別ターミナルにてプロファイル開始。10秒後にプロファイル結果ファイルが出力される。

$ go tool pprof http://localhost:6060/debug/pprof/profile?seconds=10
Fetching profile over HTTP from http://localhost:6060/debug/pprof/profile?seconds=10
Saved profile in /Users/momotaro98/pprof/pprof.samples.cpu.001.pb.gz

実行を確認するためのサンプルコード

net.http.pprof.go

package main

import (
	"fmt"
	"log"
	"net/http"
	_ "net/http/pprof"
	"os"
	"os/signal"
	"syscall"
	"time"
)

func main() {
	go func() {
		log.Println(http.ListenAndServe("localhost:6060", nil))
	}()

	sigs := make(chan os.Signal, 1)
	done := make(chan struct{})

	signal.Notify(sigs, syscall.SIGINT, syscall.SIGTERM)

	var s = &struct {
		st string
	}{
		st: "test",
	}

	// 擬似的なHTTPサーバを意図した定常的に動くプログラム
	go func() {
		for {
			time.Sleep(time.Second * 1)
			select {
			case <-sigs:
				fmt.Println("signal has come")
				done <- struct{}{}
				break
			default:
				fmt.Printf("working with %+v\n", s)
			}
		}
	}()

	fmt.Println("awaiting signal")
	<-done
	fmt.Println("exiting")
}

net/http/pprofについて詳細を追ってみたので、備考として最下部に記載しています。

プロファイリング結果の分析のやり方

プロファイリング結果ファイルが生成後の分析方法については様々な記事でわかりやすく書かれているので本記事では割愛にします。

本家pprofのREADMEがわかりやすく、参照できます。

備考 "net/http/pprof" の実装を追ってみる

net/http/pprofのソースコード

`import _ "net/http/pprof"`で何をしているか

net/http/pprofの利用においてはimportの中で_ "net/http/pprof"をしますが、これにより下記のnet/http/pprofパッケージ内のinit()関数が実行されます。

golang.org/src/net/http/pprof/pprof.go

func init() {
	http.HandleFunc("/debug/pprof/", Index)
	http.HandleFunc("/debug/pprof/cmdline", Cmdline)
	http.HandleFunc("/debug/pprof/profile", Profile)
	http.HandleFunc("/debug/pprof/symbol", Symbol)
	http.HandleFunc("/debug/pprof/trace", Trace)
}

つまり、net/httpパッケージ内のDefaultServeMuxに対してハンドラー追加していることになるので、http.ListenAndServe(":6060", nil)とnil指定で立ち上げることで/debug/pprof/以下のパスはnet/http/pprofのハンドラにさばかれることになります。そのため、指定のポートは6060である必要は全くありません。

上記の内容はnet/http/pprofの公式ドキュメントに記載されています。

`/debug/pprof/profile`は`runtime.pprof`の`StartCPUProfile`を呼んでいる。

メインの/debug/pprof/profileのエンドポイントのハンドラ関数はruntime/pprofのStartCPUProfileを呼ぶラッパーであることがわかります。