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

概要

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

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

ISUCON8予選問題のアクセスログ解析

概要

ISUCON8予選問題の環境で、H2Oサーバのアクセスログをalpに噛ませ、URI単位で重い処理を特定するまでの手順。

計測環境

改善の第一歩は現状把握ということで、色々なものの計測環境を整えていきたい。

• Webサーバ
  • アクセスログ
• アプリ
  • プロファイラ（関数単位、行単位）
• サーバ・NWリソース
  • CPU、メモリ、ディスクIO、NW帯域、ポート...

Webサーバ

特に重要な情報源となるWebサーバのアクセスログ解析のやり方を整理する。今回WebサーバはH2O。 ログ解析ツールにalpを使う。

設定ファイルの特定

サービス一覧を確認、サービス名を特定。

$ systemctl list-units --type=service
~
  h2o.service  loaded active running H2O - the optimized HTTP/1, HTTP/2 server
~

h2o.serviceの状態を確認、設定ファイルのパスを特定。今は/etc/h2o/h2o.confらしい。

$ systemctl status h2o.service
~
           ├─4359 /usr/sbin/h2o -c /etc/h2o/h2o.conf
~

ログ設定の編集

/etc/h2o/h2o.confを編集、アクセスログフォーマットをalp仕様に変更する。

access-log:
  path: /var/log/h2o/access.log
  format: "time:%t\thost:%h\tua:\"%{User-agent}i\"\tstatus:%s\treq:%r\turi:%U\treqtime:%{duration}x\tsize:%b\tmethod:%m\t"

文法チェック。

$ h2o -m test -c /etc/h2o/h2o.conf
configuration OK

h2oをリスタートさせ、ブラウザとかcurlとかでアクセスしてみる。ログが編集した通りのフォーマットになって出てくればOK。

$ sudo systemctl restart h2o.service
$ sudo tail -f /var/log/h2o/access.log

alp実行

資材をダウンロード、展開、実行。表がカラじゃなきゃOK。

$ wget https://github.com/tkuchiki/alp/releases/download/v0.4.0/alp_linux_386.zip
$ unzip alp_linux_386.zip 
$ sudo ./alp -f /var/log/h2o/access.log --sum

ベンチ後にalp実行、ボトルネック処理を特定

ログをカラにしてベンチ実行、alpで解析。このときScoreは800だった。

下図のalp結果はURIごとの累計応答時間を降順に並べている。 全合計が314秒くらいなので、/api/users/*と/だけで2/3近く占めていることが分かった。

$ sudo truncate /var/log/h2o/access.log --size 0
$ bash /home/isucon/torb/bench/tools/do_bench.sh
$ sudo ./alp -f /var/log/h2o/access.log --sum -r --aggregates "/api/users/*"
+-------+--------+-----------------------------------------+---------+
| COUNT | METHOD |                   URI                   |   SUM   |
+-------+--------+-----------------------------------------+---------+
|    12 | GET    | /api/users/*                            | 133.308 |
|    24 | GET    | /                                       |  64.064 |
|     5 | GET    | /admin/                                 |  26.668 |
|    24 | POST   | /api/events/11/actions/reserve          |  22.741 |
|    16 | GET    | /api/events/10                          |  16.836 |
~

これで、とりあえず/api/users/*や/あたりから見ていくのが良さそうなことが分かった。

余談

VSCodeの拡張機能のRemote SSHが便利だった。 図のようにサーバのディレクトリをローカルのようにいじれる感覚が素晴らしい。

ISUCON8予選問題をクラウドサービス上で動かしてみる

概要

Alibaba Cloud上でISUCON8予選問題を動かした。やり方のメモ。

Ansibleでプロビジョニング

公式のをカスタムしてあって練習に使いやすそうなリポジトリを見つけた。ありがたく使わせて頂く。

構成1：Ansible実行サーバもまとめて１サーバでやってみる（失敗）

CentOS VMインスタンスを１つ立て、自身にプロビジョニングさせたら全部１VMで済むのでは？と思いやってみた。（Windowsなので自機にansible実行環境を作るのも面倒だった）--connection=localを使う。接続も考えなくてよくて楽かも。

しかし、フォルダ同期をする箇所でrsyncが Permission denied (13)を吐いてしまい、色々試したがこれが解消できなかったため諦めた。

構成2：Ansible実行サーバと、プロビジョニング対象１サーバでやってみる（成功）

これはAnsibleがエラーを吐くことなく終了した。

手順

• VMインスタンス（CentOS 7.5 64 ビット）を２つ立てる(VM-A,VM-Bとする)
• VM-A->VM-Bの鍵設定
• VM-A上で、
  • パスフレーズがキャッシュされるように設定
  • git,ansible(2.7.9が入る),emacsインストール
  • リポジトリクローン
  • provisioning/README.mdの手順に従う。ansible-playbookを実行し、エラーが出なかったらOK。

今回書いたdevelopmentは下記の通り（VM-BのプライベートIPを書いた。例にはroot@があったが、なくてもいけるようである。）

[portal_web]
172.24.xx.xx

[bench]
172.24.xx.xx

[webapp1]
172.24.xx.xx

ちゃんとプロビジョニングできたかの確認

まずVM-Bにisuconユーザでログインする。（isucon/isuconでログインできるかと思ったができなかったので、鍵認証で。）

Webアプリ

Webアプリ「Torb」のサービスステータスを確認する。

$ systemctl | grep torb
torb.go.service  loaded    active running   isucon8 qualifier webapp in go

ブラウザからBのパブリックIPアドレスにアクセスしたが、接続できない。 curl localhostするとページが取れるので、アクセス制御の問題のようだ。 ECSのセキュリティグループ＞ルール設定＞ルールのクリック設定から、自端末のIPの接続を許可する。

これでブラウザからWebアプリにアクセスできた。

ベンチマーク

provisioning/README.mdの手順で、１発で動いた。スコアは932。

Webアプリサーバスペック

• Alibaba Cloud ECS
• CentOS 7.5 64 ビット
• ecs.t5-lc1m2.large 2 vCPU 4 GiB 基準パフォーマンス10 % Intel Xeon CPU 2.5 GHz
• イントラネット帯域 0.4 Gbps
• パケット転送速度 100,000 PPS

ベンチ実行時のモニタリングはこんな感じ。

このあと

動かせる環境が手に入ったので、改善を色々試してみたい。

余談：SSHクライアントツール

今までTeraTermを使っていたが、RLoginというツールがあることを知った。使いやすくて良い。

• Windowsターミナルソフト + Rlogin が最高すぎる！！ - Qiita
• RLoginを使い始めました - かきすて

ISUCON練習の準備

Alibaba Cloudアカウント作成

ISUCON9に向けて練習しようと思い、備忘録・チームメンバへの共有がてらブログを始めてみた。

今年のサーバ提供はAlibaba Cloudとのことで、とりあえずアカウントを作成した。クレカ登録後、IDを要求される。送って15分くらいで連絡が来て、30000円分のクーポンが使える状態になっていた。

最近AWS, GCP, Azureのアカウントを立て続けに作ったが、クレカ登録は皆要求されるものの、IDを要求されたのはAlibaba Cloudだけだった。