pprof でボトルネックを探す

読了目安約3分

SQL でもエンドポイント単位でもなく Go のコード自体が遅いとき、CPU プロファイルで犯人の関数を特定します。

この章の目次

alp では遅いのにスロークエリログでは説明がつかないエンドポイントに出会うことがあります。残る容疑者は、CPU を使う Go のコードそのものです。

この領域の計測ツールが pprof です。 pprof は Go に標準で付いているプロファイラで、「CPU 時間をどの関数が使っているか」を一定間隔のサンプリングで記録します。

計測エンドポイントを生やす

組み込みは数行で済みます。

Go
import _ "net/http/pprof"

func main() {
	go func() {
		log.Println(http.ListenAndServe("localhost:6060", nil))
	}()
	// 以下、いつものアプリの起動処理
}

net/http/pprof を空 import すると、プロファイル取得用のハンドラが http.DefaultServeMux に登録されます。お題アプリは echo などを使っていて DefaultServeMux を通らないことが多いので、別ポート（ここでは 6060）で標準のサーバーをもう 1 つ立てます。

プロファイルを取る

シェル

go tool pprof "http://localhost:6060/debug/pprof/profile?seconds=30"

seconds=30 の間、CPU の使われ方をサンプリングして、対話モードに入ります。必ずベンチを回している最中に実行してください。負荷のない間に取っても、暇にしているプログラムの記録が採れるだけです。

top の読み方

対話モードで top と打つと、CPU 時間を使った関数の順位表が出ます（数値は例です）。

テキスト

(pprof) top
Showing nodes accounting for 18.2s, 78.4% of 23.2s total
Dropped 312 nodes (cum <= 0.12s)
      flat  flat%   sum%        cum   cum%
    10.5s 45.26% 45.26%     10.6s 45.69%  golang.org/x/crypto/blowfish.encryptBlock
     1.9s  8.19% 53.45%     12.4s 53.45%  golang.org/x/crypto/blowfish.ExpandKey
     1.8s  7.76% 61.21%      1.8s  7.76%  runtime.memmove
     1.6s  6.90% 68.11%      2.1s  9.05%  encoding/json.(*encodeState).string
     ...

flat：その関数自身のコードが使った CPU 時間
cum：その関数から呼び出した先も含めた合計時間（cumulative）

flat の上位が、実際に CPU を回している現場です。 2 行目の ExpandKey は flat 1.9 秒、cum 12.4 秒。自分ではあまり働かず、1 行目の encryptBlock に時間を使わせている関係です。

どこから呼ばれているかを絵で見るには、-http を付けて起動します。

シェル
go tool pprof -http=localhost:8081 "http://localhost:6060/debug/pprof/profile?seconds=30"

ブラウザに呼び出しグラフが開き、時間を使っている経路ほど太い線で描かれます。この例なら、ログインハンドラ → bcrypt.CompareHashAndPassword → blowfish.ExpandKey → blowfish.encryptBlock という太い経路が見え、犯人はパスワードハッシュの検証だと分かります。

見つけたあとの直し方

直し方は犯人によります。

bcrypt（パスワードのハッシュ計算）：総当たり攻撃を防ぐためにわざと計算を重くする設計で、重さはコストパラメータで決まる。参照実装では必要以上に大きいことがあるので、レギュレーションとベンチマーカーの検査が許す範囲で下げる
JSON のエンコード：同じ JSON を毎回作っていないかを疑う。内容が変わらないレスポンスなら、エンコード結果を前章のキャッシュに載せる
正規表現のコンパイルがループの中：regexp.MustCompile をパッケージ変数に出して 1 回にする

直したらベンチを回し、もう一度プロファイルを取って順位が落ちたことを確かめます。 alp で場所を絞り、スロークエリログで SQL を疑い、外れたら pprof で関数まで降りる。ここでも「計測が指した場所だけを直す」のは同じです。

最終章では、これらを体に馴染ませる練習方法を紹介します。