概要
ISUCON8予選問題で、GitHub - najeira/measureを使ってメソッド・コードブロック単位で実行時間を取得する手順のメモ。
実行時間の取得
前回、リクエスト単位の解析を行った。ボトルネックの更に具体的な箇所の特定のため、より細かい単位、メソッドやコードブロック単位で時間を測る。
最初はpprofを使おうと思ったが、上手く動かせず挫折した。そこで、死闘の果てに ISUCON 8 予選を全体７位で突破した記録 - Qiitaで紹介されているGitHub - najeira/measureを試してみることに。UsageはREADME.mdに記述がある。
前提：参照実装の構造
ISUCON8予選問題のGoの参照実装では、Echoフレームワークが使われている。
e.GET("/api/users/:id", func(c echo.Context) error {...}, loginRequired)
上記のようにリクエストURIに対応する処理が記述される。alpによる解析で/api/users/*が遅いことが分かっているので、最初はその辺を重点的に見ていく。
計測コード埋め込み
計測コード埋め込み（１）import
import文を書いただけでは、ビルド時にパッケージが見つからない。go getでいちいちインストール的なことをする、というのが普通なんだろうか？Maven以外ほぼ使ったことなかったので、なんだか面倒に感じる。
import ( ... "github.com/najeira/measure" )
cannot find package "github.com/najeira/measure" in any of:
/home/isucon/local/go/src/github.com/najeira/measure (from $GOROOT)
/home/isucon/go/src/github.com/najeira/measure (from $GOPATH)
ちなみにgo get -v github.com/najeira/measureをしても上手く行ってないようで（特にエラーも表示されないが）、cannot find packageは変わらず、上記に表示されているパスにも入っていない。そこで今回はもう直接git cloneした。これで一応解決。
sudo git clone --depth 1 https://github.com/najeira/measure.git $GOPATH/src/github.com/najeira/measure sudo git clone --depth 1 https://github.com/rcrowley/go-metrics.git $GOPATH/src/github.com/rcrowley/go-metrics
計測コード埋め込み（２）Measure
URI単位の処理とか、関数単位の計測は1文で書ける。
e.GET("/", func(c echo.Context) error { defer measure.Start("GET(/").Stop()
func getEvent(eventID, loginUserID int64) (*Event, error) { defer measure.Start("func getEvent").Stop()
さらにmeasure.Startとmeasure.Stopを埋め込んでコード何行目から何行目、という単位でも計測可能。ただし、for文の中のより細かい範囲を分割して測ろうとしたときは上手く行かなかった。実行順序の指定とか上手くやればできるのかも。
計測コード埋め込み（３）Stats部分
まず、Log構造体と、Log構造体を渡してCSVファイルにレンダリングして返してくれる関数を作る。これは参照実装にあったrenderReportCSVの見様見真似。
type Log struct { Key string Count int64 Sum float64 Min float64 Max float64 Avg float64 Rate float64 P95 float64 } func renderLogCSV(c echo.Context, logs []Log) error { body := bytes.NewBufferString("key,count,sum,min,max,avg,rate,p95\n") for _, s := range logs { body.WriteString(fmt.Sprintf("%s,%d,%f,%f,%f,%f,%f,%f\n", s.Key, s.Count, s.Sum, s.Min, s.Max, s.Avg, s.Rate, s.P95)) } c.Response().Header().Set("Content-Type", `text/csv; charset=UTF-8`) c.Response().Header().Set("Content-Disposition", `attachment; filename="log.csv"`) _, err := io.Copy(c.Response(), body) return err }
上記のCSVファイルを取得するエンドポイントを作る。これは参照実装にあったe.GET("/admin/api/reports/sales"の見様見真似。statsのとり方はUsageより。Sumの所でRoundを噛ませているのは、CSVを表示したときに小数が入っていない方がぱっと見で分かりやすいため。
e.GET("/stats", func(c echo.Context) error{ stats := measure.GetStats() stats.SortDesc("sum") var logs []Log for _, s := range stats { log := Log{ Key: s.Key, Count: s.Count, Sum: math.Round(s.Sum), Min: s.Min, Max: s.Max, Avg: s.Avg, Rate: s.Rate, P95: s.P95, } logs = append(logs, log) } return renderLogCSV(c, logs) })
結果表示
ブラウザで/statsにアクセスするとCSVファイルがダウンロードできる。
参考実装の初期状態で、ベンチマーク実行後の結果を開いてみると以下のようになる。計測点は全エンドポイント、関数に設定しており、getEventは最大であったため、関数内をさらに分割している。
結果のSlack通知
いちいちCSVを開きにいくのも面倒＆後で見返しづらい。
標準入力を適当にまとめてSlackに通知するnotify_slackを作りました - catatsuy - Medium こんな素敵ツールがあったので、使ってみる。GO111MODULEを使うインストール方法は詰まったので普通にバイナリを持ってくることにした。
Slackのアカウント作成、ワークスペース作成、チャンネル作成、https://slack.com/services/new/incoming-webhookからwebhookを作成、レガシートークンも作成（これは必要かよくわかってないが）。
.tomlファイルをhttps://github.com/catatsuy/notify_slackのUsageに従って書く。
CSVをSlackに向けて飛ばしてみる。
curl ${TARGET_SITE_URL}/stats |head -n 10| tr "," "\t" | ./notify_slack
無事取得できた。もうちょっと見やすくできるといいが一旦終わり。
