ISUCON8予選に「西アジア代表」として参加してきました

f:id:kasari:20180925070121j:plain

（チーム名です。実在の西アジアとは一切関係ありません）

結果から言うと惨敗でした。Fail Finishです。（BestScoreは16000ほど）

西アジア代表としての責務を果たせなかったことが悔やまれます。

チームメンバー、言語

チーム構成はアプリ2名、インフラ1名。言語はGo。

kasari アプリ
dobai アプリ
tky インフラ

予選開始

開始と同時にポータルにアクセスし、即Enqueue。初期実装はPerlで900。

Go実装に切り替えてもう一度Enqueue。1300。

tkyにプロビジョニングをお任せして、その間にレギュレーションの確認とアプリ全体の雰囲気を見る作業に入りました。

プロビジョニング終了後

SSHログインしてインスタンスの雰囲気を掴みます。

CPU数、メモリ、起動プロセスを見ていくと、H2Oが起動しているのを見つけました。

ここでnginxに乗り換えるかどうかの判断がありましたが、alpで計測したかったのと、今回の問題は複数台構成を考慮する必要があったため、チームが慣れているnginxのほうが良いだろうと乗り換えることに。

alpがすぐに用意できそうもなかったので、とりあえずpprofで計測。

pprof

(pprof) top -cum 40
Showing nodes accounting for 4.92s, 36.96% of 13.31s total
Dropped 238 nodes (cum <= 0.07s)
Showing top 40 nodes out of 178
      flat  flat%   sum%        cum   cum%
         0     0%     0%     10.61s 79.71%  net/http.(*conn).serve
         0     0%     0%     10.57s 79.41%  github.com/labstack/echo-contrib/session.MiddlewareWithConfig.func1.1
         0     0%     0%     10.57s 79.41%  github.com/labstack/echo.(*Echo).ServeHTTP
         0     0%     0%     10.57s 79.41%  github.com/labstack/echo/middleware.LoggerWithConfig.func2.1
         0     0%     0%     10.57s 79.41%  net/http.serverHandler.ServeHTTP
         0     0%     0%     10.56s 79.34%  github.com/labstack/echo.(*Echo).Add.func1
     0.06s  0.45%  0.45%      9.10s 68.37%  main.getEvent
     0.01s 0.075%  0.53%      5.42s 40.72%  database/sql.(*DB).QueryRow
     0.02s  0.15%  0.68%      5.41s 40.65%  database/sql.(*DB).QueryRowContext

明らかに main.getEvent がボトルネックになっていたので getEvent の改善に取り掛かることに。

getEventのN+1問題

getEvent は典型的なN+1問題でした。Sheets(1000件)分ぐるぐると Sheet に紐づくReservation を取得するようになっていたので、Event に紐づく Reservation は一度に取得するようにして後はアプリ側で正しい Event を組み立てるようにします。

この組み立て作業が案外難しくバグつぶしに1時間ほど取られ、最終的にこの変更がマージされたのは13:30頃になりました。

[13:30] 1300 → 7520

実はこのときに、たまに↓のようなエラーで Fail するようになっていましたが、再現性が低かったのと、軽く調査したところ何処に問題があるのか分からなかった。また、ここで立ち止まっては予選通過点を取るのは厳しいと判断し、一旦後回しにしました（敗因）

「イベント(id:11)の総残座席数が正しくありません」

結局このエラーに最後まで捕まり Fail Finish することになります...

このエラーについては感想戦で調査し、これが原因なのでは？というものを見つけたので一番下に書いておきます。

Sheets のオンメモリ化

getEvent の中で毎回 Sheet を全取得している処理があったのでそこの改善に取り掛かりました。アプリを眺めてみると Sheet は参照にしか使用されず、マスターデータのように扱われていたためオンメモリ化で行けるやろとバシッと決めました。

getEventsのN+1問題

ボトルネックが getEvents に変わっていたので、getEvents の改修に取り掛かります。やったことは getEvent とほぼ同じです。

この2つが入り順調に点数を伸ばします。

[15:00] 7520 → 14000

この時点では中々順調でした。この流れで伸ばしていけば予選突破行けるのでは？という雰囲気がチームにあったと思います。

ちなみに7520の頃より高い頻度でFailするようになっていました。

/api/users/:id

次のボトルネックに移ります。

こいつは中々に強力な見た目をしていて実装の把握に手間取りました。

このAPIはユーザーの「最近予約したイベント」「最近予約した席」「予約総額」を返していたわけですが、初期実装の複雑なクエリとその中のLIMIT 5という文字を見た瞬間に僕は、ははーん、さては Redis だな？と勘ぐってしまいます。

んーむんーむとどのように実装しようかと悩みながらもう一度クエリを見直すと、3つのクエリに含まれているwhere user_id = ? の文字を見つけます。まさかね。と思いつつも Reservations の schema を見てみると user_id の index がありません。はい、Add Index。

また、初期実装では getEvent によって Event を取得していましたが、処理内で Event のカラムしか使っておらず、getEvent で取ってきた詳細なデータが無駄になっていることが判明。単に Event の Row を取得するようにしました。

この2つで /api/users/:id の対応は十分でした。

[17:00] 14000 → 16000

ここでハネるつもりだったので、辛かった...

またこの頃にはほぼ100％Failするようになっていました。

Fail脱出を目指して...

もう残り時間は1時間を切っているわけで、完全に手遅れじみていますが諦めるわけには行きません。ただ、この時の記憶がどうも残っていません。PR を Revert したり、アプリの状況とDBのデータを見比べたりしていたと思います。まぁ最後までFailだったわけですが。

敗因

たまのFailを甘く見てはいけない。

あとは自分の中で計測を当てにしすぎてしまった部分があると思います。「推測するな計測せよ」に乗っ取り、計測によって見つけたボトルネック以外の問題に対する修正が消極的になっていました（むしろ悪だとも考えていた）。ただ今回、自分がIdle状態になる時間があったのでもっと手を動かしてしまってた方が良かったかもしれないです。あと適切なIndexが貼れているかは計測しなくてもわかるので先に一通り見ておくべきでした。

単純に実装力が足りなかった問題もあります。残席の管理にRedisのSet型を使えば予約処理がDBトランザクションから開放され上手く回りそうだという思いつきはありましたが、Goでスラスラと実装する力がありませんでした。ここらへんは感想戦で実践しましたが、これが入っていたら本戦も届き得たかもしれません。（あのとき足踏みせず途中でググるはめになることも恐れず突き進むべきだったのかも）

感想

8時間フルに頭を使った良い問題でした。

モダンなポータルサイト、遅延の無いベンチ環境のおかげでとても快適に問題に取り組むことができました。 ISUCON運営チームの皆様、本当にありがとうございました。

くやしい！

感想戦

くやしい...

とてもじゃないけど仕事が手に付かないよ...

お！？？？

ISUCON8予選時のインスタンスですが、ベンチマーカーも動くようにしていただきましたので感想戦などでお使いください（DeNA様、GMO様ありがとうございます） #isucon
※9月25日(火)に一律停止します
※実際の予選と同じスペックですが密集度が異なるためスコアが同一の水準に満たない場合があります
— ISUCON公式 (@isucon_official) 2018年9月18日

やるっきゃない！！！

f:id:kasari:20180925073419p:plain

西アジア代表の名に恥じないScoreが出せました。

太っ腹な対応本当にありがとうございました。これでぐっすり眠れます。

（おまけ）感想戦でのFail原因調査

「イベント(id:11)の総残座席数が正しくありません」

親の顔より見たこのエラー文言。このときのDBに対して調査を行います。

最終Commit時の getEvent で叩いているクエリを直接叩いてみます。

SELECT * FROM reservations WHERE event_id = 11 AND canceled_at IS NULL GROUP BY event_id, sheet_id HAVING reserved_at = MIN(reserved_at) ;
+--------+----------+----------+---------+----------------------------+-------------+
| id     | event_id | sheet_id | user_id | reserved_at                | canceled_at |
+--------+----------+----------+---------+----------------------------+-------------+
(略
| 192012 |       11 |      967 |    1377 | 2018-09-18 10:58:20.653794 | NULL        |
| 192523 |       11 |      969 |    3819 | 2018-09-18 10:58:37.199788 | NULL        |
| 191863 |       11 |      970 |     640 | 2018-09-18 10:58:10.221825 | NULL        |

ここでは sheet_id:968 の予約は存在しないことになっています。

では次に、本当に sheet_id:968 の予約は存在しないのかどうかを確認してみると...

MariaDB [torb]> SELECT * FROM reservations WHERE event_id = 11 AND sheet_id = 968;
+--------+----------+----------+---------+----------------------------+----------------------------+
| id     | event_id | sheet_id | user_id | reserved_at                | canceled_at                |
+--------+----------+----------+---------+----------------------------+----------------------------+
| 192372 |       11 |      968 |    4786 | 2018-09-18 10:58:33.126873 | 2018-09-18 10:58:33.771982 |
| 192464 |       11 |      968 |    4737 | 2018-09-18 10:58:35.471536 | NULL                       |
| 192467 |       11 |      968 |    2099 | 2018-09-18 10:58:35.471492 | NULL                       |
+--------+----------+----------+---------+----------------------------+----------------------------+

あれ？あるぞ！！！！（しかもCancelされていない予約が2件）

どうやら reserved_at = MIN(reserved_at) で reservation(id:192372) を選択し、それが WHERE canceld_at IS NULL で弾かれているため sheet(id:968) は予約されていないことになっているようです。

初期実装のクエリで試しても同じ結果でした。（最終Commitとの差分は AND sheet_id = 968 の部分のみ）

MariaDB [torb]> SELECT * FROM reservations WHERE event_id = 11 AND sheet_id = 968 AND canceled_at IS NULL GROUP BY event_id, sheet_id HAVING reserved_at = MIN(reserved_at);
Empty set (0.00 sec)

つまり初期実装の段階で、この reservations のデータだと（現実に反して）sheet(id:968) は予約されていないとして返していたことになります。このズレがBenchmarkerのFailを引き起こしていたのではないでしょうか？

また、別ユーザーが同席を予約できてしまっているこの状況も /api/events/:id/actions/reserve は初期実装のままいじっていなかったため、恐らく元からだったのではと思います。

予約席選択のSELECT FOR UPDATE はトランザクション外にあり、また reservations に unique 制約も無いため、確かに別ユーザーが同席を予約出来てしまいそうです。

考察

負荷レベルが上がったことにより予約APIの叩かれる数が増えるにつれ、上記の様な reservations のデータ状況に陥る可能性は高くなります。そしてその結果 getEvent が Fail していたのでは？と考えます。

ただ、他のチームが難なく点数を伸ばしていたことを考えると、全ては自分の勘違いの可能性が...

ちなみに感想戦で採用した現実に即したクエリは以下になります。おやすみなさい。

SELECT * FROM reservations WHERE event_id = ? AND canceled_at IS NULL GROUP BY event_id, sheet_id ORDER BY reserved_at