Tinax blog

カテゴリー: isucon

  • ISUCON12 予選突破

    ISUCON12 の予選を通過しました！
    チーム名は快適PandAです。ISUCON11には快適PandApexという名前で参加していました。
    当日何をやったことを記録として残しておきます。

    メンバー

    • arakistic
    • das (https://blog.das82.com/post/isucon12q/)
    • tinax

    今年はDiscordで通話しながら作業しました。
    Discord Nitro に登録すれば高画質の画面共有ができるので便利です 🙂

    やったこと

    9:40

    全員で集合してyoutubeのライブ動画を見ていました。
    コードフリーズの時間など、全体のおおまかな計画を立てました。

    10:00

    AWSインスタンスの起動を待っている間、全員でマニュアルを読みました。

    10:20

    サーバーにプロファイリングツールなどをインストールしていました。欲しいツールを全部自動でインストールしてくれるシェルスクリプトを用意していたのでそれを使いました。

    僕はソースコードをgitで管理する準備をしていました。作業中、大量のsqliteデータベースファイルが見えて、mysqlに移行することになるのかなあと思っていました。

    10:30 (2500点)

    初回ベンチマークを回しました。

    10:37 (3930点)

    GoのアプリサーバーとDBサーバーを別マシンに分離しました。
    そのほうが、アプリサーバーとDBのどちらに負荷がかかっているか判断しやすいと考えたからです。

    分離作業は練習の段階で何度も行っていたので、作業自体は一瞬で終わりました。

    10:40 (3904点)

    DB側のcpu負荷が異常に大きかったので、arakistic氏にindexを貼ってもらい解決しました。
    点数がなぜか下がっていますが、たぶん slowlog や pprof などのプロファイラを有効にしたからだと思います(あまり覚えてないです)。

    その間das氏はソースコード上のN+1クエリを見つけてTODOコメントを書く作業をしていました。

    11:46 (3969点)

    Docker上に乗っていると再ビルドが遅く、slowlogなどを見るのも面倒だったので、Dockerを剥がしました。

    また、sqlite側のN+1クエリをarakistic氏に修正してもらいました。

    これからsqlite側の改善が主になると思ったので、私はsqliteのクエリログから重いクエリを順番にソートして表示する、sqlite版slowlogのようなツールを開発していました。

    12:01 (4392点)

    arakistic 氏にさらにN+1クエリを改善してもらい、点数が上がりました。

    12:20 (6898点)

    sqlite版slowlogツールが完成し、解析してみたところ INSERT が遅いことがわかったので、competitionScoreHandlerのfor文の中のINSERTを BULK INSERT に変えたところ、点数が上がりました。

    12:32 (7411点)

    BULK INSERT が使える場所がもう一箇所あったのでそちらもBULK INSERTに変更しました。また、playersAddHandler の中で retrievePlayer というSQLクエリを発行する関数を呼び出していましたが、必要ないことに気づいたので関数呼び出しを排除しました。

    12:39 (4727点)

    retrievePlayer という関数が様々な関数から頻繁に呼び出されており、この関数は呼び出しのたびに sqlite にクエリを発行するようになっていたため、das氏が結果をRedisにキャッシュするようにしました。
    しかし、点数が下がってしまいました。

    理由ははっきりとわかりませんでしたが、pprof で見たところ、redisライブラリの内部関数にかなりの時間が食われていたため、Redisとの通信や構造体のシリアライゼーションのオーバーヘッドが大きすぎたことが原因ではないかと思っています。

    そのため、Redis ではなく Go 内の配列にキャッシュデータを保存する計画が立ち上がりました。

    ~14:55

    • tinax: sqlite->mysql にデータ移行
    • das氏: Go内にretrievePlayerのキャッシュを配置
    • arakistic氏: competitionScoreHandlerのキャッシュ
      をやっていました。

    sqlite->mysqlのデータ移行は、1.dbというsqliteファイルだけ異常にサイズが大きく、データ移行が終わらず困っていました。
    最初から用意されてスクリプトではない、自作のスクリプトを作って挑戦したり、DBのパラメータをチューニングしたりしましたが、結局移行しきれませんでした。

    1.db だけ sqlite のまま使って他は mysql に移行するという、いかにもまずそうな方法も思いつきましたが、面倒だったので結局実行していません。

    ほかのチームメンバーはキャッシュを進めていましたが、ベンチがなかなか通らず、この時間はスコアの向上はありませんでした。

    去年もこの時間帯は沼っていた気がします。

    14:55 (9277点)

    arakistic氏が、終了した大会に関してはcompetitionScoreHandlerの結果が変化しないことを利用してキャッシュを行い、スコアが大幅に上がりました。

    この改善のおかげでチームメンバーの士気もかなり高まった気がします。

    sqlite->mysql の移行はこのあたりで諦めて、sqliteのまま改善を続けていく方向に切り替えました。

    TODO 続きを書く

  • ISUCON11 予選突破

    ISUCON 11 の予選に大学の友人と3人で出場してきました。ISUCONは今回が初参戦です。

    チーム紹介

    チーム名は 快適PandApex です。メンバーは

    • tinax (私)
    • das
    • arakistic

    です。全員、某大学工学部電気電子工学科の3回生です。チーム名は、das君と私が開発しているブラウザ拡張機能 “Comfortable PandA” と、3人でよくプレイしているゲーム “Apex Legends” が由来です。

    はっきりと役割分担を決めていたわけではありませんが、なんとなく

    • tinax -> アプリサーバーのコードの改善
    • das -> nginx や db の設定
    • arakistic -> dbの設定やログ解析など
      といった感じで作業を分担しました。 ちなみに、他のメンバーもISUCONのブログ書いているので、ぜひ読んでみてください！
    • das -> https://blog.das82.com/post/isucon11q/
    • arakistic -> coming soon

    当日やったこと

    ちゃんとメモを取っていたわけではないので、時刻はかなり適当です。

    9:30~10:00

    コンビニにお腹がすいたとき用のおにぎりを買いにいきました。

    10:00~10:20ぐらい

    • マニュアルのチェック
    • gitのセットアップ
    • goのpprofの設定
    • mysqlのslow queryの出力
    • nginxのログ設定
    • phpmyadminのセットアップ
    • プロンプトにgitのブランチ名を表示する設定
      などを行いました。 gitについて、具体的には webapp/goとwebapp/sqlを git 管理して、githubのprivateレポジトリにアップロードするようにしました。こうすれば、ローカル環境でコードを書きかえて push して サーバーで pull すればコードを更新できるので便利です。 また、ボトルネックを探すために、go で pprof プロファイラ と mysql の slow query を有効にしました。pt-query-digest というツールも導入しようかと話し合っていましたが、練習で一度も使ったことがなかったので今回は見送りました。 DBを楽に操作できるようにしたかったので phpMyAdmin も導入しました。このとき、AWSセキュリティグループをいじって81番ポートを開けました（これが後々大変なことになります）。 それと、bash の PS1 をいじって、現在の git のブランチ名をプロンプトに表示するようにしました。ブランチ変え忘れのヒューマンエラーが減るのでかなりおすすめです。 ログを有効化する前の初回スコアは 1799、ログを有効化した後のスコアは 1636 でした。

    10:20~

    slow query を見ると、時間がかかっているクエリの中に

    ORDER BY timestamp DESC

    のようなクエリがあり、timestamp に index が張られていなかったので index を張りました。しかし、DESC のソートでは index が効果を発揮できない（たぶん）ため、generated column を使って -timestamp の値が入ったコラム timestamp_neg を作成し、そのコラムにindexを張り、クエリは

    ORDER BY timestamp_neg ASC

    とASCのソートに書き換えました。
    かなり効果があったようで、スコアは 14184 になりました。

    11:15~

    GROUP BY を DISTINCT で置き換えたり、使えそうなところに LIMIT 1 を付けたり、N+1問題を解決したりしました。スコアは 22280 になりました。

    また、私はそれと並行して、forループ内のinsertをbulk insertに書き換える改善を進めていました。

    11:50

    bulk insert に書き換えた結果、スコアが 24430 になりました。

    11:45~

    for ループの中で INSERT しているコードがあり、slow query を見ても時間がかかっていたので、tinaxがbulk insertを利用するように改変しました。効果が出たようでスコアが2000ぐらい上がりました。

    13:00~

    contidition というコラムの中に文字列で3種類のデータをCSV形式で格納されているので、3つのコラムに分けて正規化しようとしました。初めは、3つのコラムに分割するように構造を改変した新しいテーブルを用意し、初期化時に元のテーブルから新しいテーブルに全データを移行するようにしようとしましたが、ベンチマークでfailが多発し、原因が特定できなかったため、PERSISTENTなgenerated columnを用いる方法に方針転換しました。しかし、逆にベンチのスコアが下がってしまい、改善する方法も思いつかなかったため、この部分の改善は諦めました。

    DBを大幅にいじっていたので他の改善もできず、この1時間はほとんど何も終わってしまいました。

    14:00~

    上述の通り改善に失敗し、スコアを上げるアイデアも尽きてきました。スコアが伸びなくなってきたらサーバーを分けようと話していたので、DBをServer 2に移動しました。予選前に練習した甲斐があって、移行はスムーズに進みました。スコアは 36067 まで上昇して、また元気が出てきました。

    15:00~

    Server 3がまだ余っていたため、nginxのロードバランサ機能を用いて、アプリケーションサーバーをServer 1とServer 3に分散することにしました。DBをServer 2,3に分散することもできたと思いますが、DBの分散にはGoコードの書き換えも必要になり複雑になりそうだったため、楽にできそうなアプリケーションサーバーの分散をすることになりました。nginxの設定などで少し躓きましたが、特に変なエラーが出ることもなく、スコアも大幅に伸びて 50499 になりました。練習ではアプリケーションサーバーの分散を行なったことがなかったので、これが成功したのはかなり嬉しかったです。

    15:30~

    アプリケーションサーバーをさらに高速化することになりました。グラフ関係のAPIについて何も改善していなかったため、そこに着手することにしました。Goのコードを読むも、コードの意図をはっきりと理解できず、どこに高速化の余地があるのかいまいちわかりませんでした。最終的に、私の案で、グラフの生成に利用するデータの取得の範囲を制限するという、最低限の処置だけ行うことになりました。また、arakistic君の提案で dropProbability を調整しましたが、dropProbabilityを下げると逆にスコアが下がり、解決できそうになかったので、結局dropProbabilityを初期値に戻すことになりました。

    17:00~

    17:00にコードフリーズすることにしていたので、これ以降はGoコードの改善はしていません。ギリギリまで高速化するために

    • goのechoフレームワークのログ出力をオフに
    • goのpprofコードを削除
    • mysqlのslow queryをオフに
    • phpmyadminとapacheをstop
    • apparmorをstop
      などをしました。特にgoのログの無効化とmysqlのslow queryの無効化はかなり有効だったようで、スコアが1万ぐらい上がって最大 63544 になりました。ログだけでこんなに違うんですね。 その後は systemd の設定などを調整して再起動試験の対策を行いました。 再起動試験も問題なくクリアできそうなことが確認できたあとは、みんなで改めてマニュアルやレギュレーションを読んでいたのですが、ここで「AWSのセキュリティグループの設定を変更してはいけない」というレギュレーションがあることに気づきます。phpMyAdminのインストールやサーバー分離を行なったときにセキュリティグループを変更していたため、大慌てで設定を元に戻しました。これに気づいていなかったら確実に再起動試験に引っかかっていたので、かなり危なかったです。マニュアルはちゃんと読まないとダメですね…

    18:45

    終了！最終的なスコアは 63281 になりました。

    まとめ&感想

    ISUCONは初めてで、まさか予選を通過できるとは思っていませんでした。

    予選中の行動を振り返ると、pprofやslow queryなどをあまり有効活用できていなかったような気がします。本戦までに、そのあたりを練習したいです。本戦まで4週間程度あるので、しっかり準備して、優勝を目指したいと思います。