fgprof とは

fgprofとは、go 言語のサンプリングプロファイルツールとなります。
プロファイルツールって何ぞやって人もいると思いますが、簡単にいうと「処理にかかった時間やメモリの使用量を測定するツール」といった感じになります。使用してみると下の図のように、処理に対して、どの関数がどのくらい時間がどのくらいかかったのかを、視覚的に見ることができます。(下の図は fgprof に記載されている pprof のサンプル図です。)
gcp だと stack trace とかをイメージしてもらうのがいいですね。

pprofのサンプル図

そして、go 言語には、すでに pprof という公式のプロファイルツールが存在します。しかし、この pprof は on-cpu の処理のみ測定が行うわれます。on-cpu の処理というのはいわゆる cpu 上の計算のみです。このため、DB に対してのクエリ、他サービスへのアクセス、ディスク IO などの、cpu 上で行われない処理は計算されません。そのため、pprof を使うと真のボトルネックとなる処理が分からないことが多々有りました。

そこを改良したのが fgprof となります。fgprof を使うことで cpu 上で行われない処理（off-cpu）の処理を測定し、真のボトルネックを見つけることが可能になりました。すごいツールです。

使用例

go-chi で以下のようなサーバーを作成して、どのようにプロファイルされるかを見ていきます。

package main

import (
	"context"
	"net/http"

	"github.com/go-chi/chi"
)

func main() {
	r := chi.NewRouter()

	r.Get("/", func(w http.ResponseWriter, r *http.Request) {
		// cpuを止める処理
		cpuIntensiveTask()
		// 良くわからない関数
		weirdFunction()
		// なんらかの network request
		slowNetworkRequest(r.Context())
	})

	panic(http.ListenAndServe(":3000", r))
}

pprof

まず、pprof ではどのように出力されるかを確認します。以下のように、main パッケージで、pprof を読み込み、サーバーをもう一つ立ち上げるだけで準備完了です。

package main

import _ "net/http/pprof"

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

  // code ...
}

その後、３つのシェルを起動し、それぞれで以下のように行います。

  • go run main.go の実行（サーバ起動）
  • go tool pprof -http=:6061 http://localhost:6060/debug/pprof/profile?seconds=5 の実行（プロファイルの測定）
  • curl localhost:3000 の実行（サーバへのアクセス)

そうすると、下図のような出力が見られます。下図を見る限り、 weirdFunction以外はやばそうな処理はなさそうに見えます。本当にそうでしょうか？

pprofの結果

fgprof

次に、本題の fgprof で実行していきます。変更点は以下のようです。

package main

import (
  _ "net/http/pprof"
  "github.com/felixge/fgprof"
)

func main() {
	http.DefaultServeMux.Handle("/debug/fgprof", fgprof.Handler())
	go func() {
		log.Println(http.ListenAndServe(":6060", nil))
	}()

  // code ...
}

今回のプロファイルの実行は以下のようになります。他は先程と同様です。

$ go tool pprof --http=:6061 http://localhost:6060/debug/fgprof?seconds=5

結果としては以下のように出力されます。

fgprofの結果

先程よりも詳細な情報が見れていることが分かると思います。http.serve が行われていることをクリックすると、上図のようにそれぞれの関数の詳細が見れます。これによりそれぞれの関数にどのくらいの時間がかかったが測定されていることが分かります。これを見る限り、http request に時間が結構かかっていること、こっそり time.sleep が走っていることなどがよく分かります。

まとめ

pprof 以上に詳細なプロファイルを出してくれる fgprof の紹介でした。off-cpu の処理がボトルネックとなることは多いため、ローカルで調査をするさいは結構いいかなって思っています。 一応今回使った sample は下記 URL に置いてあります。
https://github.com/komem3/fgprof_sample