ISUCON8予選2位(一日目)で通過しました

ISUCON8予選に@catatsuy、@cubicdaiya、@syu_creamの3人でチーム「ここで一句」として参加してきました。 前回と前々回は予選落ちで悔しい思いをしましたが、今回は一日目で2位、全体で6位ということで予選突破できました。ISUCON5以来の本選出場です。 スコアは以下の通り。

f:id:cubicdaiya:20180917090950p:plain

すでに@catatsuyが書いてるエントリがありますが、ここではターニングポイントとなった変更を中心にもう少し詳しく解説していこうと思います。

medium.com

なお、言語はメンバーが使い慣れているGoを選択し、@cubicdaiyaがインフラ担当、残りの二人がアプリケーションのチューニングを担当という形で役割分担しました。

h2o -> OpenResty

リバースプロキシ自体はh2oのままでもスコアにはほぼ影響はなかったのですが、あまり慣れてないこともあって複数台構成にする際やロギングの設定で手間取りそうだったので早い段階でOpenRestyに切り替えました。結果的に複数台構成への移行やアクセスログからの傾向調査をスムーズに行うことができました。あとは静的ファイル向けにexpiresの設定をしたり、gzip_staticを有効にしたり。

N+1クエリを剥がす

アクセスログの集計結果やコードリーディングからgetEvent()getEvents()内のN+1クエリが重いよねってことで、これらを剥がす作業を@catatsuyが進めていきました。また、/api/events/:id/actions/reserve等にもN+1クエリがあったのでこっちの修正を@syu_creamが進めていきました。

reservationsテーブルへのインデックス追加

今回の問題ではreservationsテーブルのレコード数が多く、初期状態で20万件近くある一方でインデックスはevent_idとsheet_idの複合インデックスのみだったので、なんかありそうだなと思いつつ、少し手が空いたタイミングで↓ のSQLを発見したのでuser_idにインデックスを追加。

rows, err = db.Query("SELECT event_id FROM reservations WHERE user_id = ? GROUP BY event_id ORDER BY MAX(IFNULL(canceled_at, reserved_at)) DESC LIMIT 5", user.ID)
if err != nil {
    return err
}
defer rows.Close()

インデックス追加前後のEXPLAIN結果

実際の環境はMariaDBでしたが、ここではMySQL5.7を使って出力しています。

mysql> EXPLAIN SELECT event_id FROM reservations WHERE user_id = 1 GROUP BY event_id ORDER BY MAX(IFNULL(canceled_at, reserved_at)) DESC LIMIT 5\G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: reservations
   partitions: NULL
         type: index
possible_keys: event_id_and_sheet_id_idx
          key: event_id_and_sheet_id_idx
      key_len: 8
          ref: NULL
         rows: 191614
     filtered: 10.00
         Extra: Using where; Using temporary; Using filesort
1 row in set, 1 warning (0.01 sec)

mysql> ALTER TABLE reservations ADD KEY user_id_idx (user_id);
Query OK, 0 rows affected (0.21 sec)
Records: 0  Duplicates: 0  Warnings: 0

mysql> EXPLAIN SELECT event_id FROM reservations WHERE user_id = 1 GROUP BY event_id ORDER BY MAX(IFNULL(canceled_at, reserved_at)) DESC LIMIT 5\G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: reservations
   partitions: NULL
         type: ref
possible_keys: event_id_and_sheet_id_idx,user_id_idx
          key: user_id_idx
      key_len: 4
          ref: const
         rows: 33
     filtered: 100.00
        Extra: Using index condition; Using temporary; Using filesort
1 row in set, 1 warning (0.00 sec)

mysql>

ベンチマークのランダムfail地獄からの脱出

上述のN+1クエリをチューニングしてスコアが1,000~2,000点台から10,000点台にジャンプした一方で、このあたりから謎のfailに悩まされるようになりました。しかも毎回失敗するわけではなく数回に1回の頻度で失敗するという不安定な状態で、エラー内容を見ると/admin/api/reports/events/:id/salesのレスポンスにあるべきデータがないというメッセージが表示されていましたが、データベースの中を見ると該当のレコードはちゃんとあったので、ベンチマーカーがシビア過ぎて「変更が反映される前にリクエストが来てるんじゃね?」という推測の元、sleepを挟むようにしました。

--- a/webapp/go/src/torb/app.go
+++ b/webapp/go/src/torb/app.go
@@ -922,6 +922,7 @@ func main() {
        return nil
    }, adminLoginRequired)
    e.GET("/admin/api/reports/events/:id/sales", func(c echo.Context) error {
+       time.Sleep(time.Second * 10)
        eventID, err := strconv.ParseInt(c.Param("id"), 10, 64)
        if err != nil {
            return resError(c, "not_found", 404)

Goの場合は1プロセスで並行して複数のリクエストを処理できるのでtime.Sleep()を呼ぶだけで十分ですが、 RubyPythonでpreforkモデルのアプリケーションサーバを利用している場合に同じことをするのであれば前段のリバースプロキシでノンブロッキングスリープを入れると効果的です。 例えば、OpenRestyであればngx_luangx.sleep()を呼ぶことでノンブロッキングスリープが可能です。

location ~ ^/admin/api/reports/events/\d+/sales$ {
    rewrite_by_lua_block {
        ngx.sleep(10)
    }
    proxy_set_header Host $host;
    proxy_pass http://127.0.0.1:8080;
}

ひとまずこれでベンチマーク実行が安定するようになりました。ただ、ここでかなり時間をロスしてしまったのが悔やまれます。

pt-query-digestでスロークエリを集計して方針決め

N+1クエリが減ってMariaDBのCPU使用率がある程度下がり始めた & ベンチマーク実行が安定し始めたのでpt-query-digestでスロークエリを集計してアプリケーション担当に共有し、今後の方針決め。

汎用メソッドgetEvent()の置き換え

getEvent()が非常に汎用的なメソッドとして各所で利用されていましたが、もっとシンプルにできる箇所がいくつかあり、その修正を@syu_creamが進めていきました。(e.g. reservationsテーブルを引かない、eventsテーブルのみを引く)

複数台構成への移行

16時を回ったあたりで再度少し手が空いたので、複数台構成に移行する準備を始めました。この際、ベンチマークの実行先をMariadbの入っていないサーバに移したので、db/init.shを外部コマンドで実行している/initializeが動かなくなってしまったため、下記の設定を入れました。

location = /initialize {
    proxy_set_header Host $host;
    proxy_pass http://x.x.x.x:8080; # Mariadbのサーバに振る
}

最終的にはnginx & torb.go.service x 2、MariaDB x 1という構成になりましたが、結局MariaDBのチューニングが不十分だったせいか複数台にしてもあまりスコアは上がりませんでした。また、この時点で17時ちょっと過ぎ。スコアは25,000~29,000あたりをうろうろしている状況で、少し前にポータルで他チームのスコアを見た限り予選突破するにはもう1つブレイクスルーが必要そうな状況でした。

続・reservationsテーブルへのインデックス追加

まだアプリケーション側で改善できそうな部分の修正を@catatsuyと@syu_creamに任せて、何かないかと思ってソースコードを眺めていたら/api/events/:id/actions/reserveでこんなクエリを発見。

SELECT * FROM sheets WHERE id NOT IN (SELECT sheet_id FROM reservations WHERE event_id = ? AND canceled_at IS NULL FOR UPDATE) AND `rank` = ? ORDER BY RAND()

おや?

mysql> EXPLAIN SELECT sheet_id FROM reservations WHERE event_id = 3 AND canceled_at IS NULL FOR UPDATE\G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: reservations
   partitions: NULL
         type: ref
possible_keys: event_id_and_sheet_id_idx
          key: event_id_and_sheet_id_idx
      key_len: 4
          ref: const
         rows: 23504
     filtered: 10.00
        Extra: Using where
1 row in set, 1 warning (0.00 sec)

mysql>

んんー?

mysql> ALTER TABLE reservations ADD KEY event_id_idx_and_canceled_at_idx (event_id, canceled_at);
Query OK, 0 rows affected (0.27 sec)
Records: 0  Duplicates: 0  Warnings: 0

mysql> EXPLAIN SELECT sheet_id FROM reservations WHERE event_id = 3 AND canceled_at IS NULL FOR UPDATE\G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: reservations
   partitions: NULL
         type: ref
possible_keys: event_id_and_sheet_id_idx,event_id_idx_and_canceled_at_idx
          key: event_id_idx_and_canceled_at_idx
      key_len: 13
          ref: const,const
         rows: 1000
     filtered: 100.00
        Extra: Using index condition
1 row in set, 1 warning (0.00 sec)

mysql>

キタ━━━━(゚∀゚)━━━━!!

f:id:cubicdaiya:20180917090950p:plain

/api/events/:id/actions/reserveへのリクエストが多かったのとメソッドがPOSTで配点が大きかったので最終的にこの変更が決め手となり、20,000点以上ジャンプアップすることができました。ちなみに、この変更の直後に記録したスコアがベストスコアの49,329でしたが、その後再現することは叶わず。あとは再起動試験を行ったり、ベンチマークを何度か実行してフィニッシュ。

感想

中盤でランダムfail地獄に陥ってた時は完全にお通夜モードでしたが、そこからなんとか巻き返せたかなという感じです。本選もがんばります。

みんなのGo言語〜現場で使える実践テクニック〜

みんなのGo言語【現場で使える実践テクニック】

みんなのGo言語【現場で使える実践テクニック】

執筆陣の一人である@songmuさんから献本いただきました。ありがとうございます。

手元に届いたのが9月の海外出張当日で、最初は飛行機の中でゆっくり読もうと思ってたのですが、 行きも帰りも深夜だったせいかずっと眠ったままで海の向こうでもあまり読む時間が取れず、気が付いたら10月なっていました。

まぁ、言い訳はそれくらいにして感想を。

本書は開発環境の構築からGoのお作法に始まり、ビルド、ポータビリティ、テスト、シグナル、I/O、そして並行処理などなど、Goを触ったことがないプログラマにはもちろん、既に実戦で本格的にGoを使ってるプログラマにとっても有益な内容が数多く散りばめられていて、楽しく読むことができました。

かく言う私もプロダクション環境向けのシステムやツールをGoで開発していますが、「お、これは明日からでも使えるぞ!」といった気付きを得る場面がちらほらあり、「現場で使える実践テクニック」の名にある通り、Goプログラマにとってはデスクか本棚にThe Go Programming Language (Addison-Wesley Professional Computing Series)と一緒に並べておいて損はない一冊と言えるでしょう。

(一方でゴルーチンを利用した並行処理パターンの紹介やcgoについての解説がもう少し欲しかったかな、と思いました。)

#shibuyago #2でSlackboardの話をしました

shibuyago.connpass.com

Shibuya.go#2でSlackboardの話をしてきました。以下発表資料。

speakerdeck.com

資料にもあるようにSlackboardはSlackのプロキシサーバとそのためのクライアントプログラムで構成されるツールです。

github.com

具体的には以下の3つになります。

  • slackboard - Slackのプロキシサーバ
  • slackboard-cli - slackboardとの通信用クライアント
  • slackboard-log - cronlogライクなslackboard-cli

今回はSlackboardの一通りの使い方とそもそも何故Slackのプロキシサーバが必要なのかという話をしました。後者は簡単に言うと、

  • Slackに通知されるメッセージとログの集約
  • Slackへの通知方法の統一

ということになります。サーバの台数やコンポーネントの数が多い環境だといろんなサーバからSlackにメッセージがポストされるようになってくるのですが、各サーバから個々にSlackに通知していると、

  • 肝心のメッセージがどこから飛んできているのかわからない(管理が大変)
  • チャンネル名変えたけど、まだどっかのサーバから古い名前のチャンネルに通知してた(結果通知が届かない)
  • 各所でSlackに通知するために利用しているプログラミング言語やライブラリがバラバラ(メンテコストが上がる)

ということが起こります。また、実際に上記の事態に遭遇したのがSlackboard開発のきっかけでもあります。今は全サーバにslackboard-clislackboard-logがインストールされているのでとても楽だなぁという感じです。

さいごに、会場とピザとビールを提供してくださった@suzu_vさん、VOYAGE GROUPさん、ありがとうございました。