時計を壊せ

駆け出してからそこそこ経ったWebプログラマーの雑記

ISUCON11予選に参加しました

id:Sixeightとid:aerealとチームにゃんこ選抜というチーム名で予選に参加しました。

再試験スコアは25746点、ベストスコアは記録をちゃんと残せてなかったけど3万ちょっとでした。 予選通過ラインが10万点ちょっとだったので、全然届かずという結果。色々と力及ばず完敗で無念……。

やったこと

事前準備と素振り

ISUCON10の予選問題を使って素振りを行いました。 週末を2日つかって予選突破スコアまで行くところまで体験するという感じのことをやり、チームとしての動き方のイメージをつかみました。

ぼくは主にインフラを中心にアレコレやりつつアプリにも時々手を出すという立ち位置で動くことにしました。

ほか、秘伝のタレ化しているansibleのplaybookを調整したり、alpにpcapサポートを追加するPRを送りつけたりり、チームのScrapboxに計測/調査などのノウハウや勉強ログを共有するためにメモを書き溜めたりしました。 alpのpcapサポートはあまり使ったことのないリバースプロキシなどが出てきたら使おうかなと思っていました。

なお、AWS CDKで一撃で分かりやすいPrivate IPを振ったEIP付きのEC2インスタンスを作って適切なセキュリティーグループを作った上でEIPをRoute53に登録する仕組みを用意していたのですが、 今年の運営は想定外にとても丁寧にCloudFormation Templateを提供してくれたのでこれは徒労に終わりました。（手でRoute53を設定したりしましたが、想定外にSecurity Groupの変更が許されない制約があり、またTLS証明書を事前に用意していなかったのでこのDNSレコードを使う機会は訪れませんでした……）

マニュアルの読み合わせ

アプリの仕様のデカさと複雑さにビビってちゃんと理解してから手を付けようとマニュアルを2時間くらいかけて読み合わせてチームの認識を揃えてました。

最終的に作業時間がもうちょっと取れればこれはなんとかなったのでは……という結果になってしまったり、マニュアルから読み取った最適化のヒントやスコアアップのためのヒントを活かせるところまで辿り着けなかったりと、結果論ですがあまり意味がなかったのでこれは失敗だったかもしれません。バランスの悪い時間の使い方をしてしまったかも……。とはいえ、理解せずに手を付けてもあまり意味がないことも多いので難しい……。

焦らない。ということを念頭に置いた結果、ちゃんと理解して手をつけようということにしていたのですが、予想以上に難しい仕様で時間が思いの外取られてしまったという格好でした。

netdataやalpなどを入れたりなど足回りの整備

ansibleで一発で入れられるようにしておいたので一発でいけました。

ただ、Security Groupで穴をあけるのが許されなかったのでNetdataにアクセスできず、ssh port forwadingもダルいしミスの温床になりそうだしどうしたもんかと困ったところとりあえずこんな感じでルーティングして難を逃れました。

        location /_netdata/isucon11q-1/ {
            access_log off;
            rewrite /_netdata/isucon11q-1/(.*) /$1 break;
            proxy_pass http://127.0.0.1:19999;
        }

        location /_netdata/isucon11q-2/ {
            access_log off;
            rewrite /_netdata/isucon11q-2/(.*) /$1 break;
            proxy_pass http://192.168.0.12:19999;
        }

        location /_netdata/isucon11q-3/ {
            access_log off;
            rewrite /_netdata/isucon11q-3/(.*) /$1 break;
            proxy_pass http://192.168.0.13:19999;
        }

        location /_misc/isucon11q-1/ {
            access_log off;
            rewrite /_misc/isucon11q-1/(.*) /$1 break;
            proxy_pass http://127.0.0.1:29999;
        }

        location /_misc/isucon11q-2/ {
            access_log off;
            rewrite /_misc/isucon11q-2/(.*) /$1 break;
            proxy_pass http://192.168.0.12:29999;
        }

        location /_misc/isucon11q-3/ {
            access_log off;
            rewrite /_misc/isucon11q-3/(.*) /$1 break;
            proxy_pass http://192.168.0.13:29999;
        }

nginxから静的ファイル配信

ぱぱっとやってしまおうと思ったら、ミスや見落としが多かったり思ったようにいかず1,2時間くらい四苦八苦して時間を溶かしてしまいました……。

こんな感じの設定をいれました。

        root /home/isucon/webapp/public;

        location = / {
            rewrite / /index.html break;
            break;
        }

        location /assets/ {
            break;
        }

        location = /register {
            rewrite /.* /index.html break;
            break;
        }

        location /isu/ {
            rewrite /.* /index.html break;
            break;
        }

同時にアクセスログの形式をalpに食わせられるような形式にそろえて、alpでエンドポイント単位の統計情報を作れるようにしました。

MySQL8への変更

dstatでtopを見るにmysqldのCPUがベンチマーク中ずっと張り付いていたので、 初期状態がMariaDBだったのもあり、素振りでも使った比較的慣れているMySQL8に変更することにしました。

ここでまたしても、Ubuntu標準のMySQLをアンインストールしてMySQL Communityのdeb packageからMySQL8をインストールするレシピをうっかりそのまま流してしまい、 MariaDBが入ったままMySQL CommunityのMySQL8をインストールしようとしてインストールの途中で引っかかってpurgeすることもまともにできない状態に陥ってしまい、1時間弱ほど時間を溶かしてしまいました。

アップグレード手順は事前の環境の状態に大きく依存するし、どうせ何度もやる作業ではないので、ansibleでやっつけようとせずに手順書ベースで手でやればよかったと反省しました。

これに伴い、アプリケーションとデータベースを別のインスタンスに分けることに成功し、buffer poolなども調整した設定でMySQLが動かせるようになったことでスコアが少しだけ向上しました。

なお、他の変更も含めてこの時点でスコアが4440点、時刻が14:25ということで残り時間半分を切っていて、それまでミスが続いたのも相まっていよいよマズイと焦りが出てきてしまいました。

インデックスを貼る

GET /api/trend や GET /api/condition/:jia_isu_uuid などで打たれていたクエリがpt-query-digestの上位に上がってきていたので、これを解決できるインデックスを貼りました。

github.com

ただ、これはindexの順番をミスっていて、本来は (jia_isu_uuid, timestamp DESC) に貼るべきでした。焦って確認もミスった……。

他の変更も含めてこの時点でスコアが13332点、時刻が14:57でした。

LIMITを付ける

めちゃくちゃ膨れるisu_conditionからSELECTしてアプリケーション側でLIMITしているやつがあったので、id:Sixeightがcondition_levelを入れてくれたので先回りしてSQLでLIMITするようにしました。

github.com

ログをちゃんと残していないけどまだ他の大きなボトルネックで詰まってたからかスコアには大きく響かなかった気がする。

isu_conditionテーブルへのINSERTバッファリング&直列化

GET /api/trend などでのN+1問題は他のメンバーにまかせていたので、先回りして POST /api/condition/:jia_isu_uuid で行われているisu_conditionテーブルへのINSERTバッファリングと処理の直接化を行いました。

具体的にはこんな感じの関数をGoroutineで立てて、channel経由でinsertするべきレコードをここに送ってまとめた上で複数リクエスト間でまとめてbulk insertすることによって、インデックスの更新負荷やロック獲得負荷を低減させることを狙いました。

func insertIsuConditions(ctx context.Context, logger echo.Logger, ch <-chan insertIsuConditionsArgs) {
    var rows [5000]*insertIsuRow
    var rowsSize int

    ticker := time.NewTicker(50 * time.Millisecond) // 50msごとにflushする
    defer ticker.Stop()
    for {
        select {
        case args := <-ch:
            for _, c := range args.conditions {
                // 呼び出し元でチェックしているのでここではチェックしない
                // if !isValidConditionFormat(cond.Condition) {
                //     return
                // }

                timestamp := time.Unix(c.Timestamp, 0)
                rows[rowsSize] = &insertIsuRow{
                    JIAIsuUUID: args.jiaIsuUUID,
                    Timestamp:  timestamp,
                    IsSitting:  c.IsSitting,
                    Condition:  c.Condition,
                    Message:    c.Message,
                }
                rowsSize++
                if rowsSize == len(rows) {
                    insertIsuConditionDoit(ctx, logger, rows[:])
                    rowsSize = 0
                }
            }

        case <-ticker.C:
            if rowsSize > 0 {
                insertIsuConditionDoit(ctx, logger, rows[:rowsSize])
                rowsSize = 0
            }

        case <-ctx.Done():
            return
        }
    }
}

これに加えてクライアントからは同期的に見えるように sync.Cond を使ってINSERT完了を待ち合わせたりする手なども試したのですが、 待ちが長くなりすぎたのか同時接続数が増えすぎてしまったので断念し、100msを越えない程度に適当なsleepを仕込んでお茶を濁しました。 なお、この同期は動作確認がてらcommitせずにdeployして試してしまったのでログにまともに残っていません。

この変更は他のN+1の修正に先んじてmergeしておいたのですが、GET /api/trend のN+1解消で出てたベンチマーカーエラーの原因特定が間に合わずここでタイムアップを迎えてしまいました。

MySQLのCPU100%張り付きが解消できないままアプリケーションサーバーのリソースがあまり続けてしまって2台構成でフィニッシュです。

感想

ボリュームがとても多く、また解決が難しい問題がたくさんあり、優先順位をちゃんと付けて適切に対処していかないとスコアの上がらないとても良い問題だったと思います。 関係者の皆様、お疲れさまでした！本戦に向けて引き続きがんばってください！

余談

その後、ベンチマーカーを公開してもらえたので、ミスってたところを直したりアレやろうと思っていたことをやってみたりしたところ、ちょっとイジっただけで119022点までいけました。 1時間あればこれくらいは全然できたはずだろうなと思うと悔しい……。

github.com

言い訳

www.youtube.com

実は木曜から金曜にかけての夜から当日まで殆ど眠れないというアクシデントに見舞われており、当日は死にかけみたいな体調でやってました。辛かった……。

なお、ISUCONが終わったあとはさすがに疲労困憊したからなのか、それとも新しい処方に体が慣れてきたからなのか、ぐっすり眠れました。

今夜も眠れるといいなぁ。