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冊だけ書籍購入しました。まだ全部読めてません。

ISUCON11予選でチーム ウー馬場ーイー2 として参加し、本選進出を決めました

TL;DR

ISUCON11予選にチーム ウー馬場ーイー2 として出場しました。 上位25チームに残り本選進出が決まりました。やったね。 最終スコアは389509で8位、予選中のベストスコアは394682でした。本選もがんばるぞ!

毎年素晴らしいコンテストを開催してくださる運営様には感謝しかありません。本当にありがとうございます!!1

体制

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

3人がそれぞれ別々の場所にいたのでリモート接続しながら挑みました。 画面共有は VDO.ninjaRemote Screenshare into OBS で生成されたURLを直接相互参照しました。遅延なく解像度も高くて最高。 音声と文字チャットはDiscordを使ってます。ISUCON公式のコミュニケーションツールもDiscordなのでツールを統一できて便利。

使用したツールなど

方針

  • サーバ上で直接vimソースコードを変更するスタイル
    • 手元での再現環境構築や外部からのデプロイは行わない
    • sshrc で環境がかぶらないようにしてメンバーごとにvim/ssh環境を分離
  • 実装言語はGoを選択
  • 負荷テスト中は topdstat -tlamp を目視確認
  • 負荷テスト後にアクセス解析
    • nginxのログをkataribeで解析して /result/kataribe.log に出力
    • mysqltuner.plを実行して /result/mysqltuner.log に出力
    • MySQLはスロークエリーを出力せずパフォーマンススキーマを有効にしてslowquery2tsvでTSV化して /result/slowquery.tsv に出力
      • ただslowquery2tsvはMariaDBへの対応ができておらず
      • 急遽使い慣れたpt-query-digestに差し替えてスロークエリーを /result/slowquery.log に出力
  • /git init
    • /etc/home と解析結果を含む /result をまるごとコミット(必要に応じて.gitignoreで除外)
    • git add / して git commit
    • GitHubのプライベートリポジトリに git push

今回スロークエリー解析用にslowquery2tsvを作成したのですが、その理由は以下のとおりです。

  • GitHubCSV/TSVビューアが優秀なのでこれを使いたかった
  • pt-query-digestは大量のスロークエリーが出力された場合に解析が遅いのでPerformanceSchemaを使いたい
  • TSVであればless/vimでもおおよそ桁揃えできるので見やすい

slowquery2tsvは次回までに修正しておきたいと思います。

gitは履歴管理と差し戻しが必要になった際の確認用です。パッケージインストールでの /etc 配下更新やアクセス解析結果を含むため git revert の実行は想定してません。割り切り。 /home/etc を含むことで何をやったかが後から追えるのでブログでまとめやすくなります。

最終構成

当初は1台目のみを使い、ある程度負荷傾向が定まってきてから複数サーバを使うように構成変更しました。 複数サーバに分けることにしたタイミングではDBよりもappのCPU負荷が高かったので、appを2台配置としています。

サーバ 構成要素 備考
1台目 nginx + varnish + app(go) varnishを追加インストール
2台目 MariaDB 初期実装のままバージョン変更なし
3台目 app(go)

nginxの設定はこんな感じです。

  • /api/trend はvarnish経由で1台目のappへ
  • /api/isu/*/graph/api/condition/* はvarnishを経由せず1台目と3台目のappへ
  • 上記以外の /api//initialize はvarnishを経由せず1台目のappへ
  • それ以外はすべてnginxで応答

ベンチマーク結果

ベストスコア

f:id:tmatsuu:20210822133617p:plain

あくまでベストスコアであって実際には上下してます。

全スコア

f:id:tmatsuu:20210822134154p:plain

回数多いかな。どうでしょう。

やったこと

「時間 スコア 概要」でまとめていきます。

10:23 2974 初期ベンチ

公式マニュアルに従いインスタンス作成完了が 10:05、SSHでログインが 10:10 でした。 そこから必要なパッケージのインストールや git init などが完了して初回ベンチマークが 10:23 でした。

10:35 1829 パフォーマンススキーマ有効化

集計のためにMariaDBのPerformanceSchemaを有効にして再計測したらスコアが下がりました。まぁそんなもん。

10:42 1683 スロークエリーログ出力に切り替え

MariaDBのPerformanceSchemaは出力結果がMySQL8と異なり手元の集計ツールが正しく動作しなかったので、方針変更してスロークエリーログ出力とpt-query-digestに切り替えました。スコアはさらに下がって1683。まぁそんなもん。

10:51 16664 DB周りチューニング

pt-query-digestでスロークエリーが顕著に出ていたので、この内容を見ながらDB周りの調整を行っています。

# Rank Query ID                            Response time  Calls R/Call V/M
# ==== =================================== ============== ===== ====== ===
#    1 0x8155B89FFD74A9D523D19AC409FD97AF  330.2609 56.9%  2447 0.1350  0.06 SELECT isu_condition
#    2 0x931A992E852C61FC6D46141A39DEF4FE  178.2064 30.7%  3393 0.0525  0.06 SELECT isu_condition
#    3 0xFFFCA4D67EA0A788813031B8BBC3B329   31.0515  5.3%  7506 0.0041  0.01 COMMIT
#    4 0xDA556F9115773A1A99AA0165670CE848   16.7825  2.9% 87951 0.0002  0.00 ADMIN PREPARE
#    5 0xB8B32624C3268C0925657C305C0ED778   14.2339  2.5% 69887 0.0002  0.00 INSERT isu_condition
#    6 0x9C6C682008AE0D08F3E2A0049B030C70    4.3813  0.8%   141 0.0311  0.03 SELECT isu_condition
#    7 0x5F580A12ADA1633C9634298BE5BD9422    1.7119  0.3%    61 0.0281  0.05 SELECT isu_condition
#    8 0x1E561CE87F050ED58A7E1A7FBB6C2285    1.0212  0.2%  7023 0.0001  0.00 SELECT isu
#    9 0x07890000813C4CC7111FD2D3F3B3B4EB    0.5763  0.1% 87951 0.0000  0.00 ADMIN CLOSE STMT
#   10 0x8C2BC651CBBBF3DB41D1CAD61AA0BD68    0.5094  0.1%  1200 0.0004  0.00 SELECT isu
  • goのdb接続パラメータに interpolateParams を追加
  • インデックス追加
    • テーブル isuINDEX (jia_isu_uuid) を追加
    • テーブル isu_conditionINDEX (jia_isu_uuid, created_at) を追加
      • しかしこの created_attimestamp の間違いだったと後で気づく

これによってpt-query-digestの結果は、Response timeが大きく改善しました。

# Rank Query ID                            Response time  Calls R/Call V/M
# ==== =================================== ============== ===== ====== ===
#    1 0x931A992E852C61FC6D46141A39DEF4FE  116.4533 39.7% 13452 0.0087  0.02 SELECT isu_condition
#    2 0x9C6C682008AE0D08F3E2A0049B030C70   50.8375 17.3%  2649 0.0192  0.02 SELECT isu_condition
#    3 0xFFFCA4D67EA0A788813031B8BBC3B329   42.2897 14.4%  9056 0.0047  0.01 COMMIT
#    4 0x8155B89FFD74A9D523D19AC409FD97AF   38.4616 13.1%  4336 0.0089  0.02 SELECT isu_condition
#    5 0xB8B32624C3268C0925657C305C0ED778   25.6250  8.7% 75058 0.0003  0.01 INSERT isu_condition
#    6 0x5F580A12ADA1633C9634298BE5BD9422   12.4012  4.2%   731 0.0170  0.02 SELECT isu_condition
#    7 0x677D4DCDF729CC334DE038E9477B32B3    1.8281  0.6%   232 0.0079  0.01 SELECT isu_condition
#    8 0x8C2BC651CBBBF3DB41D1CAD61AA0BD68    1.0356  0.4%  4400 0.0002  0.01 SELECT isu
#    9 0x1E561CE87F050ED58A7E1A7FBB6C2285    0.9872  0.3%  7556 0.0001  0.01 SELECT isu
#   10 0xADCA4F127A769A45A2D1B74705103105    0.9068  0.3% 11201 0.0001  0.00 SELECT user

ちなみに各テーブルは /initialize が呼ばれるたびに毎回 DROP TABLE が実行されるので、インデックスは ~/webapp/sql/* もしくは /initialize の中で追加する必要がありました。

11:03 18138 nginxチューニング

続いてnginxにチューニングに入ります。

  • nginxとapp間で持続的接続が有効化
  • /api/と/initialize以外はnginxから直接返す

プログラムをみると /isu/*/register などはindex.htmlを返していたので、 try_files を使って存在しないファイルはすべて /index.html を返すようにしているのが工夫ポイントです。

upstream app {
  server 127.0.0.1:3000;
  keepalive 16;
  keepalive_requests 10000000;
}

server {
    listen 443 ssl http2;

    ssl_certificate /etc/nginx/certificates/tls-cert.pem;
    ssl_certificate_key /etc/nginx/certificates/tls-key.pem;

    location /api/ {
        proxy_set_header Host $http_host;
        proxy_set_header Connection "";
        proxy_http_version 1.1;
        proxy_pass http://app;
    }

    location /initialize {
        proxy_set_header Host $http_host;
        proxy_set_header Connection "";
        proxy_http_version 1.1;
        proxy_pass http://app;
    }

    root /home/isucon/webapp/public;
    index index.html;
    location / {
      try_files $uri /index.html;
      expires 86400s;
    }
}

11:09 17774 nginxにclient_body_buffer_size追加

/var/log/nginx/error.log を確認すると POST /api/isu で一時ファイルが生成されていることを確認したため、アクセスログ$request_length を出力してサイズを確認しその最大値を少し上回る値を client_body_buffer_size として設定しました。

    location ~ ^/api/isu$ {
        client_body_buffer_size 128k;
        proxy_set_header Host $http_host;
        proxy_set_header Connection "";
        proxy_http_version 1.1;
        proxy_pass http://app;
    }

でも今思えば proxy_request_buffering でやるべきだったかもですね。このあたりは後日追試しようと思います。

11:23 17618 bulk insertに変更

kataribeの出力結果を見るとトップは POST /api/condition/* でした。ちなみにkataribeはほとんど Sort By Total しか見てません。

Top 40 Sort By Total
Count    Total    Mean  Stddev    Min  P50.0  P90.0  P95.0  P99.0    Max    2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
75487  433.603  0.0057  0.0139  0.000  0.001  0.016  0.035  0.073  0.107  75213    0  274    0          42          0          0         14  POST /api/condition/<uuid> HTTP/2.0

そこで該当の関数を以下のように変更しました

  • INSERT前のSELECTが0件以上あるかの確認だったので SELECT 1 FROM ... LIMIT 1 に変更
  • INSERTを数珠つなぎにしてbulk insertに変更

結果スコアは下がったものの、Countが増えてMeanは下がってるので負荷軽減に効果があったと判断しokとしています。

Top 40 Sort By Total
Count    Total    Mean  Stddev    Min  P50.0  P90.0  P95.0  P99.0    Max    2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
75731  339.605  0.0045  0.0106  0.000  0.001  0.012  0.023  0.055  0.216  75508    0  215    8           0          0          0          0  POST /api/condition/<uuid> HTTP/2.0

11:44 20127 /api/trendの全件取得を1件に

引き続きMariaDBのCPU負荷が高いためpt-query-digestのトップに来ているクエリーを確認したところ /api/trend の中で実行しているクエリーであることを確認しました。

SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = ? ORDER BY timestamp DESC

このクエリーはLIMITが使われていないものの、その後の処理で最初の1件しか使っていないこと、また一部のカラムしか利用していないので以下ようにクエリーを変更しました

SELECT `condition`, timestamp FROM `isu_condition` WHERE `jia_isu_uuid` = ? ORDER BY timestamp DESC LIMIT 1

conditionが予約語らしく バッククォートでくくる必要があったのが罠でしたね。 ちなみにN+1は解消してません。1件取得するだけの変更にとどめています。

11:49 37019 インデックスの間違いに気づく

10:51に追加したインデックスの間違いに気づき isu_conditionINDEX (jia_isu_uuid, created_at)INDEX (jia_isu_uuid, timestamp) に変更しました。

変更前のpt-query-digest

# Rank Query ID                            Response time  Calls R/Call V/M
# ==== =================================== ============== ===== ====== ===
#    1 0x2C2674DBBE2489BF6C83BB0B21790D62  140.3237 32.3% 16026 0.0088  0.02 SELECT isu_condition
#    2 0x9C6C682008AE0D08F3E2A0049B030C70  107.6753 24.8%  3357 0.0321  0.02 SELECT isu_condition
#    3 0x8155B89FFD74A9D523D19AC409FD97AF   97.9899 22.6%  7478 0.0131  0.02 SELECT isu_condition
#    4 0xFFFCA4D67EA0A788813031B8BBC3B329   36.3303  8.4%  9885 0.0037  0.00 COMMIT
#    5 0x5F580A12ADA1633C9634298BE5BD9422   27.1060  6.2%   974 0.0278  0.02 SELECT isu_condition
#    6 0xB8B32624C3268C0925657C305C0ED778   12.5142  2.9%  7610 0.0016  0.01 INSERT isu_condition
#    7 0x677D4DCDF729CC334DE038E9477B32B3    4.6057  1.1%   381 0.0121  0.02 SELECT isu_condition
#    8 0xADCA4F127A769A45A2D1B74705103105    1.8215  0.4% 17482 0.0001  0.00 SELECT user
#    9 0x8C2BC651CBBBF3DB41D1CAD61AA0BD68    1.4361  0.3%  5154 0.0003  0.00 SELECT isu
#   10 0xB5F4855605637317357023AD70B91455    1.3706  0.3%  8824 0.0002  0.00 SELECT isu

変更後のpt-query-digest

# Rank Query ID                            Response time Calls R/Call V/M 
# ==== =================================== ============= ===== ====== ====
#    1 0x9C6C682008AE0D08F3E2A0049B030C70  42.6501 29.9%  5344 0.0080  0.01 SELECT isu_condition
#    2 0xFFFCA4D67EA0A788813031B8BBC3B329  35.1129 24.6% 13416 0.0026  0.01 COMMIT
#    3 0x2C2674DBBE2489BF6C83BB0B21790D62  25.9887 18.2% 45806 0.0006  0.00 SELECT isu_condition
#    4 0x5F580A12ADA1633C9634298BE5BD9422  13.6792  9.6%  2282 0.0060  0.01 SELECT isu_condition
#    5 0x8155B89FFD74A9D523D19AC409FD97AF   8.8025  6.2% 22660 0.0004  0.00 SELECT isu_condition
#    6 0xB8B32624C3268C0925657C305C0ED778   6.4959  4.6%  7621 0.0009  0.00 INSERT isu_condition
#    7 0xADCA4F127A769A45A2D1B74705103105   2.3164  1.6% 44119 0.0001  0.00 SELECT user
#    8 0xB5F4855605637317357023AD70B91455   1.8257  1.3% 26210 0.0001  0.00 SELECT isu
#    9 0x8C2BC651CBBBF3DB41D1CAD61AA0BD68   1.6544  1.2% 14503 0.0001  0.00 SELECT isu
#   10 0x88716D544EA925A1EE9114761B982E3E   0.7488  0.5%  7627 0.0001  0.00 SELECT isu

Response timeが大きく改善しましたね。

12:09 44034 Varnishで/api/trendをキャッシュ

マニュアルと実際の動作をにらめっこしたところ、 /api/trend はログイン状況に関わらずコンテンツの出し分けがなくログインチェックもないのでキャッシュで返せることに気づきました。 そこでVarnishをインストールしてキャッシュ応答をするように変更しています。CookieリクエストヘッダーがついているとVarnishはキャッシュを返さないので、Cookieリクエストヘッダーは vcl_recv で削除しています。

nginx

upstream varnish {
  server 127.0.0.1:6081;
  keepalive 16;
  keepalive_requests 10000000;
}

server {

    # ...

    location ~ ^/api/trend$ {
        proxy_set_header Host $http_host;
        proxy_set_header Connection "";
        proxy_http_version 1.1;
        proxy_pass http://varnish;
    }

varnish

backend default {
    .host = "127.0.0.1";
    .port = "3000";
}

sub vcl_recv {
    if (req.url ~ "^/api/trend") {
        unset req.http.cookie;
    }
}

sub vcl_backend_response {
    set beresp.ttl = 0.8s;
    set beresp.grace = 0.2s;
}

変更前のkataribe

Count    Total    Mean  Stddev    Min  P50.0  P90.0  P95.0  P99.0    Max    2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
  637  257.361  0.4040  0.1896  0.003  0.415  0.638  0.713  0.870  0.978    573    0    3   61     2575394          0       4043       4535  GET /api/trend HTTP/2.0

変更後のkataribe

Count    Total    Mean  Stddev    Min  P50.0  P90.0  P95.0  P99.0    Max    2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
  864   15.936  0.0184  0.0651  0.000  0.000  0.023  0.158  0.359  0.515    798    0    0   66     3559454          0       4119       4537  GET /api/trend HTTP/2.0

Meanが大きく下がりました。わいわい。

13:39 79819 たくさん修正

だんだん雑になってきました。昼飯を食べながらざっくりやったほうがいいことを調べて、まとめて適用します。

  • isu にインデックス INDEX (jia_user_id, jia_isu_uuid) を追加
  • アプリからのDB接続数を引き上げ db.SetMaxOpenConns(150) db.SetMaxIdleConns(150)
  • /api/trendのレスポンスをVarnishでgzip圧縮
  • POST /api/condition/* は最後のconditionだけ登録だけでいいのでは?と判断してで最後の1件だけ登録、ついでにトランザクション処理を解除
  • dropProbabilityを0.9から0.6に変更
  • innodb周りのチューニングを追加

14:25 74425 iconを静的ファイルに出力してアプリから返す

GET /api/isu/*/icon がkataribeで2位となっているのでDBに格納せずnginxから返すようにしました。このエンドポイントはログイン必須であるため単純に画像を返すとエラーになるのではと判断し、ファイルに書き出したもののnginxからは応答せずアプリから応答しています。 スコアは下がったもののDBの負荷とトラフィック量は減っており、後々効いてくるだろうと判断して差し戻しは行ってません。

14:44 146710 DBを2台目サーバに移す

スコアに直結するような改修がおもいつかなくなってきたこと、またアプリとdbでCPU負荷を食い合う状況になってきたので、2台目サーバのMariaDBを利用するようにしました。それまではずっと1台目サーバだけで進めていました。

15:22 208386 iconをnginxから返すためX-Accel-Redirectレスポンスヘッダーを追加

DBを分離したあともアプリの負荷が高いため、アプリの処理を減らそうと X-Accel-Redirect レスポンスヘッダーを返すことでnginxから静的ファイルを返すように変更しました。またiconは一度登録すると更新されることはないためキャッシュするよう設定しています。

画像の出力は /home/isucon/tmp に生成していたので、そこをinternalで取得できるようにして X-Accel-Redirect でリダイレクトさせています。ついでにexpiresも追加しています。

    location /icon {
        internal;
        alias /home/isucon/tmp; 
        expires 86400s;
    }

    location ~ ^/api/isu/.*/icon$ {
        proxy_set_header Host $http_host;
        proxy_set_header Connection "";
        proxy_http_version 1.1;
        proxy_pass http://app
        expires 86400s;
    }

15:31 188370 静的ファイルをgzip圧縮で応答するもスコアが下がる

~/webapp/public/ 配下のファイルについてそういえばgzip圧縮応答していなかったと思い出し、gzip圧縮してnginxの gzip_static で応答したのですがなぜかスコアが下がってしまいました。何度かon/offを切り替えながらベンチを回したもののoffが良さそうなので最終的にはoffとしました。

この原因は何だったんでしょうね。gzip展開でベンチマーカーのCPU負荷が高まるからか?とか思ったんですが真相は不明です。

16:27 66170 graphの改善を試みるもスコアだだ下がる

マニュアルを読むとグラフの確認による加点があるものの、自分たちの環境はすべてWorstになっていることからこれを改善すればスコアが大きく伸びるのではと思ったのですが、改善しきれませんでした。ここは今後の課題となります。

16:49 269411 3台目サーバをapp用に利用する

アプリのCPU負荷が高い状況が続いていたため、ここで3台目サーバをapp用に利用しています。ほぼほぼ上記最終構成と同じ構成になりました。 これによりスコアが大きく改善しました。

17:00 379417 dropProbabilityを差し戻すとスコアが上がる

打つ手が思いつかない中、13:39に0.6に下げていたdropProbabilityを0.9に戻してみたら大きく改善しました。なんでやねん。よくわかりません。

18:18 394682 最終調整

最終調整を行っていました。

  • nginxの worker_connections を増やす
  • nginxの upstream において keepalive を増やす
  • MariaDBquery_cache を無効にしてみたもののスコアが下がったので差し戻す
  • MariaDBのスロークエリーログ出力をやめる
  • nginxのアクセスログ出力をやめる
  • 再起動試験を実施

最終調整の中で記録したベストスコアが 394682 でした。

その後も何度かベンチガチャを回して予選中の最終スコアは18:39に記録した388657です。

HighLoad Cup 2021(Gold Rush) write-up

ロシア企業Mail.ruが主催するパフォーマンスチューニングコンテストHighLoad Cup 20201に参加したのでその報告。

Webサイト

https://cups.mail.ru/en/contests/goldrush

結果

Battle-Round 47位(63位以上がFinal進出)、Final-Round 37位でした。 Battle-RoundとFinal-Roundは内容は同じまま、Finalはチート対策でSEEDがランダムになっただけなので実質課題は1つです。 可もなく不可もなく、微妙なスコアですね。はい。

課題

簡単にまとめるとこんな感じです。

時間内に宝物を「探索」して「掘削」して「換金」するHTTPクライアントを実装せよ

ざっくりとした仕様は以下の通り。

  • 縦横3500x3500、深さ10の領域が与えられる
  • POST /exploreで指定した縦横範囲の探索ができる
    • 探索するとその範囲に含まれる宝物の数がわかる
    • 探索は範囲指定が可能(0,0の座標から3x4の範囲を探索など)
    • 探索ではどの深さに宝物があるかわからない
  • POST /digで指定した場所(x, y, depth)を掘削ができる
    • 1度に掘削できる深さは1のみ
    • 深さ2を掘削するためには先に深さ1を掘削しないといけない
    • 横に掘ることはできない
    • 掘削にはライセンスが必要
  • POST /licenseでライセンス取得ができる
    • ライセンスは無料と有料がある
    • 1ライセンスで掘削できる回数は無料と有料で異なる
    • 1度に保持できるライセンスは10まで
  • POST /cashで掘削された宝物をコインに換金できる
    • コインの数=最終スコア
    • 有料ライセンスはコインを消費する=最終スコアも減る

詳細は以下をご参照ください。

やったこと

以下、ネタバレ含みます。

  • 公式のpython実装を元にgolang実装で書き換え
  • ライセンスを10個取得して並行処理
  • 「探索」「掘削」「ライセンス取得」「換金」をそれぞれgoroutineにしてchannelで受け渡し
  • channelのcapを抑えめにすることで無駄なHTTPリクエストが発生しないように調整
    • それぞれの処理を複数workerを構成に
  • 有料ライセンスを使用してレイテンシ改善
    • ただし有料はコインを消費=スコアが下がるのでいい塩梅を模索
    • コインが入手できるまでは無料ライセンス、入手できるようになったら1コイン消費で有料ライセンス
  • 1つのライセンスで複数回掘削できることから、ライセンスを掘削回数分コピーして一斉に同時掘削
    • 掘削完了を検知するためにsync.WaitGroupを活用しまくる
  • 4x4や8x8など広めの範囲から枝刈り全探索で効率化
    • 試行錯誤の結果、1x10、1x15、2x7あたりが何故か効率が良かったので採用
  • GOGC=off
  • ライセンス取得のレイテンシがボトルネックになるのでPOST /digのHTTPリクエストを投げた時点でライセンス取得を行う
  • net/http/httptrace.ClientTrace.WroteRequest を使って最速再取得を試みる
    • しかしWroteReuqestではエラー多発。GotFirstResponseByteであればエラーはなくなるものの改善効果なし
  • encoding/jsongithub.com/goccy/go-json に置き換え
    • go build 時のメモリ消費がネックに
    • 簡易なJSONは自力の文字列処理でencode/decodeすることでさらに軽量化
  • net/httpgithub.com/valyala/fasthttp に置き換え
    • CPU負荷は下がったがCPUがボトルネックになってなかったのであまり効果はなかった
  • HTTP Keep-Aliveが無効になっているので事前に net.Dial を行うことで自前コネクションプール
    • 思いついたときは勝利を確信したもののあまり効果はなかった

スコア上位がやっていた(らしい)こと

公式Telegramでの事後チャットを眺めていたのですが、こんな感じみたいです。

  • Battle-roundは宝物の配置が固定なため配置をハードコードして探索処理をスキップ
  • Final-roundはハードコード対策が行われたものの、サーバサイドがgolang実装なのを考慮して疑似乱数生成(PRNG)の使われ方を推測、宝物の配置パターンからSEEDを特定することで探索処理をスキップ

いやーこれは度肝抜かれましたね。でも主催側もここまですることを想定していたようです。まじかよスゲーなロシア。

ソースコード

サーバサイドのソースコードは全日程終了後公開されたので手元環境で再現可能です。わいわい。 https://github.com/All-Cups/highloadcup/tree/main/goldrush/server

まとめ

今回はHTTPクライアントを実装することもあって、これまでISUCONなどで培ってきたWebサービスに関する知識が生かせず苦労したのですが、その分HTTPクライアントに関する知見を多く得られたこと、またgoroutine、channel、syncパッケージを使った並行処理の良い練習になりました。今後どこかで活かせるといいですね。

ロシア版ISUCONであるところのHighLoad Cup 2021(Gold Rush)のベータテストがはじまりました

ついにきたぞ!

ロシア版ISUCONともいうべき高負荷環境をチューニングするプログラミングコンテストHighLoad Cup 2021(Gold rush)がついに始まりました。2017年、2018年と2回開催されて以降更新がなかったのですが、All Cupsの一部として装いも新たについに降臨です。いやぁ待った甲斐があったね。

cups.mail.ru

開催日程

現時点での開催日程は以下の通りです。

2021/02/19 - 2021/03/05 Beta-testing

2021/03/05 - 2021/03/26 Battle-round (予選)

2021/03/26 - 2021/04/02 Final round (本選)

Beta-testingの期間もテスト走行は可能ですが、ランキングとしては記録されません。Battle-roundが本番となる見込みです。

Beta-testingの間は仕様が変更になる可能性がありますが、おおよそプログラムの実装を進めておき、Battle-roundの期間で本格的に実装すればokでしょう。期間の間ずっと張り付いている必要はなく、その期間内の任意のタイミングで実装すればokです。

Battle-roundで上位20位になるとFinal roundへ進めるようです。

賞金

賞金は一応用意されています。

1位 200,000ルーブル

2位 150,000ルーブル

3位 125,000ルーブル

4~6位 35,000ルーブル

日本在住者が賞金を貰えるのかはちゃんと確認してません。

はじめかた

ざっくりとはじめかたを紹介します。

アカウント登録

まずはアカウント登録をしましょう。アカウント登録は画面右上のAUTHORIZATIONからRegister Nowを選択すれば可能です。

概要

問題の概要は以下のページにあります。ロシア語だけでなく英語も用意されてますので安心です。

cups.mail.ru

サンプル実装

現時点でPythonによるサンプル実装が用意されています。

github.com

また、swagger.yamlがあるのでこれを参考に実装するのがいいでしょう。

Dockerコンテナイメージ上で稼働できるのであれば実装言語何でもokです。

実装の提出 

実装の提出はDockerコンテナを作成して主催者が用意するDockerレジストリにpushして提出することになります。そのため手元にDocker実行環境を用意してください。提出方法の詳細はアカウントでログイン後の MY WORKSPACEをご確認ください。

まずは上記サンプル実装を提出してみてテスト走行してみるのがいいでしょう。

 質問など

ちょっとした質問であればTelegramで質問するのがいいでしょう。ロシア語が飛び交ってますが、英語で質問したら丁寧に教えてくれました。

t.me

もしくは私が回答できることならTwitterでいつでもどうぞ。

 

ISUCON10本選に出場し17:00時点ではベストスコア1位だったもののfailフィニッシュになりました

TL;DR

ISUCON10本選に出場し、17:00時点でベストスコア1位につけるも最終的にはfailフィニッシュとなった(と思われる)matsuuです、こんにちは。

体制(予選から再掲)

チーム名 ウー馬場ーイーツ

あいこん なまえ やくわり
f:id:tmatsuu:20190909215748j:plain:w100 matsuu バリバリ実装する前衛
f:id:tmatsuu:20190909215614p:plain:w100 netmarkjp 司令塔
f:id:tmatsuu:20190909215620j:plain:w100 ishikawa84g SELinuxAppArmorとレギュレーションやコードやDiscordを見るセキュリティ&情報官

本選も同じくそれぞれの場所からリモート体制です。

方針

基本的に予選を踏襲してsshrc+tmux+vim(or nvim)です。 gitについてはファイルシステムのルートで git init を実行し、.gitignoreで /home/etc を記録するようにしました。このあたりはまだ改善余地があったので来年に向けて改善を続けます。

解析ツール

予選と同じのため省略

最終構成

最終構成は以下の通りです。

サーバ スペック 構成要素 備考
isu1 1コア1GB envoy+varnish varnishを追加インストール
isu2 2コア2GB mysql バージョン変更なし
isu3 4コア1GB xsuportal/benchmark_server golang

当初は1台目のみを使い、ある程度負荷傾向が定まってきてから最適なスペックに配分していきました。

ベンチマーク結果

ベストスコア遷移
f:id:tmatsuu:20201004154854p:plain
あくまでベストスコアであって実際には上下してます。

全スコア一覧
f:id:tmatsuu:20201004194846p:plain

初動

開始後、自分はkataribeやpt-query-digestなどを設定できるよう調整。言語もrubyからgolangに変更しています。 envoyを自分で触るのはほぼ初めてだったものの、envoyの公式ドキュメントを確認したところデフォルトのログ形式でも %DURATION% として応答時間が記録されることを確認。そのままkataribeに食わせることに。kataribeの設定はこんな感じ。

# kataribe.toml
scale = -3
effective_digit = 3
log_format = '^\[([^\]]+)\] "((?:\\"|[^"])*)" (\d+) (\d+|-) (\d+) (\d+) (\d+) (\d+) .*$'
request_index = 2
status_index = 3
bytes_index = 6
duration_index = 7

今回MySQLのバージョンが最初から8.0.21だったので、予選から本選の間に調べたREDOログの無効化を速攻で実施してます。

ALTER INSTANCE DISABLE INNODB REDO_LOG;

atsuizo.hatenadiary.jp

本番環境で実行しちゃダメだぞ!

マニュアルを読む

私が初動のenvoy調整をしている間に @netmarkjp と @ishikawa84g でマニュアルを通読してもらいました。 気になるところは @ishikawa84g がスライドにまとめ上げていて後で参照しやすくとても助かりました。わいわい。

docs.google.com

初回ベンチ実行

初回ベンチ実行でダッシュボード表示(/api/audience/dashboard)が遅いことを確認してます。 kataribe実行結果より

Top 50 Sort By Total
Count     Total    Mean  Stddev    Min  P99.9    Max    2xx   3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
11606  1821.391  0.1569  0.1799  0.002  1.560  1.990  11606     0    0    0   249308292          2      21480      25122  GET /api/audience/dashboard HTTP/2
 1596   581.121  0.3641  0.1905  0.001  0.665  0.666   1596     0    0    0       34450          5         21         80  POST /xsuportal.proto.services.bench.BenchmarkQueue/ReceiveBenchmarkJob HTTP/2
 2978   572.663  0.1923  0.2492  0.001  1.941  2.525   2978     0    0    0       34173          0         11         73  get /api/contestant/notifications?.*

アプリ実装とSQLを確認したもののすぐの改修が難しく、いくつかインデックスの追加しても速度改善が見込めない状況でした。

キャッシュ戦略

ただ、マニュアルをしっかり読んでいたため1秒間はキャッシュできることを確認したのでenvoyとxsuportalの間にVarnishを挟んでキャッシュする戦略としました。 初期化対策のため /initialize にアクセスがあった場合はキャッシュを削除するよう設定しています。

# /etc/varnish/default.vcl
vcl 4.0;

backend default {
    .host = "127.0.0.1";
    .port = "9292";
}

sub vcl_recv {
    if (req.url ~ "^/initialize") {
       ban("obj.http.url ~ ^/api/audience/dashboard");
    }
}

sub vcl_backend_response {
    if (beresp.http.content-type ~ "text") {
      set beresp.do_gzip = true;
    }
    if (beresp.http.content-type ~ "javascript") {
      set beresp.do_gzip = true;
    }
    if (bereq.url ~ "^/packs/") {
      set beresp.ttl = 60s;
      set beresp.http.cache-control = "public, max-age=60";
    }
    if (bereq.url ~ "^/api/audience/dashboard") {
      set beresp.ttl = 1s;
      set beresp.http.cache-control = "public, max-age=1";
    }
}

この1秒キャッシュはその後負荷が増えると応答遅延などの影響でエラーとなる場合あり、キャッシュ時間は 1s0.8s0.7s と徐々に短くしてます。 上記の結果もありkataribeの結果はダッシュボード表示が2番に下がったことを確認してます。

Top 50 Sort By Total
Count    Total    Mean  Stddev    Min  P99.9    Max    2xx   3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
 1822  510.656  0.2803  0.2199  0.007  0.637  0.671   1822     0    0    0       70231          5         38         80  POST /xsuportal.proto.services.bench.BenchmarkQueue/ReceiveBenchmarkJob HTTP/2
21365  205.622  0.0096  0.0265  0.000  0.382  0.416  21354     0    0   11   790986026          2      37022      55120  GET /api/audience/dashboard HTTP/2
 4392  129.572  0.0295  0.0282  0.002  0.332  0.400   4392     0    0    0       77408          0         17         74  get /api/contestant/notifications?.*

ReceiveBenchmarkJob対策

次に多い ReceiveBenchmarkJobのソースコードを見て「ウッ、gRPCなんも分からん」となったものの、SELECT FOR UPDATEからUPDATEを実行している実装があって一応「あっこれ予選で見たやつだ」となって念の為修正しています。

負荷が増えないところからTeamCapacityの気づき

CPUやメモリに負荷がなくボトルネックになっている様子がないことから何らかのリミットを考えてトラフィック量を削減するためにVarnishでgzip応答を返してみるものの改善せず、何だろうなとマニュアルとソースとにらめっこしていたところ、アプリ側でTeamCapacityで上限が制約されていることを確認。これだーと気づいてTeamCapacityを増やしていきました。 10→20→60→120→180→60。このあたりの調整に時間をかけていたのですが、最終的には120でフィニッシュしています。

open files limit対策

TeamCapacityを増やしていくとenvoyやアプリでopen files limitに引っかかったようなメッセージが表示されることを確認したのでインフラにめっぽう強い我々は速攻で対処しています。

# systemctl edit envoy.service
[Service]
LimitNOFILE=524288

13:07、スコアは25455です。

メモリ対策

MySQLとVarnishのメモリ消費が問題となったので、以下のように対策を実施しました。

  • MySQLはメモリ量の多いisu2サーバに移設
  • Varnishはメモリ設定を変更しても削減されず
    • xsuportal宛の通信をすべてVarnishに通していたが、キャッシュ対象のみ通すように変更

Varnishのメモリ消費原因の特定がなかなかできなかったのですが、大量の接続とgzip処理による負荷ではないかと思っています。これで一旦メモリ消費は解消しています。

Varnishではforkが問題になったのでこちらも併せて引き上げています。

# systemctl edit varnish.service
[Service]
TasksMax=4096

CPU負荷対策

このあたりでアプリ(xsuportal)のCPU負荷がネックとなっていたのでCPUコアの数が多いisu3へアプリを移設しました。

この時点で14:49、スコアは30244でした。

通知機能対策

この頃になると通知機能がボトルネックになっていました。

Top 50 Sort By Total
Count     Total    Mean  Stddev    Min  P99.9    Max    2xx   3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
19604  2624.748  0.1339  0.1460  0.001  1.325  1.943  19604     0    0    0      196884          0         10        118  get /api/contestant/notifications?.*
 2100  2031.179  0.9672  1.1011  0.002  8.695  9.750   2100     0    0    0       77559          5         36         80  POST /xsuportal.proto.services.bench.BenchmarkQueue/ReceiveBenchmarkJob HTTP/2
 1123  1038.024  0.9243  1.0063  0.001  5.062  5.306   1121     0    2    0     5275953          0       4698       9800  GET /api/contestant/clarifications HTTP/2

そこでアプリケーションマニュアルで手厚く説明されているWeb Push serviceの実装に踏み切ります。 慣れないWebPush実装は少し手こずったものの、なんとかベンチマークが実行できるところまで実装することができました。

Top 50 Sort By Total
Count     Total    Mean  Stddev     Min   P99.9     Max    2xx   3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
 2146  1892.735  0.8820  1.1223   0.003   9.864  10.454   2146     0    0    0       85671          5         39         80  POST /xsuportal.proto.services.bench.BenchmarkQueue/ReceiveBenchmarkJob HTTP/2
22411  1785.695  0.0797  0.1195   0.000   1.240   1.843  22411     0    0    0           0          0          0          0  get /api/contestant/notifications?.*
 1321   963.386  0.7293  0.9943   0.002   4.938   4.980   1319     0    2    0     5946332          0       4501       8850  GET /api/contestant/clarifications HTTP/2

この時点で16:29、スコアは32173でした。

TeamCapacity調整

ここからはTeamCapacityを60から120に引き上げることでベストスコア44269を記録するもののfailとなる割合が多く、3回に1回ぐらいの頻度でしか成功しない状況が続きます。 が、ここで当日マニュアルの「競技時間終了後に運営によって行う作業手順」を 3回のうち1回でも負荷テストに通ればok、それでダメでもその次の再チェックで通ればok と勘違いをしてしまいこのままフィニッシュとしてしまいました。 ここで日和って120から60などに下げておけばおそらくfailにならずに完走できたのではないかと悔やんでおります。うーむ、悔しい。

わいわい

そんなわけでウー馬場ーイーツはほぼインフラエンジニア力で大半のスコアを稼ぎ、おまけで通知機能のプログラミングを少し頑張った実装になりました。まだまだ改善の余地はあるので引き続き感想戦に邁進し、来年こそは優勝をもぎ取ろうと思います。来年の活躍にどうぞご期待ください。

ISUCON10予選で12位になり本選進出を決めました

TL;DR

ISUCON10の本選出場が決定しました。わいわい。 予選12位、最終スコアは2837でした。

毎年素晴らしいコンテストを開催してくださる運営様には、本当に頭が下がります。いつもありがとうございます。 本選もがんばるぞ!

体制

チーム名 ウー馬場ーイーツ

あいこん なまえ やくわり
f:id:tmatsuu:20190909215748j:plain:w100 matsuu バリバリ実装する前衛
f:id:tmatsuu:20190909215614p:plain:w100 netmarkjp 司令塔
f:id:tmatsuu:20190909215620j:plain:w100 ishikawa84g SELinuxAppArmorとレギュレーションやコードやDiscordを見るセキュリティ&情報官

今回は3人が同じ場所に集まらずすべてリモート体制としました。 3人だけのDiscordサーバを用意し、Discord上で画面共有と音声チャットで進めています。

方針

毎年同じですが

  • sshで接続してtmux上でvimで直接編集
  • isuumo配下でgit initを実行するが履歴保存用でbranchは作成しない

毎年今年こそはvscodeとか夢見るんですが、結局手に馴染んだtmux+vimが最強というオチです。

解析ツール

使用した解析ツールは以下の通り。

  • dstat
  • kataribe
  • mysqltuner.pl
  • pt-query-digest
  • top

ベンチマーク実行中はdstatとtopで負荷状況を目視確認しています。 ベンチマーク実行後はkataribeとpt-query-digestでログ解析、おまけでmysqltuner.plを実行しています。

事前にNew Relicも確認してましたが、goでは導入に骨が折れるので利用しませんでした。

最終構成

最終構成は以下の通りです。

サーバ 構成要素 備考
1台目 nginx+go バージョン変更なし
2台目 mysql 8.0.21にアップグレード
3台目 使用せず(!!!)

3台目も活用できればもっといけたかもですね。

ベンチマーク結果

f:id:tmatsuu:20200913131101p:plain

初動

pt-query-digestとkataribeで集計できるようmysqlとnginxの設定変更。

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

+
+slow_query_log=1
+slow_query_log_file=/var/log/mysql/mysql-slow.log
+long_query_time=0

/etc/nginx/nginx.conf

     log_format  main  '$remote_addr - $remote_user [$time_local] "$request" '
                       '$status $body_bytes_sent "$http_referer" '
-                      '"$http_user_agent" "$http_x_forwarded_for"';
+                      '"$http_user_agent" $request_length $request_time';

$request_length も追加するのが最近のお気に入りです。

マニュアルを読む

マニュアルを読んだ段階でnginxでUser-Agentによるbotフィルタ実施。正規表現を読み砕いて不要な表現は削除しています。

/etc/nginx/sites-available/issumo.conf

+map $http_user_agent $bot {
+  default 0;
+  "~ISUCONbot" 1;
+  "~Mediapartners-ISUCON" 1;
+  "~ISUCONCoffee" 1;
+  "~ISUCONFeedSeeker" 1;
+  "~crawler \(https://isucon\.invalid/(support/faq/|help/jp/)" 1;
+  "~isubot" 1;
+  "~Isupider" 1;
+  "~*(bot|crawler|spider)(?:[-_ .\/;@()]|$)" 1;
+}
+
 server {
     root /home/isucon/isucon10-qualify/webapp/public;
     listen 80 default_server;
     listen [::]:80 default_server;

+    if ($bot = 1) {
+        return 503;
+    }
+

curlで該当するUser-Agentでアクセスしてみて503応答になることを確認。

初回ベンチ実行

topとdstatを実行しながらベンチマーク実施。この時点でmysqldのCPU負荷が支配的であることを確認。 pt-query-digestの結果をもとにインデックスを追加しました。

isuumo/webapp/mysql/db/3_index.sql

-- この時点で追加したインデックスは記録が取れておらず記憶があいまい
ALTER TABLE isuumo.estate ADD INDEX (rent, popularity);
ALTER TABLE isuumo.estate ADD INDEX (door_width, door_height, popularity);
ALTER TABLE isuumo.estate ADD INDEX (popularity);
ALTER TABLE isuumo.chair ADD INDEX (stock, price);
ALTER TABLE isuumo.chair ADD INDEX (price);

ADMIN PREPARE対策

ADMIN PREPAREが多い。DBへの接続時に自動prepareをしないようDSNに interpolateParams=true を追加しました。

 func (mc *MySQLConnectionEnv) ConnectDB() (*sqlx.DB, error) {
-       dsn := fmt.Sprintf("%v:%v@tcp(%v:%v)/%v", mc.User, mc.Password, mc.Host, mc.Port, mc.DBName)
+       dsn := fmt.Sprintf("%v:%v@tcp(%v:%v)/%v?interpolateParams=true", mc.User, mc.Password, mc.Host, mc.Port, mc.DBName)
        return sqlx.Open("mysql", dsn)
 }

なぞって検索対策

なぞって検索に関連するSQLの実行回数が異常に多いことからN+1実装となっていることを確認。1発のクエリーで取得できるよう変更しました。

SELECT * FROM estate WHERE latitude <= ? AND latitude >= ? AND longitude <= ? AND longitude >= ? AND ST_Contains(ST_PolygonFromText(?), POINT(latitude, longitude)) ORDER BY popularity DESC, id ASC LIMIT ?

rentなどの範囲による絞り込みをID化

pt-query-digestの上位クエリーがrentなどの範囲(range)による絞り込みになっておりインデックスを効かせにくいと判断してrentのIDを格納するカラムをテーブルに追加しています。

ALTER TABLE isuumo.estate ADD COLUMN rent_id INTEGER NOT NULL DEFAULT 0;
ALTER TABLE isuumo.estate ADD COLUMN door_height_id INTEGER NOT NULL DEFAULT 0;
ALTER TABLE isuumo.estate ADD COLUMN door_width_id INTEGER NOT NULL DEFAULT 0;

ALTER TABLE isuumo.chair ADD COLUMN height_id INTEGER NOT NULL DEFAULT 0;
ALTER TABLE isuumo.chair ADD COLUMN width_id INTEGER NOT NULL DEFAULT 0;
ALTER TABLE isuumo.chair ADD COLUMN depth_id INTEGER NOT NULL DEFAULT 0;
ALTER TABLE isuumo.chair ADD COLUMN price_id INTEGER NOT NULL DEFAULT 0;

UPDATE estate SET rent_id = 0 WHERE rent < 50000;
UPDATE estate SET rent_id = 1 WHEN 50000 <= rent AND rent < 100000;
UPDATE estate SET rent_id = 2 WHEN 100000 <= rent AND rent < 150000;
UPDATE estate SET rent_id = 3 WHEN 150000 <= rent;
ALTER TABLE estate ADD INDEX (rent_id);
-- 以下同様のため省略

条件のSQL生成がすっきり。

-               if estateRent.Min != -1 {
-                       conditions = append(conditions, "rent >= ?")
-                       params = append(params, estateRent.Min)
-               }
-               if estateRent.Max != -1 {
-                       conditions = append(conditions, "rent < ?")
-                       params = append(params, estateRent.Max)
-               }
+               conditions = append(conditions, "rent_id = ?")
+               params = append(params, estateRent.ID)
        }

INSERT前に rent_id に格納する値を計算。

var rentId int64
switch {
        case rent < 50000:
                rentId = 0
        case rent < 100000:
                rentId = 1
        case rent < 150000:
                rentId = 2
        default:
                rentId = 3
}

SELECT * FROM ...rent_id などを取り除いたカラムを列挙。

-- 変更前
SELECT * FROM estate ...
SELECT * FROM chair ...
-- 変更後
SELECT id, name, description, thumbnail, address, latitude, longitude, rent, door_height, door_width, features, popularity FROM estate ...
SELECT id, name, description, thumbnail, price, height, width, depth, color, features, kind, popularity, stock FROM chair ...

initializeがタイムアウト

上記設定後に実行したベンチマーク結果のpt-query-digestの上位クエリーにさらにインデックスを追加していくと、initializeが30秒以内に終わらなくなる。

今回各テーブルの descriptionVARCHAR(4096) と大きくレコード登録後にカラムを追加するととても時間がかかることが判明。幸いデータの流し込みがカラム名指定付きのINSERTだったのでデータ流し込み前にカラムを追加しても問題ないと判断。

CREATE TABLE isuumo.estate
(
   -- 省略
);

ALTER TABLE isuumo.estate
  ADD COLUMN rent_id INTEGER NOT NULL DEFAULT 0 AFTER id,
  ADD COLUMN door_height_id INTEGER NOT NULL DEFAULT 0 AFTER id,
  ADD COLUMN door_width_id INTEGER NOT NULL DEFAULT 0 AFTER id,

その他のクエリーも高速化。UPDATEはCASEで一度に。インデックス追加も一発で。

UPDATE isuumo.estate SET
  rent_id = CASE WHEN rent < 50000 THEN 0 WHEN rent < 100000 THEN 1 WHEN rent < 150000 THEN 2 ELSE 3 END,
  door_width_id = CASE WHEN door_width < 80 THEN 0 WHEN door_width < 110 THEN 1 WHEN door_width < 150 THEN 2 ELSE 3 END,
  door_height_id = CASE WHEN door_height < 80 THEN 0 WHEN door_height < 110 THEN 1 WHEN door_height < 150 THEN 2 ELSE 3 END;

ALTER TABLE isuumo.estate
  ADD INDEX (rent_id, popularity),
  ADD INDEX (door_height_id, rent_id),
  ADD INDEX (door_width_id, rent_id),
  ADD INDEX (rent),
  ADD INDEX (popularity),
  ADD INDEX (latitude);

この時点で15:37:01、スコアは1144です。

MySQL 8.0へのアップグレード(ORDER BY対策)

この時点でもMySQLのCPU使用率が支配的な状況。pt-query-digestで上位のクエリーのEXPLAINを確認すると ORDER BY でインデックスが効いてない。よく見るとDESCとASCの混合が理由と判明。

SELECT ... ORDER BY popularity DESC, id ASC LIMIT ...

MySQL 8.0ではこのような場合でもインデックスを適用できる降順インデックスの存在を思い出してMySQL 8.0へのアップグレードを決意。

wget https://dev.mysql.com/get/mysql-apt-config_0.8.15-1_all.deb
sudo dpkg -i mysql-apt-config_0.8.15-1_all.deb
sudo apt update
sudo apt install mysql-server

これでMySQLはバージョン8.0.21に。

MySQLアップデート後性能が大きく下がってしまったが、調べていくとMySQL8.0でバイナリログが有効に変わり、undoログが記録されるようになったことを確認。この環境のDISK性能が結構低いなどからio改善のため以下を追加。

disable-log-bin
innodb_log_group_home_dir = /dev/shm/
innodb_doublewrite = 0
innodb_flush_log_at_trx_commit = 0

UNDOログもtmpfsに載せようとしたものの、試行錯誤の結果UNDOログは消えると正常に起動しないことから再起動リスクが大きいと判断して触りませんでした。

innodb_log_fileをtmpfsに逃したことと、disable-log-binの効果が大きかった気がします。

なお、 innodb_log_group_home_dirの/dev/shmへの変更はAppArmorで遮られるため適宜調整しています。

/etc/apparmor.d/usr.sbin.mysqld

  /dev/shm/ r,
  /dev/shm/** rwk,

降順インデックス追加

ALTER TABLE isuumo.estate ADD INDEX (rent_id, popularity DESC, id ASC);
ALTER TABLE issumo.estate ADD INDEX (popularity DESC, id ASC);
ALTER TABLE isuumo.chair ADD INDEX (popularity DESC, id ASC);

いい感じにインデックスが効くようになったことを確認。

この時点で16:50:09、スコアは1200です。

空間インデックスと向き合う

この時点でもMySQLのCPU使用率が支配的な状況ですが、一番遅いクエリーはなぞって検索のクエリー。

SELECT id, name, description, thumbnail, address, latitude, longitude, rent, door_height, door_width, features, popularity FROM estate WHERE latitude <= ? AND latitude >= ? AND longitude <= ? AND longitude >= ? AND ST_Contains(ST_PolygonFromText(?), POINT(latitude,longitude)) ORDER BY popularity DESC, id ASC LIMIT ?

ここで空間インデックスの存在を思い出し ST_Contains() で空間インデックスを利用できないかの検討をはじめました。

まず POINT(latitude, longitude) はlatlngから導出できるためpoint型としてカラムに追加。ただし追加するタイミングではNOT NULLにできず、しかしインデックスを追加するためにはNOT NULLに設定する必要がありこんな感じになりました。

ALTER TABLE isuumo.estate ADD COLUMN point POINT;
-- データ登録
UPDATE isuumo.estate SET point=POINT(latitude, longitude);
ALTER TABLE issumo.estate MODIFY COLUMN point POINT NOT NULL;
ALTER TABLE issumo.estate ADD SPATIAL INDEX (point);

しかしこの変更を行ってもSPATIAL INDEXが使われずしばらく悩んだのですが、ググラビリティと試行錯誤を経て SRID 0 を追加すればインデックスが使われることをEXPLAINで確認しました。

ALTER TABLE issumo.estate MODIFY COLUMN point POINT SRID 0 NOT NULL;

わかるかこんなの! なぞって検索の応答時間は平均0.401秒から平均0.063秒と大きく改善しました。

この時点で18:24:13、スコアは1819です。

件数をキャッシュ

この時点でもMySQLのCPU使用率が支配的な状況ですが、pt-query-digestの上位3番目ぐらいに以下のクエリーがきていたので、

SELECT COUNT(*) FROM estate WHERE rent_id = ?

rentのみが条件の場合に絞ってCOUNTをアプリ側でキャッシュすることにしました。

自分はsync.Mapが大好きマンなのでこんな実装になっています。使い方が間違ってたら教えて下さい。

var rentMap sync.Map

        // 初期化
        rows, err := db.Query("SELECT rent_id, count(1) FROM estate GROUP BY rent_id")
        if err != nil {
                ...
        }
        for rows.Next() {
                var rentId, cnt int64
                rows.Scan(&rentId, &cnt)
                rentMap.Store(rentId, &cnt)
        }
        rows.Close()

        // INSERT時のインクリメント
        v, _ := rentMap.Load(rentId)
        p, _ := v.(*int64)
        atomic.AddInt64(p, 1)

        // 取り出し
        if len(conditions) == 1 && hasRent {
                v, _ := rentMap.Load(rentId)
                res.Count = *v.(*int64)
        }

再起動対策のため起動時はmain()とinitialize()の両方でやってます。

この時点で19:30:06、スコアは2070です。

MySQLを2台目サーバに

この時点でもMySQLのCPU使用率が一番高いのですが、nginxとappのCPU使用率も上がってきたことを確認したのでMySQLを2台目サーバに移すことにしました。

この時点で20:07:59、スコアは2612です。

MySQLを3台目サーバに用意するも断念

binlogを出力するとDISK性能が刺さることからレプリケーションは断念、ただあろうことか両方にINSERTすればいいのではという発想でプログラムを改修したものの、おそらくINSERTにかかる時間でタイムアウトが発生しcritical errorを回避できずに断念しました。

今にして思えばJOINがなかったのでテーブルを分ければ良かったのですが、そこまでは思いつきませんでした。分けた場合の性能改善は今後の検討課題です。

ログ出力を抑制

仕上げとしてmysqlのスロークエリーログ、nginxやアプリのアクセスログ出力を抑制してベンチを回しました。

この時点で20:46:31、スコアは2837です。

事前の再起動テストで問題発覚

最後に再起動試験を行ったところ、1台目サーバと2台目サーバの再起動タイミングがずれるとアプリからのDB接続に失敗、systemdのデフォルト設定によりアクセスできなくなってしまう事象が発生しました。

systemdのログからギリギリで以下の設定を追加しています。

/etc/systemd/system/isuumo.go.service

[Service]
StartLimitBurst=999

あぶない。

その他

その他に以下のような改善を実施しています。

  • nginxでgzipを有効に
  • nginxとgolangの間の接続をHTTP/1.1にしてkeepaliveを有効に
  • POST /api/estatePOST /api/chairclient request body is buffered to a temporary file の発生を確認したため、nginxで client_body_buffer_size を調整
  • POST /api/estatePOST /api/chair でのINSERT時に tx.Prepare() してから stmt.Exec()

ISUCON9本選を11位でフィニッシュしました

ISUCON9本選に「いんふらえんじにあー as Code」として参加し、11位でフィニッシュしました。悔しい。 最高スコアは9107、運営確認の最終スコアは8995でした。

メンバー紹介

チーム名 いんふらえんじにあー as Code

あいこん なまえ やくわり
f:id:tmatsuu:20190909215748j:plain:w100 matsuu バリバリ実装する前衛
f:id:tmatsuu:20190909215614p:plain:w100 netmarkjp 司令塔
f:id:tmatsuu:20190909215620j:plain:w100 ishikawa84g レギュレーションやコードやログやDiscordを見る情報官

構成

初期はこんな感じですが

1台目 nginx --- go(docker) --- mysql(docker)
2台目 同上
3台目 同上

最終構成はこうなりました。

1台目 nginx --- go --- mysql(docker)
2台目 利用せず
3台目 利用せず

goをdockerから剥がしただけ、中途半端にmysqlをdockerに残したままとなりました。 このような構成になったのは以下が理由です。

  • docker-composeでgoのアプリ更新がうまくいかず手っ取り早く更新ができるようにgoを引きはがした
  • mysqlはバージョン8が利用されておりインストールの手間を避けた
  • mysqlのcpu負荷が支配的でmysqlレプリケーション構成に変更する時間もなくサーバを分けるところまで至らなかった

ただ、この構成にしたためにsystemdの起動用service unitで考慮が必要となり、再起動対策で終盤時間を取られてヒヤヒヤものでした。

スコアの遷移

f:id:tmatsuu:20191006144309p:plain
ISUCON9本選スコア遷移@いんふらえんじにあー as Code

序盤足踏み状態が続いたものの後半からスコアが倍々に増えていったものの、入賞するところまでスコアを上げきれませんでした。残念。

ざっくりまとめ

ネタバレを含みますのでご了承ください。

安易にPRIMARY KEYを張ってはいけない

今回、初見でDBのCPU負荷が高く、PRIMARY KEYが設定されていないテーブルでスロークエリーが発生していたこともあり安易にPRIMARY KEYを追加したのですが、これが 大きな罠 でした。 後から分かったことではあるのですが、PRIMARY KEYがないテーブルはINSERTされた順番に意味がある上に ORDER BY が使われておらず、むやみにPRIMARY KEYやINDEXを追加すると出力結果がかわってしまってFailになるのです。さらに質が悪いのがPRIMARY KEYを張って直後のベンチマークでは即座にエラーにならず、またPRIMARY KEYやINDEXを外しても出力結果が変わってしまい、最初からデータを作り直す以外はどう頑張っても復旧できなくなってしまった(と思い込んだ)ことです。 おそらくそれについては勘違いではないかと思いたいのですが、問題が公開されたらしっかり追試するつもりです。

goplsはメモリを食うので気を付ける

我々のチームはサーバ上でvim(vim-go)の環境を構築してプログラムの修正を行っていたのですが、goplsが思いのほかメモリーを食ってました。今回の環境はメモリーが1GBと少なくページイン/ページアウトが発生しまくって極端に体感速度が遅くなる事態が発生しました。一時は killコマンドすらメモリ不足で実行(fork)できない 最悪の事態になって無駄に時間を浪費しました。あの時間ロスがなければ…。

Docker構成は中途半端にはがすことなかれ

Docker構成のまま、Docker構成をやめる、のいずれの対応でもよかったのですが、剥がすなら中途半端にせず全部剥がすべきでした。再起動した場合の起動制御がややこしくなるためです。

docker-composeはログ出力によるメモリ消費に注意

今回webappは意図的にデバッグログの出力が多く残されているためかdocker-composeのメモリ消費がもりもり増える現象に悩まされました。今回の本選マニュアルにもメモリ消費に気をつける旨の記述があったので気をつけたいところですね。現実にもあるあるなのかも。

Alibaba Cloudのサーバはタイムゾーンが中国標準時(CST)

今回OSはUbuntu 18.04だったんですが、Alibaba CloudのUbuntuサーバはデフォルトのタイムゾーン設定が中国標準時になっているのでログを見るときは要注意です。Alibabaらしさを感じますね。ちなみに予選の環境はUTCに設定されていました。

運営のシークレットメッセージを見つけよう

運営はscreen/tmuxをつかった場合にメッセージを残していました。

# ~/.bash_profile
case "${TERM}" in
  screen*)
    export PROMPT_COMMAND='printf "\033k\U1F004 %s:\033\\" "${HOSTNAME%%.*}"'
    ;;
esac

どうなるかはぜひ手元で試してみてください。

おわりに

ありがとう運営。そしてしっかり復習しようと思います。来年も頑張るぞ!