kavo’s diary

備忘録

ISUCON8予選問題のメソッド・コードブロック単位の実行時間の解析

概要

ISUCON8予選問題で、GitHub - najeira/measureを使ってメソッド・コードブロック単位で実行時間を取得する手順のメモ。

実行時間の取得

前回、リクエスト単位の解析を行った。ボトルネックの更に具体的な箇所の特定のため、より細かい単位、メソッドやコードブロック単位で時間を測る。

最初はpprofを使おうと思ったが、上手く動かせず挫折した。そこで、死闘の果てに ISUCON 8 予選を全体7位で突破した記録 - 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/*が遅いことが分かっているので、最初はその辺を重点的に見ていく。

計測コード埋め込み

計測コード埋め込み(1)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

計測コード埋め込み(2)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.Startmeasure.Stopを埋め込んでコード何行目から何行目、という単位でも計測可能。ただし、for文の中のより細かい範囲を分割して測ろうとしたときは上手く行かなかった。実行順序の指定とか上手くやればできるのかも。

計測コード埋め込み(3)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は最大であったため、関数内をさらに分割している。

f:id:kavohtn:20190729020304p:plain

結果の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

f:id:kavohtn:20190729024625p:plain

無事取得できた。もうちょっと見やすくできるといいが一旦終わり。