開発^3

Web開発、宇宙開発、ゲーム開発の3種類についてつらつらと

ISUCON9本選でFailしてきました

TL; DR

後は備忘録的にやったことや、嵌った点などをツラツラと。

スコア

予選と違っていつもと同じリクエスト数基準になりましたが、ベンチの出来が良いのか、スコアはかなり安定していたように思います。
他のチームだとリクエストを捌ききって、3連続で同じスコアとかもあったみたいですが、見た感じこちらでは起きていないので、まだまだ足りなかった様子。最後までCPUボトルネックでした。

  • 初期実装 + 少しIndex: 1,227
  • 1台構成で最適化: 8,181
  • 3台構成(?): 19,023 ※後述
  • 再起動後: 0 (Fail)

f:id:sheile:20191006184046p:plain

やったこと

事前準備

環境構築や測定用のスクリプトを準備。

  • いつものdotfiles
  • pt-query-digest
  • kataribe
  • netdata

1人参加では全体をいじるのはどうやっても手が足りないので、予選と同じく、計測して一番重い場所を直す、の繰り返しで進めることにする。

f:id:sheile:20191006184316j:plain

当日朝

9:15ぐらいに会場入り。すこし悩んだけどキーボードとマウスを持ち込みで。
焦っているときのタイプミスはさらなる焦りを呼ぶので、持って行って良かったと思う。

f:id:sheile:20191005091851j:plain

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行近くあるメソッドにめまいがする。

塚田農場のご飯美味しい。 f:id:sheile:20191005120429j:plain

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様、楽しいイベントをありがとうございました！

  1. 終了後にサポートチャットを見たら、似た症状で再起動してもらっているチームがあった。なかーま。↩