ISUCON11予選に参加して失格になってきた - taka_rock’s blog

taka_rock’s blog

エンジニアの勉強記録

ISUCON11予選に参加して失格になってきた

概要

去年(予選, 本戦)に引き続きISUCON11 予選に参加し、失格になってきた。
その振り返り。

f:id:taka_rock:20210901000004p:plain
最終スコア

また、去年参加したチームは、今年社会人になった僕以外今年も学生ということで、学生枠での本戦出場を目指して解散した。
ということで会社の同期に声を掛けて、次のチームで出場した。

事前準備したこと

利用言語は、メンバー全員が普段業務でKotlin, ScalaといったJVM系の言語を書いており、実装が無いので可読性の高さなどからGoでやることにした。
ミドルウェアはNginx, MySQLが使用されると想定して、設定や計測の練習や準備を事前に行った。

準備した計測ツールは下記

  • プロファイラー
    • pprof
  • アクセスログ解析
    • alp
  • スロークエリ解析
    • pt-query-digest
  • リソース確認
    • htop

毎年ツールの導入方法をISUCON前に思い出しているので、自分のメモのために導入方法も書いておく。

pprof

net/http/pprofに書いてあるように、こんな感じで追記すればOK。便利。

import _ "net/http/pprof"

func main() {
  go func() {
      log.Println(http.ListenAndServe("localhost:8080", nil))
  }()
}

プロファイルする際はローカルから

$ go tool pprof -http=":8888" "http://example.com:8080/debug/pprof/profile?secondos=60"

みたいな感じで、計測をした。

alp

下記コマンドでインストール

$ curl -OL https://github.com/tkuchiki/alp/releases/download/v1.0.7/alp_linux_amd64.zip
$ unzip alp_linux_amd64.zip
$ sudo install alp /usr/local/bin/alp

Nginxのログ出力をLTSV形式に設定して、こんな感じのコマンドでアクセス合計時間で降順にソートしてログを解析できる。

$ alp --sort=sum -r --file=/var/log/nginx/access.log ltsv | head -n 10

pt-query-digest

下記コマンドでインストール

$ wget https://www.percona.com/downloads/percona-toolkit/3.0.3/binary/debian/jessie/x86_64/percona-toolkit_3.0.3-1.jessie_amd64.deb
$ sudo apt-get install -y gdebi
$ sudo gdebi -n percona-toolkit_3.0.3-1.jessie_amd64.deb

MySQLの設定でslow_queryを出力するようにして、下記コマンドで解析できる。

$ pt-query-digest /var/log/mysql/mysql-slow.log

htop

topコマンドで もリソース確認できるが、特に何もしなくても見やすいのでhtopを使用することにした。

$ sudo apt install -y htop

でインストールして

$ htop

で使用する。

セットアップスクリプト

当日、各サーバーにセットアップする手間を減らすために簡単なスクリプトを書いた。

github.com

デプロイスクリプトも書きたかったが、準備する時間が無く、準備できなかった。絶対にあった方が便利なので、来年は頑張りすぎない程度に事前に用意する。

当日やったこと

当日のチームメンバーの動きは、下記のように予め大まかに決めておいた。

  • takahiro
    • インフラ
  • tomonori
    • 問題の読み込み+計測+App改善
  • shutarou
    • App改善

当日行ったことを、自分が行ったことと記憶を元におおまかな時系列順にまとめていく。

10:00 競技開始と初回ベンチ2396点

競技開始され、AWS CloudFormationのテンプレートが配布されたので適用した。
競技用サーバーのIPが確定したら、ssh用のconfigファイルを用意してメンバーに共有した。
ここで実行した初回ベンチマークのスコアは2396点だった。

10:10 諸々のセットアップ

事前に用意しておいたセットアップスクリプトを実行し、tomonoriに問題の読み込み、shutarouに競技のコードをGitHubへのpushをお願いした。
自分は、サーバーのスペックと実行環境を確認した。
サーバーのスペックはAWSコンソールから確認し

$ sudo systemctl status nginx

でnginxが動作してることを安心して

$ sudo systemctl status mysql

でMariaDBだったことに少し驚いたが、MySQLと互換性あるからなんとかなるだろうと思い、alpとpt-query-digestで計測できるようにNginxとMatiaDB側の設定を書き換えた。

10:30 AppとDBの分離

AppとDBを別のサーバーに分けたほうが計測しやすいと考え、最初に下記の様にAppとDBを別サーバーに分離した。

  • サーバー1
    • Nginx
    • App(Go)
  • サーバー2

(限界まで1サーバーでチューニングした方が良い気もするので、来年は事前の準備段階でそのことについてもうちょっと考えておいた方が良さそう。)

ここで、ローカルからもDBへアクセスできるように、AWSのセキュリティーグループのインバウンドへ3306を特に何も考えずに追加した。

11:00 MariaDBのチューニングを少しして6825点

MariaDBのチューニングを少しした。 git管理していなかったので微かな記憶だが、下記の値を設定した気がする。
(来年はこの辺の設定ファイルもちゃんとgit管理しておきたい)

innodb_buffer_pool_size = 3GB
innodb_flush_log_at_trx_commit = 2
innodb_flush_method = O_DIRECT

サーバーのメモリが大きかったので、雰囲気でquery_cache_sizeも大きくしといた気がする。

この時点で、スコアは6825点

12:00 DB使用率が100%

ベンチマークを実行した際のサーバーリソースを計測すると、DB使用率が100%だった。
alpの実行結果と f:id:taka_rock:20210901002957p:plain pt-query-digestの実行結果 f:id:taka_rock:20210901003437p:plain を確認して、isu_conditionテーブルのreadとwriteが原因でCPU利用率が100%になっていると考え、POST /api/condition/[0-9a-z\\-]+があまりにも多かったので、write側のチューニングをしようとチームで決めた。
(pt-query-digestの結果から、INDEXを貼ることによりreadの改善が期待されたが、write優先で後回しにした。パッとできる改善ではあったので、パッとやっちゃえば良かったと後から思った。)

12:30 isu_conditionのBulkInsert化

他のメンバーがisu_conditionのwriteを減らすために複数回分のリクエストをまとめてInsertしようとしたりしてくれていたが、非同期周りのハンドリングが難しくて、1リクエスト内のBulkInsertだけ実装した。この辺はチームメンバーに任せていたので、詳しいことは分かっていない。
その間に自分は、Appのソースコードを読んだり、DBの中身を確認してた。

13:30 GoからDBへのコネクションの制限を無くす

ソースコードを読んでいたら

db.SetMaxOpenConns(10)

と、最大コネクション数が10に制限されていたので、コメントアウトした。
スコアは全然上がらなかった。

14:00 jia_service_urlを変数で持つように

isu_association_configに保存されているjia_service_urlが、初期化処理時以外に変化して無さそうだったので初期化処理時に変数で持つようにしてDBから取得しないようにした。
これもスコアは全然上がらなかった。

14:30 DBを2台にしようと妄想する

相変わらず、DBサーバーがCPU100%のままなのでなんとかしようと考える。 水平分割すると良いのかな？とか妄想しながらとりあえず、ボトルネックになっているisu_conditionテーブルだけ別サーバーのDBにしてなんとかしようとGoとDBのセッティングをしてた。
↓が起きたので、PRだけ作成して反映はしなかった

15:00 isu_conditionに貼り忘れてたINDEXを貼る 23000点

isu_conditionにINDEX貼ると良さそうって話をしていたもののINDEXを貼っていなかったので、tomonoriがINDEXを貼ってくれた。
ベンチマークを実行すると唐突に23000点になって衝撃を受けた。

サーバーのリソースを確認するとDBのCPU使用率が低下し、App側が100%になっていたので、サーバー構成を

  • サーバー1
    • Nginx
    • App(Go)
  • サーバー2
    • App(Go)
  • サーバー3

にしようと考える。

16:30 App2台構成で30000点

Nginxでロードバランシングすれば、App2台に簡単に構成にできると思ってたら、少しハマってベンチマークが失敗し、時間を取られてしまった。

ハマった点としては下記

  • 初期化に必要なSQLファイルが追加したサーバーに配置されていなかった
    • 初期化に必要な/sql/1_InitData.sqlをgitignoreしており、元々存在していたファイルを削除してしまっていたため、初期化に失敗していた。全然意識していなかったので、気づくのに遅れてしまった。
  • jia_service_urlを取得できない
    • jia_service_urlを初期化時に変数で持つようにしたことにより、初期化をしていないサーバーだと失敗するようになっていた。

上記を改善して、App2台構成で30000点

17:00 trend APIの改善をしようとする

App2台構成で負荷分散すると、DBのCPU使用率が100%になった。
alpの結果が

f:id:taka_rock:20210901013538p:plain

とtrend APIの呼び出し回数が、増えていたので他のチームメンバーに改善をお願いした。
任せてしまったので、詳細な変更内容は把握できてないが、処理の高速化を行ったらAPI呼び出しが増えてスコアが下がってしまい、revertした。

17:10 Nginxの設定をチューニングしたりした

nginxのworker_connectionsを増やしてみたり、ロードバランシングをラウンドロビンとLeast Connectedで比較してみたりした。 スコアはあまり変わらなかった。

この辺で、運営側に障害が発生し、ベンチマークが実行できなくなった。

17:30 撤退準備してたら51865点

ベンチマークが実行できなくなってる間に、撤退準備をした。
行ったこととしては、nginx,mysqlのログ出力停止、goのpprofを削除したりした。

その間にベンチマークが復活し、実行すると51865点。
pprofの削除が効いたっぽい？

18:30 dropProbabilityに願いをかける

ベンチマークの障害により延長された時間でdropProbabilityに願いをかけた。
0, 0.5, 0.9の値で検証してみたものの、デフォルトの0.9が最もスコアが高かったため、0.9を採用。

18:45 競技終了 43797点

51865点を取った際と特に差分はないはずだが、何故か再現することができず43797点でフィニッシュ。

結果

失格になりました。

f:id:taka_rock:20210901000004p:plain
最終スコア

DB等をローカルからアクセスできるようにするために、AWSのセキュリティーグループのインバウンドを追加した事が原因です。 レギュレーションをちゃんと読んでおらず、禁止されていることを認識せずに何も考えずに行いました、、、

振り返り

良かったこと

  • チームメンバーの役割分担を予め決めておいたこと
  • 計測ツールの導入、実行方法を予め確認できていたこと
  • サーバーリソースの確認、ログの解析を行いながらチューニングが行えたこと

悪かったこと

  • レギュレーション、アプリケーションマニュアルをちゃんと読んでいなかったこと
  • INDEX追加等、とりあえずできることをすぐにやらなかったこと
  • ミドルウェアのチューニングをなんとなくで進めてしまっていたこと

今年できなかったけど来年はやるとよさそうなこと

まとめ

チューニングを愚直にやることで、着実に点数が上がる問題だった。
結果として失格にはなってしまったが、ちゃんと計測し、チームで色々議論しながらパフォーマンスチューニングできて楽しかった。
来年も出場して本戦出場したい。

appendix

shutarouの参加ブログ chouxcreams.hatenablog.com

使用したGitHubレポジトリ github.com