TL; DR
後は備忘録的にやったことや、嵌った点などをツラツラと。
スコア
予選と違っていつもと同じリクエスト数基準になりましたが、ベンチの出来が良いのか、スコアはかなり安定していたように思います。
他のチームだとリクエストを捌ききって、3連続で同じスコアとかもあったみたいですが、見た感じこちらでは起きていないので、まだまだ足りなかった様子。最後までCPUボトルネックでした。
- 初期実装 + 少しIndex: 1,227
- 1台構成で最適化: 8,181
- 3台構成(?): 19,023 ※後述
- 再起動後: 0 (Fail)
やったこと
事前準備
環境構築や測定用のスクリプトを準備。
- いつものdotfiles
- pt-query-digest
- kataribe
- netdata
1人参加では全体をいじるのはどうやっても手が足りないので、予選と同じく、計測して一番重い場所を直す、の繰り返しで進めることにする。
当日朝
9:15ぐらいに会場入り。すこし悩んだけどキーボードとマウスを持ち込みで。
焦っているときのタイプミスはさらなる焦りを呼ぶので、持って行って良かったと思う。
10:00-11:30
一人参加のメリットを活かして3台のサーバーにいつものdotfiles / 開発環境を構築。
続いて計測用の設定……あれ、/etc/mysqlがスカスカ？ってdocker composeだ！
だいぶ前の記憶を呼び起こしつつ、isutrain/webapp/mysql/conf.dにslowクエリ用設定を書くが、slow_query_log_fileは変更されるのに、slow_query_logがOFFのままという問題に悩まされる。
mysql> show variables like 'slow%';
+---------------------+-------------------------+
| Variable_name | Value |
+---------------------+-------------------------+
| slow_launch_time | 2 |
| slow_query_log | OFF |
| slow_query_log_file | /var/log/mysql/slow.log |
+---------------------+-------------------------+
3 rows in set (0.00 sec)
試行錯誤して解決したが、 /var/log/mysql/slow.logへの書き込み権限が無いとOFFになる様子。
（ONだけどファイルが作られないなら、すぐに気づけたと思うんだが）
改めてdocker logs見たら書いてあったので、Docker慣れが足りなくてもったいないことをした。
2019-10-06T01:25:44.909172Z 0 [ERROR] [MY-011263] [Server] Could not use /var/log/mysql/slow.log for logging (error 13 - Permission denied). Turning logging off for the server process. To turn it on again: fix the cause, then either restart the query logging by using "SET GLOBAL SLOW_QUERY_LOG=ON" or restart the MySQL server.
11:30-11:50
Slowクエリを元にIndexを追加。
とりあえず検索結果が見られるようになったのでベンチ実行
【初期スコア 1,227】
12:00-12:30
お昼ご飯食べながら方針検討。
デバッグのしやすさなどを考え、開発中はPythonをDockerコンテナの外に出すことに。
search/seatのN+1がひどいのでそこから手を付けることにするが、200行近くあるメソッドにめまいがする。
塚田農場のご飯美味しい。
13:25
station_masterをオンメモリに。/api/train/searchが少し落ち着いたので/api/train/seatへ
【スコア 1,503】
14:25
reservationsにdeparture_id, arrival_idを追加して、2テーブルの結合で済むように。
優勝チームの話を聞いているとseat_reservationsの方に追加していれば1テーブルで済んだようだ。
【スコア 3,895】
15:50
seatのN+1を解消。
ご丁寧に「他予約の下車駅と自分の乗車駅が同じ場合は予約が取れる」といった仕組みがあるので、不等号にはまる。
あのドタバタの中で<と<=の条件を（しかも被る条件が欲しかったので反転して）考えるのは焦りっぷりがすごい。
readlineのバージョン？なのか、mysql-cliで検索クエリに日本語が入れられなかったのも拍車をかける。なんとか修正。
seat_list[seat_row * 5 + seat_column]['is_occupied'] = Trueで直接occupiedフラグを書き換えられないかと思いついたが、先にデータ確認したら4列席の列車があったので断念。
【スコア 4,509】
16:10
あれこれ嵌ってたのもあって、時間がたつのが早い。
手が入れられていないpaymentやロックで待ち時間があるのもあって、CPUの上下移動が激しくなってきたので、（予選でもスコアがはねたし）APサーバーの台数を増やすことに。
とりあえずworkerを増やしてみる。
【スコア 6,715】
～16:53
ロック漏れによる多重発券に悩まされFail連発。
そういえば、事前説明に「ロックがちゃんとしていない」とあったなぁ……
読んではみたものの、300行近くあるreserveで原因追及は残時間では無理！と、広めのテーブルロックをかけて対処する。
【スコア 6,959】
17:00
残り1時間。
時間的には再起動試験とかに入りたいところだが、worker増加の効果が分かっているし3台は使い切りたい。
（実際はこの前にもベンチマーク中にB/Cサーバーの設定などは行っていたのである程度の準備はできていた）
なんとなく一番後ろがDBの印象があるのでサーバーCをDBサーバーにすることに。
docker-compose.db.ymlとして切り出して、マニュアルに従ってDBサーバーを再構築……あれ、重……い……？
原因自体は（おそらくだが）すぐに分かった。
01_schema.sqlにあれこれIndexを張った状態で、時刻表マスタの280万件をいれようとして、死ぬんだ。RAM1GBの非力な環境というのも影響して、Swap地獄になっているっぽい。
状況はみるみる悪化し、SSHはつながらない、psは結果が返らない、systemctl stopも動かないとボロボロに。
[isucon@team103-c]~ % ps -eaf | grep mysql
zsh: fork failed: cannot allocate memory
ぎりぎり残っていたターミナルからsudo systemctl disable isutrain-db; sudo rebootを投げるが反応が無い。エラーにはなっていないので、通るのを祈る。1
これ、もう無理じゃね？と思いつつも1台構成では10,000超えないのもわかっているので、ギリギリまであがくことに。
サーバーCは無事再起動できたとしても、データが破損してるので使えない。
サーバーBをDBサーバーにすることにして、同じ轍を踏まないようにALTER TABLEしていく。
01_schema.sqlにしか変更を残していなかったので、git log -pからALTER TABLEを作るのがまた大変。
並行してサーバーAのnginxにロードバランシングの設定を追加。
これ自体は予選の時にも経験済みなのでさくっと。
17:35ぐらい？
サーバーCがなんとかsudo rebootまで通って再起動してくれたので、DBサーバーからAPサーバーに仕立て直していく。
あわわわわ
17:52
どのタイミングで実行してたのかわからないが、少しだけ高いスコアが記録されていた。
--workers 4あたりだろうか。
【スコア 8,181】
17:55
APをdockerコンテナに戻したらDBに繋がらない！
.envにはMYSQL_PORTが無いことに気づき、慌ててDBサーバーを3306:3306に。
17:56
正直、これがなぜ通っていたのか、いまだによくわからない。
当時は以下の3台構成が動いたと思っていた。
- A: APサーバー(4worker)
- B: DBサーバー
- C: APサーバー(4worker)
が、再起動後の状況を見るとサーバーCは.envが最新化されておらず、DBサーバーへの接続ができていなかった。（ので最終結果がFail）
サーバーAでsystemctl restart nginxしたタイミングが分からないが、ひょっとすると、ロードバランシングの設定書いた後に再起動していない？
ただ、下記構成で19,023出るかというと……謎。
- A: APサーバー(4worker)
- B: DBサーバー
【スコア 19,023】
17:57
再起動しても問題を直す時間は無さそう。
APサーバー/DBサーバーを頻繁に切り替えたのもあって、systemctl disable/enableの確認と修正に時間を費やす。
（後から考えるとそれでも再起動しておくべきだったか……）
前述のとおり、サーバーCで最後のgit pullが漏れており、.envが最新化されていなかった。
結果、MYSQL_HOSTがサーバーBになっておらず、接続に失敗。
ということで最終結果はFail(0)となりました。
もったいないことしたけど、最後の1時間は全力以上でやり切った感はある……でもスコアが残らないのはやっぱり悔しい。来年の開催があったら残り時間を考えつつ頑張ろう。
最後になりますが、運営・問題作成・サーバー提供をしていただいたLINE様、さくらインターネット様、mercari様、Alibaba Cloud様、楽しいイベントをありがとうございました！
