Gマイナー志向

とくに意味はありません

ISUCON11本選でチーム ウー馬場ーイー2 として参加し、7位になりました

TL;DR

運営の皆様、参加者の皆様、本当にありがとうございました。ISUCONと嫁は私の生きがいです。 優勝までは届きませんでしたが、Failで終わったISUCON10本選から少し人権を取り戻した気がします。

スコアについて

本選時間中のベストスコアは80,473、再計測による最終スコアは83,756、7位でした。 本来は12位ぐらいので実力でしたがFailとなったチームがいたので運良く10位以内に入れたようです。

f:id:tmatsuu:20210920165946p:plain

今回、途中で急激なスコアの伸びたことが理由でTVer賞をいただいたのですが、スコアが伸びたのは開始から3時間44分後の1台構成から2台構成に切り替えたタイミングでした。最初しばらくは1台構成で進めて、煮詰まったら複数台構成としているので、予め複数台構成にするよりも大きく伸びやすいというのがあると思います。そのようなスコア評価があることは事前に知らなかったのでラッキーでしたね。わいわい。

体制

あいこん なまえ やくわり
f:id:tmatsuu:20210822141550j:plain:w100 matsuu バリバリ実装する前衛
f:id:tmatsuu:20190909215614p:plain:w100 netmarkjp 司令塔
f:id:tmatsuu:20190909215620j:plain:w100 ishikawa84g SELinux AppArmorとマニュアルやコードやDiscordを見るセキュリティ＆情報官

予選と同様に3人別々リモート、VDO.ninjaで画面共有、Discordで音声＋文字チャットです。

使用したツールなど

  • sshrc ssh接続先に手元の環境(dotfilesなど)を持っていく
  • tmux ターミナル分割として
  • vim 我らがエディタ
  • top リソース使用状況確認
  • iotop I/Oが多いプロセス特定 NEW!
  • dstat リソース使用状況確認
  • MySQLTuner MySQLパラメータ確認
  • kataribe アクセスログ解析
  • pt-query-digest MySQLスロークエリー解析

このチームはサーバにSSH接続してサーバ上で直接vimを叩いてプログラムを変更するポリシーなので、isuconユーザ上にお互いのvim環境やtmuxの設定を分離するためにsshrcを使っています。便利。

最終構成

今回は最後までDBの負荷が高い状態を改善できませんでした。トランザクション処理を考えるとDBレプリケーションで整合性をとりつつ性能を出すのは難しいと判断したのでDB1台、app2台としています。

サーバ 構成要素 備考
1台目 nginx + app(go)
2台目 app(go)
3台目 mysql

やったこと

10:16 31,928 初期スコア

一通り環境を揃えてperformance_schemaなども有効化してベンチマークを回した結果です。

10:35 36,321 interpolateParams=true

golangの王道、interpolateParams=trueを設定しています。

10:41 32,810 スロークエリーログ集計に変更

performance_schemaからの集計は見にくいとの結論から従来どおりpt-query-digestによるスロークエリーログ集計に切り替えました。スコアは落ちました。

11:24 30,448 トランザクション処理引き剥がし

スロークエリーログで上位にCOMMITがきてしまい内容がわからないため、外せるトランザクション処理は引き剥がしていきました。スコアは下がりましたがスロークエリーログの見通しは良くなったためそのまま進めます。

11:30 33,240 アプリログ外しとCOMMIT特定

11:24の対応でもある程度COMMITは排除できたのですが、残るCOMMITを判別するため、COMMITにコメントを入れることでスロークエリーログの出力を分ける対策をしました。こんな感じ。

- if err = tx.Commit(); err != nil {
+   if _, err := tx.Exec("COMMIT /* RegisterCourses */"); err != nil {

これは慧眼。自分たちを褒めてやりたい。スコアが少し上がったのはアプリログ外しのおかげです。

11:51 40,492 mysqlとnginxのパラメータチューニング

秘伝のタレの時間です。

/etc/mysql/mysql.conf.d/mysqld.cnf

innodb_log_file_size = 32M
innodb_doublewrite = 0
innodb_flush_log_at_trx_commit = 0
innodb_flush_log_at_timeout = 3

innodb_log_group_home_dir = /dev/shm

disable-log-bin

innodb_log_group_home_dir の変更はそのままだと正しく動作しないためAppArmorも調整してます。ワレワレハAppArmorト共存スル。

nginxはupstreamとHTTP/1.1の接続設定の他、nginxのerror.logに client request body is buffered to a temporary file が出力されていたのでassignmentsは proxy_request_buffering off を追加しています。

  location ~ ^/api/courses/.*/classes/.*/assignments$ {
    proxy_pass   http://app;
    proxy_set_header Connection "";
    proxy_http_version 1.1;
    proxy_request_buffering off;
  }

12:06 39,072 db接続数を増やしたら遅くなった

DBの接続数がデフォルトの10のままだったので100に増やしてみました。

-    db.SetMaxOpenConns(10)
+   db.SetMaxOpenConns(100)
+   db.SetMaxIdleConns(100)

が、これが元でスコアが下がりました。状況を確認するとFOR UPDATEによるロック待ちで滞留が増えてしまっているようでした。なるほどなるほど。ただ将来ロックを解消して接続数を増やす必要がでてくるだろうと判断して差し戻さずそのまま進めています。

12:52 41,368 cpをlnに変更する

今回の本選は提出された課題(pdfファイル)をzip形式で一括ダウンロードする機能があるのですが、pdfファイルをzipで圧縮する前にcpでファイル名をかえつつ集めている処理があったのですが、ここでインフラエンジニア力が発揮されcpをlnで置き換える奇策が適用されました。

   // ファイル名を指定の形式に変更
    for _, submission := range submissions {
        if err := exec.Command(
-          "cp",
+           "ln",
            AssignmentsDirectory+classID+"-"+submission.UserID+".pdf",
            tmpDir+submission.UserCode+"-"+submission.FileName,
        ).Run(); err != nil {

lnコマンドは-sをつければシンボリックリンクを作成しますが、-sをつけなければハードリンクになるため副作用が発生しにくいうえに高速にリンクを作成できるため今回の用途にピッタリでした。わいわい。これがインフラエンジニアだ。

13:35 42,491 GetGradesのN+1を一部解消

/api/users/me/grades でたびたびタイムアウトが発生しており、IFNULLが使われれているクエリーがスロークエリーログのトップに来ていたのですが、かんたんな改善が思いつかず、取り急ぎ同処理内の修正できそうなN+1を解消しています。スコアの伸びはわずかです。

13:44 68,795 2台構成に変更

ここまでで一番のボトルネック（と思っていた）DBに対して打つ手がなくなってきたので、3台目をDBサーバとして利用するよう構成変更を行いました。このときのスコアの伸びがTVer賞になっています。

16:07 75163 GPAの統計値を予め計算したスコアテーブルを作成

DBサーバを分離してもDBのCPU負荷がボトルネックになっていたため、採点をするたびに total_score として積算していくためのカラムを追加したのですがdeadlockが多発、ええいテーブルも分離して積算だとテーブルを分けてもdeadlock、最終的には一応スコアが出るようになったのですが、何がなんだかさっぱりわからずやたら時間を食ってしまいました。厳しい。

16:22 77,029 課題提出周りを改善

zipダウンロードでnginxにてbufferingが発生していることを確認したため proxy_buffering off を追加しています。

  location ~ ^/api/courses/.*/classes/.*/assignments/export$ {
    proxy_pass   http://app;
    proxy_set_header Connection "";
    proxy_http_version 1.1;
    proxy_buffering off;
  }

また、合わせてアップロードされた課題は io.ReadAll() の代わりに io.Copy() でメモリに読ませず直接出力するようにしています。

16:45 73,395 DB接続数上限を200に増やすもスコア下がる

DBの接続数が上限まで使い切っていたので上限を増やしてみたものの、スコアはむしろ下がってしまいました。LOCK待ちが増えたからですね。

17:00 78,336 appを2台構成に

引き続きDBのCPU負荷がボトルネックになっている状況（だと思っていた）のですがDBを2台構成にするのは難しい（と思い込んでいた）ので2台目にもappを配置して最終構成としました。結果、スコアは少しだけ伸びました。

17:35 80,473 ログ出力を無効にしてスコアアップ

nginxのアクセスログとmysqlのスロークエリーログの出力を停止することで若干のスコアアップとなりました。

18:00まで 偏差値がマイナスになっていることに気づいて慌てふためく

ふとサイトにログインして動作確認していたところ、S99999ユーザで偏差値がマイナス値になっていることに気づいて焦りました。 f:id:tmatsuu:20210920201312p:plain 学内GPA偏差値 -331.8 とは

偏差値でマイナスとかありえへんのでどこかでエンバグしてしまったのだと思い、関連しそうな場所をrevertしてみたりしたものの改善せず。ええい仕方ない最終的にスコアのよかった実装にしてそのままフィニッシュとなりました。

この偏差値は最初からバグってたのか、エンバグしたのかはまだわかってません。追試で調査を行おうと思います。おわり。

おまけ1 やったこと公開しました。

予選本選でやったことはgithubで公開してます。

github.com github.com

おまけ2 OODAループについて

本選直前のgihyo.jpのインタビュー記事でも少しだけ回答したのですが、我々の戦略はOODAループを基本としています。

OODAループ - Wikipediaより：

OODAループは、観察（Observe）- 情勢への適応（Orient）- 意思決定（Decide）- 行動（Act）- ループ（Implicit Guidance & Control, Feedforward / Feedback Loop）によって、健全な意思決定を実現するというものであり、理論の名称は、これらの頭文字から命名されている。

これはgihyo.jpのインタビュー記事の設問に

1.今回の予選課題が発表されて，最初に感じたこと，また，具体的に取り組むに当たってどのような方針でスタートしましたか。

とあって、事前に環境整備の準備はするものの、予選課題の発表後に大方針のようなもの決めてないしPDCAじゃないよなぁ、とググってたら見つけた理論で、我らが今までISUCONでやっていたことはOODAループと同じだった、というだけです。

OODAループに関する書籍やYouTube解説動画などもあるのですが、ビジネス寄りでちょっと胡散臭い雰囲気があるのが残念ですね。エンジニアの我々は理論だけ活用していきましょう。

OODAループに関して1冊だけ書籍購入しました。まだ全部読めてません。

OODA　危機管理と効率・達成を叶えるマネジメント

OODA　危機管理と効率・達成を叶えるマネジメント

Amazon