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


# はじめに

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

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

1. 計測
2. 分析

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

# TL;DR

* プロファイリング方法として1. go testのベンチマークで取る方法と、2. コードに追記する方法がある。
* 2. コードに追記する方法の中に以下の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の公式ドキュメント](https://golang.org/pkg/runtime/pprof/)を見るとラベリングをしたりする機能もあるようです。

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

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

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

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

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

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

```terminal:プログラム開始
$ go run net.http.pprof.go
awaiting signal
working with &{st:test}
working with &{st:test}
working with &{st:test}
```

```terminal:別ターミナルにてプロファイル開始。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](https://github.com/google/pprof#basic-usage)がわかりやすく、参照できます。

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

[net/http/pprofのソースコード](https://golang.org/src/net/http/pprof/pprof.go)

### `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の公式ドキュメント](https://golang.org/pkg/net/http/pprof/)に記載されています。

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

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

```golang.org/src/net/http/pprof/pprof.go
func Profile(w http.ResponseWriter, r *http.Request) {
	// 【前略】
	sec, err := strconv.ParseInt(r.FormValue("seconds"), 10, 64)
	if sec <= 0 || err != nil {
		sec = 30
	}
	// 【中略】
	if err := pprof.StartCPUProfile(w); err != nil {
		// StartCPUProfile failed, so no writes yet.
		serveError(w, http.StatusInternalServerError,
			fmt.Sprintf("Could not enable CPU profiling: %s", err))
		return
	}
	sleep(w, time.Duration(sec)*time.Second)
	pprof.StopCPUProfile()
}
```

# 参考

* http://klabgames.tech.blog.jp.klab.com/archives/pprof1-cpuprofile.html
* https://docs.google.com/presentation/d/1Fghxd31leQN2N2dW9h9D0KivPSSh-ROnzlsdqfsaGVw/pub
* https://chromium.googlesource.com/external/github.com/google/pprof/+/HEAD/doc/README.md
* https://users.rust-lang.org/t/pprof-wont-show-symbols/24241