ISUCON特訓 ① プロファイリング編

ISUCON?

いい感じにスピードアップコンテスト(http://isucon.net/)の第8回に学生枠として参戦することにしました。コードやインフラの構成をチューニングしてよりパフォーマンスの良いアプリケーションを作る大会です。お仲間はメルカリで一緒だった爆優秀な @nakabonne(https://twitter.com/nakabonne)と@zaq1tom0(https://twitter.com/zaq1tomo)

プロファイリングから始めよう

何から始めていいかよく分からない手探りな状況だったのですが、過去の優秀者たちのブログ等を見たり過去問に当たっているうちに指針が立ってきました。ISUCONで勝つためにまず始めに取り組まなければいけないであろうことはプロファイリングのようです。

プロファイリングとは、アプリケーションのどのエンドポイント・どのルーチン・どのコードがボトルネックになっているかを解析することです。実際にどうやってパフォーマンスを上げていくかはこのプロファイリングをもって判断するので非常に重要かつ不可欠なステップになります。

ISUCONで必要となりそうなプロファイリングは大きく分けて次の3ステップがあります
1. アクセスログの解析
2. コードの解析
3. データベースクエリの解析

アクセスログの解析

こちらはalpというツールを使うことが多いようです。インストールはこんな感じで

$ wget https://github.com/tkuchiki/alp/releases/download/v0.0.4/alp_linux_amd64.zip
$ sudo apt install unzip
$ unzip alp_linux_amd64.zip
$ sudo mv alp /usr/local/bin/alp
$ sudo chown root:root /usr/local/bin/alp

Nginxのログとして出力するためには/etc/nginx/nginx.confのlog_formatとaccess_logのディレクティブを以下のように変更します

    log_format ltsv "time:$time_local"
        "\thost:$remote_addr"
        "\tforwardedfor:$http_x_forwarded_for"
        "\treq:$request"
        "\tmethod:$request_method"
        "\turi:$request_uri"
        "\tstatus:$status"
        "\tsize:$body_bytes_sent"
        "\treferer:$http_referer"
        "\tua:$http_user_agent"
        "\treqtime:$request_time"
        "\truntime:$upstream_http_x_runtime"
        "\tapptime:$upstream_response_time"
        "\tcache:$upstream_http_x_cache"
        "\tvhost:$host";

    access_log /var/log/nginx/access.log ltsv;

これで準備完了、nginx reloadした後に一旦ベンチを回しましょう。その後に $ alp -f /var/log/nginx/access.logでエンドポイントごとの処理時間についてのプロファイルが見れます

コードの解析

使用する言語によるので今回使う予定のGoについてのみの説明を載せておきます
手順は簡単です　まずはnet/http/pprofをブランクインポートしておき、main関数にlocalhost:6060でサーバを立てるコードを入れておきます

import (
        _ "net/http/pprof"
)

func main() {
    go func() {
        log.Println(http.ListenAndServe("localhost:6060", nil))
    }()
        
        r := RegisterRoutes()
        http.ListenAndServe(":8080", r)
}

その後、ISUCONから与えられているベンチマークを回しておき、

$ curl -s http://localhost:6060/debug/pprof/profile > cpu.pprof

を実行
その後、go run時にできた実行ファイルと上記コマンドでできたcpy.pprofを引数にして以下を実行

$ go tool pprof main cpu.pprof
File: main
Type: cpu
Time: Aug 29, 2018 at 11:09pm (JST)
Duration: 30s, Total samples = 130ms ( 0.43%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)

ここからはインタラクティブに解析が可能です topと入力すると実行に時間がかかっている順に見られますまた、list mainと入力すると、main関数内のどこで時間がかかっているかをより詳細に見られます

データベースクエリの解析

ISUCONでよく使われているのはスロークエリログのようですスロークエリログを仕込むためには、/etc/myconfに以下のように追記します

[mysqld]
slow_query_log = 1
slow_query_log_file = /var/log/mysql/slow.log
long_query_time = 0

（myconfの場所は環境によって変わるようです、以下のQiitaを参考にしてください my.cnfの場所を調べる）それからmysqlをrestartさせた後、再度ベンチを回しましょうそうするとログファイルが生成されるので、以下のコマンドで読み込みます

$ sudo mysqldumpslow /var/log/mysql/slow.log

全体の流れ

alpでどの辺りのエンドポイントが時間をかかってるか計測し、pprofでそのエンドポイントの中のどの処理に時間がかかってるのかを計測し、スロークエリログでその処理の中のどのクエリに時間がかかってるかを計測する、という流れになると思います（スロークエリログは使わないこともあると思いますが）