golangでpprofを使ってみたら使え過ぎな件

あまりにも使え過ぎたので使い方を忘れないためにアウトプットする。

pprofとは

GOのアプリケーションやバイナリをプロファイリングするために使う。
runtimeで動かしてプロファイリング結果をダウンロードし確認するタイプのものと、
HTTP経由でプロファイリング結果を参照し確認するタイプのものがある。

runtimeで動かす方はこちらを見てください。
ここではやりません。

HTTP経由で確認する方をやります。

golang.org

導入する

ISUCON9の内容でやります。
本当はちゃんとベンチマークを実行するべきですが、(面倒なのと、)導入の仕方がわかればいいのと、見方がわかればいいので、ローカルで動かしたものに対してプロファイリングします。

実行環境

$ go version
go version go1.13 darwin/amd64

$ sw_vers
ProductName:    Mac OS X
ProductVersion: 10.14.6

導入

導入自体は一瞬で終わる。
まずはgraphvizをインストールする。

$ brew install graphviz

main関数に以下の記述を追加。

import     _ "net/http/pprof"

// ===== 中略 =====

func main() {
    go func() {
        log.Println(http.ListenAndServe("localhost:6060", nil))
    }()
// ===== 以下略 =====

実行する

プロファイリング対象のアプリを起動する。

起動したら以下を実行

go tool pprof -http=":8081" ~/dev/isucon9/webapp/go http://localhost:6060/debug/pprof/profile

このコマンドを実行すると、30秒くらいプロファイリングした後、自動的にブラウザが立ち上がり、結果が表示される。
この30秒の間にベンチマーク実行したり、画面ぽちぽちしたりする。

結果

TOP

ブラウザで開くと最初は以下のような画面になっている。

関数ごとにプロファイリング結果が表示されている。
それぞれの項目の見方は以下。

Flat：関数の処理時間
Flat%：各Flatの全体に対する割合
Sum%：スタック履歴からの累計Flat%
Cum：待ち時間も含めた処理時間
Cum%：各Cumの全体に対する割合
Name：関数名

Graph

こんな感じのチャートが表示される。

こっちを見るより次に紹介するflame graphの方が見やすいのでそっちを見る。

Flame Graph

こんな感じのチャートが表示される。

各箱は関数を表している
各箱の幅は、CPU上での合計の処理時間
- 大きい幅の箱は、小さい幅の箱に比べて、一回あたりの処理時間が長いか、複数回呼ばれる処理であるということを意味する
ちなみに、上の箱が下の箱を呼び出す形になっており、これがそのままスタックトレース

箱にカーソルを合わせると、関数名と処理時間が表示される。
この関数そのものに時間がかかっているか、その関数が呼び出している関数の処理に時間がかかっているのかすぐにわかる。

ある箱Aの処理時間が10ms、その下の箱Bの処理時間が1msの場合
Aの関数はBの関数の結果をせいぜい1ms待つだけ。
つまりAの処理そのものに9msかかっていることになるので、ここにボトルネックがあるのかも？ということになる

さらに、箱をクリックすると、その箱にフォーカスした表示に切り替わる。

pprof-focused-flame-graph — flame-graph-focused

まじですごくないですかこれ、、、

Source

極め付きがこれ。
Sourceを開き、検索窓に関数名を入れて、 REFINE でSHOWをクリックすると、以下のような表示になる。

ある関数の中で、具体的にどこに時間がかかっているのかがわかる。

これ、本当に使える。。。

ぜひ使ってみてください。
以上でした。

外に出るねくら

~ 外に出たって結局やることは自宅と同じ ~

golangでpprof使ってみたら使え過ぎな件