ISUCON6本戦で惨敗した

はじめに

Catechinというチーム名で大学の友人(@Kender_09, @o_sama3)とISUCON6に参加してきました。 結果はタイトル通り惨敗で、最初に気づいたボトルネックに全く手を付けなかったくらい、迷走してしまいました。

チーム内での役割は緩やかに分担していて、DB周りは僕、nginxは@o_sama3、golangのプロファイリングは@Kender_09でしたが、基本的に一人に丸投げではなく、3人で共有しつつ属人化は避けようにしていました。 3人ともそれほど何かに詳しいわけでもなく、ISUCONのために勉強する部分も大きかったので、判断ミスを防いだり、練習時は一緒に議論が出来たりしたので、良かったと思います。 言語はせっかくISUCON参加するならGoでと思って、予選前からGo一択で練習に付き合ってもらっていました。2人ともありがとう。

順位的には残念な結果に終わってしまったけど、練習から予選、本戦とやってこれて楽しかったです。 本戦の静かだけれど確かな緊張感も味わえたので、来年もあれば参加したい！

また、ISUCONの開催は、出題する会社のトップエンジニア数人を少なくとも1ヶ月分は拘束するから優勝賞金とか目じゃないほどのコストがかかっていると聞いて、ISUCON開催の大変さを思い知りました。 ISUCON運営陣の方々ありがとうございました。

あまりスコアも良くなかったので、当日にやったことを書く気もしないし、本戦の内容や解き方は他のブログに任せて、ここでは本戦に向けて準備したものと敗因について書いておきます。

準備

練習中に準備したものや作ったものたち。

MySQLWorkbench

http://www.mysql.com/products/workbench/

公式でサポートされていそうなクライアントアプリケーション。 5.7から標準で導入されているsysスキーマを使ってstatement毎の実行時間その他もろもろの情報を確認できる。
mysqlが5.7以降でないとPerformance関連の機能は使えないので、5.6以下だったらら入れ替えるつもりだったけど、予選からちゃんと5.7で良かった。

pt-query-digestでやるのがお手軽かと思いきや、

• ログが多いと集計に数秒かかる
• 上位5個しか見られない（過去問で/initializeがあるとそのデータ作成が入って3,4個しか見られないこともある）
• ベンチ毎にログローテートをしなければならない

といった不満点がある。

これをスッキリ解消して、かつindexの利用状況等他の統計情報も1,2クリックで見られる。

sysスキーマの情報はDROP DATABASEや再起動できえてしまうので、slow logはとってもいいかもしれないが、あまりコンテスト中に振り返ることがなかったので、本番はこれだけで十分だった。

例えば今回の本戦でpointsテーブルにカバリングインデックスを貼ったことでpointsテーブルの他のIndexが使われなくなったのがわかる
ここにインデックスを貼ってる時点でやること間違っているのがひどい。。。

Sequelpro

MySQLWorkbenchは中身のデータを確認するには若干時間がかかるので、初期のデータやテーブル定義、INDEXをシュッと確認するにはsequelproも良いと思う。
コマンドライン上で確認しても良いけど、isuconだとblob型で画像が入っていたり、ちょっと手動で追加したデータを確認したいのにカラム指定したりソートしたりLIMITするのは面倒なので、慣れていてもこっちのほうが速いでしょという感じ。

nginxのログ可視化

nginxのログをkibanaで可視化

github.com

予選ではnginxのログからalpを使って集計していました。 ここから更にベンチマークのリクエストの傾向を時系列で確認したいとなったのでnginxのログを固定にして、Elasticsearch+kibanaで可視化するようにしてみました。 nginxでcookieの値を出力して、ログイン中のユーザがどのくらいに頻度でアクセスしているのか、ベンチマークに何かしらの偏りがあるのかを確認するのに便利でした。

とりあえずフルパスとcookieの値を出しておいて、kibana画面からフィルタリングしながら必要な項目を見てみるという感じで使えます。

コンテスト中に使えるかというと、urlの形式にあわせて修正しないと行けない部分がいくつかあるので、かなり微妙です(´-﹏-`；)

go-command_metrics

github.com

golangでの外部コマンド実行時間を計測します。

pprofはシンプルなprofilerなので、命令毎の総実行時間を計測してくれたりはしません。

golang で sql, template, http リクエストのパフォーマンスメトリクスとるライブラリ作りました

で紹介されているメトリクス測定ツールが良くて、これと同じようにgoの外部コマンドの実行時間も図ってみようと思って作りました。
Run()とOutput()に対応しています。

実際にはgoで外部コマンドする問題は実行時間というより、その間goroutineを止めてしまうということにあるので、実行時間を計測する必要はない気がします。

他

かなり雑に作ったセッティング用のファイルたち。

https://github.com/tom--bo/settings
confファイルのサンプルとかインスタンスに置いておきたいrcファイルとか

https://github.com/tom--bo/isucon_ansible
サーバセッティング用のansible

Postmortem

当日にやったことを書くことにはあまり価値がなさそうなので、次回につなげたい所。未来の自分向け。 （Postmortemって単語を使いたかっただけ）

メンバーと振り返って話していても、当日の空気とDocker,Reactに飲まれたのか、チーム全員が優勝を意識しすぎて、何でこんなところから手を付けたんだろうねと言うものが多くて悲しい。

そもそも、コンテスト全体で最終スコアがここまで低いと思っていなかった(優勝チームで55000点程度)というのもある。 しかし、そういった点も含めてISUCONなので、なにを言ってもしょうがないが、次回に活かすためにも敗因を整理していこう。

DockerとReactを調べておきたいという気持ちが強くなって、ボトルネックが何処なのか、何処が一番の回収どころなのかの判断がつかなくなってしまったのが原因だと思う。

• DockerとReact

  • 僕自身がDockerはこの夏ちょっと触ったくらいで、チームの2人は全く触ったことがない状況だった
  • Dockerを挟むことでパフォーマンス上の問題が起こるか不明だったこともあり、とにかく撤退しようとした
  • React, Dockerとほとんど経験のないものに意識が行き過ぎていて、落ち着いてどこがボトルネックなのかというのを考えられなかった。
  • 「おちついて、何処がボトルネックか考えよう」って3回は言った覚えがあるけど、まともに考えられなかったのが不思議。
    • 普段から色々な技術を触ろうねという話もあるが、それよりも焦っても原則に立ち戻って冷静な判断が出来るようになりたい。
    • 口でいっても難しいので、やるべきことのリストを書き出して、優先度付をリストに書き加えるとかすると良さそう。
    • リストの大まかな項目として「ボトルネックはどこか」とか何時までにどの問題に取り組むのかとかを決めると多少は冷静になれると思った。

• Error内容を軽視しすぎ

  • golangのコネクション数が多くなったことで出た"too many open files"を見て思いつく対策方法を取り始めたが、エラー番号も含めて考えていればより正確な解決方法に気づ桁かもしれない。
  • systemdでのエラー内容の見方に戸惑った。練習でも何度か見ていたのに、、、

• アプリケーションをスケールする作業を優先した

  • 開始前からの方針の間違い。
  • これが一番良くない失敗だった。
  • 最終的に（おそらく）アプリケーションサーバを状態を持たないようにしてスケールさせることを考えると、I/Oやネットワーク帯域などCPUバウンドでない部分が問題になる可能性もあると考えて、複数台構成にしてからボトルネックと対策を検討しようとしていた。
  • これによってオペレーションコストも増加し、メンバー間での同期作業も増えるばかりで良いことがなかった。
  • 最終的な構成が多くなっても初期実装の1台のときの構成と思い箇所は大きく変わらないので、まずは1台で考えるほうが効率が良いと教わった。

• チーム間で気遣うことを気にしすぎ

  • どうしても作業中に割り込んでそれなりに重要な会話をしなければいけないことが多いので、言葉遣い等に気を使って会話をするようにしていた。
  • 一方でなかなかチームの人もそうしてくれるわけではなく、いらいらすることがあった。
  • 強い口調を使うのは良くないと思うけど、そこに気を取られすぎた気もする。。。
  • クソなものにはとにかくクソと言いたい人もいるし、あまり気にしない強い精神も必要。

感想

アプリケーションのパフォーマンス改善はうまくいくとバグとり以上に楽しい作業で、まさにそれがコンテストになったISUCONは僕には最高に楽しいイベントでした。

パフォーマンスチューニングに関してはSystems Performanceを読んでいる途中(ISUCON本戦までに読み切っていたかったけど全然...)だけれど、ISUCONに参加することで、実際にどういった観点でパフォーマンス改善に取り組めばよいかを実践で考えることが出来てよかったです。

goの参考実装があるISUCON3以降の予選と本戦、Pixiv社内ISUCONはとりあえず全部環境を用意して3人で練習して、AWSに1.7k円突っ込んだのにこんな結果で残念ですが、集まって練習するのも楽しかったし、勉強になりました。

アプリケーションもベンチマークもあるので、変更の効果を感じやすくて楽しい(=ﾟωﾟ)ﾉ

準備したと思っていても、ボトルネックに注力できていなかったり、計測の手段の分からないメトリクスを放置してしまっていることもあって、まだまだだなぁ思う部分も多いです。強くなりたい。。。

本戦の時間のない中での緊張感で実力が出し切れないのは、普段の作業に最短時間でやろうという意識のなさが伺えるので、日々の活動から変えていきたいと思います。

ひたすらに椅子書いて笑った