ISUCON5予選で失った人権を取り返すために奮闘したが、駄目だった。この悔しい思いを忘れないようにするためにもISUCON6予選での作業ログを残す。

チーム名

yokohama-north

メンバー

• @trtraki => PHP環境構築, 実装切替, アプリケーション改修担当
• @bati11 => インフラ, DB, サーバリソースの監視
• @hanhan1978 (自分) => アプリケーション改修のみ担当

10:00 〜 11:45

デプロイ待ち。15分くらいしたらssh出来るようになったので、自分のタスクに取り掛かった。私はアプリ改修のメイン担当なので、画面遷移図の作成・ソースコードの分析、修正箇所の洗い出しを行った。

最初の時点で、ソースコードのみから判断出来たことは以下の通り。

• エンドポイントが少ない。
• テーブルが少なく、かつデータ量も少ない。
• htmlifyの正規表現はやばい。
• 内部でHTTP通信を使っている箇所が何個かあってボトルネックになりそう
• spamチェックの怪しい5050ポートのサービスも発見。
• userテーブルは不変っぽい。

11:45

それぞれの初期タスクが終わり、実装がPHPに切り替わったタイミングで対策会議を開いた。

ボトルネックは明らかにhtmlifyで、それ以外のボトルネックが全く見えてこない状況なので、アプリのメイン改修担当である自分はhtmlifyを倒すという方針で確定。エンドポイント内でのHTTP通信撲滅や、全体に散らばるSELECT *については、@trtrakiに対応をお願いした。

userテーブルのキャッシュや、isudaとisutarの統合についても話題にはなったが、その時点でボトルネックにはなっていなかったので放置した。これは正解であったと思う。

12:00 ~ 13:00

• アプリケーションをgithubのプライベートリポジトリに登録
• 修正候補の内容を付箋でチケット化し、isudaとisutarそれぞれで管理
• 環境構築をしていた@trtrakiにアプリケーションの構成や、細かい挙動について説明
• 修正チケットを@trtrakiに依頼すると共に、修正方法や作業方法について細かく意識共有

今回はアプリケーションの改修担当が自分と@trtrakiの2人だったので、特に両名でイメージのズレが発生しないように初期段階での共有にきちんと時間を取った。また、各修正の対応後は必ずベンチマーカーを回して動作確認を行い、PRを出してもらい相手に確認を取った上でマージするやり方にした。

13:00〜16:00

htmlifyの対応の一つ目。SELECT * FROM entry...でRDBから取得していたkeywordをRedisのZSETに切り替える対応を行った。対応自体は1時間もかからず終わったのだが、initialize処理が5秒以内ということだったので、Redisをdumpからレストアする仕組みを作るのに結構時間がかかってしまった。

Redisのレストアの仕組みは、以降のRedis対応でずっと役にたったので無駄ではなかったのだが、もっと短時間で出来たら・・・と悔やまれる。

16:00〜16:50

@bati11に再度ボトルネックの調査を以来したところ、ボトルネックがMySQLからPHPに移ったことが確認された。ここで、ISUCON用に用意したお手製のProfilerを仕込んで処理時間を計測したところpreg_matchがやはり遅い。

色々と協議した結果、素敵なアルゴリズムとかは全然思いつかなかったので、htmlifyのキーワードを各entryごとに事前に抽出してredisのZSETに突っ込むことにした。ベンチマーク中に新規登録されたkeywordはRedisのsetに追加して、事前抽出のZSETにentry読み込み時に追加してやるという方針を取ることにした。

方針が決まると、対応自体は15分程度で終わったのでベンチマークを流して動作確認。提出用インスタンスにも反映して動作確認した。この時点で60000くらい。

16:50〜17:50

@bati11と@trtrakiがspamチェックのアルゴリズムを精査してNGワードを拾っている間、サーバ再起動のテストを行った。結果としては再起動しても上手くphp-fpmが動作せず一気にパニックに・・・。

少し手が震えていたが、一個ずつ原因を拾っていったところ、環境構築時に新規インストールしたphp-fpmの起動スクリプトが邪魔をしていることが判明。systemdでdisableして、もう一度再起動してみるがやはり動かない。

震える手でなるべく冷静を保ってログを確認したところ、/var/runの下にPIDが作れていないことがわかったので、PIDの作成先を/tmpに変更して、再起動テストをもう一度行ったら、立ち上がってくれた・・・。

再起動テストの内容を提出用のインスタンスに適用して、再起動テストが終わったのが17:50。最後のベンチマーカーが終わったのが17:55。この時点で83000程度。精も根も尽き果てたので、後は祈るのみ。

振返り

予選ボーダーは90000点だったので、あと1手足りていなかった。予選後に冷静になった頭で考えて見れば内部リンク候補のkeywordをキャッシュするのではなく、preg_matchの結果をキャッシュすべきであった。新しいキーワードが追加された場合の即時反映は考える必要があるが、preg_matchをなるべくやらないという方向性のが圧倒的に正しい気がする。

また、最後にはRedisがボトルネックになってきていたので、opcache等で上手くPHP間で使いまわせていたらどうだったろうか・・・とか、反省は尽きない。

過去のISUCONではRedisがボトルネックになるところまでチューニングが進まなかったので、大いなる進歩であるとは思うのだが、少し手が届かなったという厳しい現実とこれからまた一年向き合っていきたい。

アプリケーションが速いということは、どういうことなのか？今までよりももう少し踏み込んだ領域を学習していかねば。

まとめ

まずはISUCON6の運営の皆様に対する感謝の思いでいっぱいです。たくさん成長させてもらいました、毎年結構成長しているつもりが、ISUCONではあと少し届かないという状態を繰り返しているので、来年こそは人権を取り戻したいです。

※ISUCON7があれば・・・ですが。あってほしいなぁ・・・

おまけ

リポジトリ

私(@hanhan1978)と@trtrakiの対応内容がPR単位で見れますので、PHPの修正実装に興味があればどうぞ。

https://github.com/hanhan1978/isucon6_qualifier

エンドポイント分析シート

画面遷移図

ISUCON5予選後からISUCON6予選までにやってきたこと。

• PHPとWebサーバの組み合わせの確認
  4ヶ月くらいかけてベンチマークして、勉強会で発表とかしてました。
  PHP7 Casual Talks 2でI○UCON対策について話してきました。
• Redisについて一段深い学習
  特にデータ構造と、各関数の計算量については何度も復習しました。今回スムーズにredisを利用できて、かつベンチマーカーでもほとんどfailを出さなかったのはredis学習の成果と思っています。
• 通し練習 x3
  メンバー全員が既婚なので、週末一日潰すのは調整が大変なのですが合計3回行いました。pixiv-isuconの問題を使って練習しました。