チーム白金動物園としてISUCON13に参加しました

結成たぶん10年くらいのチーム白金動物園（mirakui, sorah, rosylilly）として ISUCON 13 に参加してきました。ここ数年はなんだかんだ運営側であることが多かったので、いち選手としては随分久しぶりな気がします。

結果は694チーム中18位で、最終スコアは 103,838 でした。 ISUCON13 受賞チームおよび全チームスコア : ISUCON公式Blog

優勝経験のあるチームとしては満足のいく結果ではありませんが、Rubyを使ったチームの中では一番スコアが高かったようです。

上位30チームに限定すると以下となりました
Go　　 29組　96.7%
Ruby 　 1組 　 3.3%

ISUCON13 利用言語比率 : ISUCON公式Blog

この1組が我々です。

あとLINEヤフー社が提供してくださった会場に入場した順では僕が1位を取りました。

やったこと

どういう問題だったかは公式の解説にお任せしますが、我々が高速化のためにやったのはこういう感じです。

  • サーバ3台の分散
    • (1)リバースプロキシ,DNS, App (2) App, (3) App, DB
  • アイコンをファイルに書き出して Nginx で配信する
  • 権威 DNS を PowerDNS （MySQLベース）から nsd （ファイルベース）に置き換える
  • スロークエリ、N+1 クエリの解消

僕は主にボトルネックの分析と指示出し、 SQL まわりの改善をやっていました。しかし MySQL ネックが解消されたのに App の CPU リソースが余り続け、ベンチからの負荷を捌ききってしまいスコアが全く伸びないという状況に陥りました。結局打ち手がなくなってしまい、インフラ周りの微調整をこなして過ごし、そのあたりが最終スコアになってしまいました。

最終盤で気付いたのですが、DNS を nsd に置き換えた際に DNS レコード追加（ファイル書き込み）を flock を用いて直列化していたため、DNS レコード追加の発生するユーザ作成のリクエストをあまり捌けておらず、ユーザ数に応じたベンチマーカーからの負荷上昇が得られていなかったことがスコアの伸び悩みの原因だったようです。ユーザ数作成数がネックになっていたことはアクセスログの分析をしていても、他のパスと比べても特別に遅いわけでもなかったため気づきませんでした。

ボトルネックの分析

僕はチームの中では分析係をいつもやっているんですが、今回は Nginx のアクセスログを alp で分析するのと、MySQL のクエリを Performance Schema を使って分析するのをやっていました。

alp

alp は毎年お世話になっていて、

  log_format ltsv "status:$status"
    "\ttime:$time_iso8601"
    "\treqtime:$request_time"
    "\tmethod:$request_method"
    "\turi:$request_uri"
    "\tprotocol:$server_protocol"
    "\tua:$http_user_agent"
    "\tforwardedfor:$http_x_forwarded_for"
    "\thost:$remote_addr"
    "\treferer:$http_referer"
    "\tserver_name:$server_name"
    "\tvhost:$host"
    "\tsize:$body_bytes_sent"
    "\treqsize:$request_length"
    "\truntime:$upstream_http_x_runtime"
    "\tapptime:$upstream_response_time"
    "\tuid:$upstream_http_x_isu_userid"
    "\txtime:$upstream_http_x_isu_time"
    "\treqid:$upstream_http_x_isu_reqid";
  access_log /var/log/nginx/access.log ltsv;

こんな感じの LTSV で Nginx のアクセスログを出しておき、

$ alp ltsv -r --sort=sum --format=csv --file=access.log -m '/api/user/[^/]+/icon,/api/user/[^/]+/theme,/api/user/[^/]+/livestream,/api/user/[^/]+/statistics,/api/livestream/\d+$,/api/livestream/\d+/livecomment,/api/livestream/\d+/reaction,/api/livestream/\d+/report,/api/livestream/\d+/ngwords,/api/livestream/\d+/enter,/api/livestream/\d+/exit,/api/livestream/\d+/moderate,/api/livestream/\d+/statistics'

というようなオプションで実行し、スプレッドシートに貼り付けてチームに共有していました。

Performance Schema

MySQL の Performance Schema については存在は知っていたものの今回の ISUCON で初めて使いました。例年では昔ながらの slow log を pt-query-digest に入れて見ていましたが、さすがに2023年なので近代的(?)な道具を使えるようになろうと思って勉強し、以下のようなクエリを事前に用意しておいて持ち込みました。

select
  SCHEMA_NAME,
  -- DIGEST,
  DIGEST_TEXT,
  COUNT_STAR,
  round(SUM_TIMER_WAIT / pow(1000,4), 3) as SUM_TIMER_WAIT_SEC,
  round(MIN_TIMER_WAIT / pow(1000,4), 3) as MIN_TIMER_WAIT_SEC,
  round(AVG_TIMER_WAIT / pow(1000,4), 3) as AVG_TIMER_WAIT_SEC,
  round(MAX_TIMER_WAIT / pow(1000,4), 3) as MAX_TIMER_WAIT_SEC,
  round(SUM_LOCK_TIME / pow(1000,4), 3) as SUM_LOCK_TIME_SEC,
  round(QUANTILE_95 / pow(1000,4), 3) as P95,
  round(QUANTILE_99 / pow(1000,4), 3) as P99,
  round(QUANTILE_999 / pow(1000,4), 3) as P999,
  SUM_ERRORS,
  SUM_WARNINGS,
  SUM_ROWS_AFFECTED,
  SUM_ROWS_SENT,
  SUM_ROWS_EXAMINED,
  SUM_CREATED_TMP_DISK_TABLES,
  SUM_CREATED_TMP_TABLES,
  SUM_SELECT_FULL_JOIN,
  SUM_SELECT_FULL_RANGE_JOIN,
  SUM_SELECT_RANGE,
  SUM_SELECT_RANGE_CHECK,
  SUM_SELECT_SCAN,
  SUM_SORT_MERGE_PASSES,
  SUM_SORT_RANGE,
  SUM_SORT_ROWS,
  SUM_SORT_SCAN,
  SUM_NO_INDEX_USED,
  SUM_NO_GOOD_INDEX_USED,
  -- round(SUM_CPU_TIME / pow(1000,4), 3) as SUM_CPU_TIME_SEC,
  round(MAX_CONTROLLED_MEMORY / pow(1024,2), 3) as MAX_CONTROLLED_MEMORY_MB,
  round(MAX_TOTAL_MEMORY / pow(1024,2), 3) as MAX_TOTAL_MEMORY_MB,
  -- COUNT_SECONDARY,
  -- FIRST_SEEN,
  -- LAST_SEEN,
  QUERY_SAMPLE_TEXT,
  -- QUERY_SAMPLE_SEEN,
  round(QUERY_SAMPLE_TIMER_WAIT / pow(1000,4), 3) as QUERY_SAMPLE_TIMER_WAIT_SEC
from
  performance_schema.events_statements_summary_by_digest
where
  `SCHEMA_NAME` != 'performance_schema'
  AND `SCHEMA_NAME` IS NOT NULL
order by
  SUM_TIMER_WAIT desc
limit
  20

このクエリでは、実行時間の合計（SUM_TIMER_WAIT）が多い上位20件のクエリの情報をダンプしています。元々の events_statements_summary_by_digest テーブルのほぼ全カラムをそのまま出しているだけですが、時間が格納されているカラムの単位がピコ秒(!)なのが見づらかったので秒に変換しています。Performance Schema を用いた分析は pt-query-digest と比べて以下のようにメリットが多くありました。

  • 速い＆楽
    • performance_schema = ON しててもスコアに響くほどの影響はない
    • そもそもデフォルトで有効
    • 記録の初期化はテーブルを TRUNCATE するだけ
    • 特に分析ツールなどを噛まさなくても、知りたい値がそのままテーブルにまとめられていて見やすい（events_statements_summary_by_digest テーブル）
  • クエリダイジェスト（DIGEST_TEXT）と代表的な実クエリ（QUERY_SAMPLE_TEXT）の両方が見られる
    • 実クエリがあると即座に EXPLAIN に持ち込める
  • インデックスが使われてないクエリが分かる（SUM_NO_INDEX_USED）
    • 今回の問題は初期状態でほとんどインデックスが無かったが素早く対応できた
  • 遅くないけど量が多いクエリも分かる
    • slow log だと long_query_time 秒の閾値を越えたものだけを記録するので、高速かつ量が多いような N+1 クエリを見抜けない
    • 今回の問題は SELECT * FROM users WHERE id=? のようなシンプルな N+1 が大量にあったので役に立った

現代においてはマネージドな RDB （Aurora など）を使うことが一般的になっていて、パフォーマンス分析も Performance Insights のような便利 UI が用意されていますが、Performance Schema を可視化しているだけだったりするのでこういったクエリで直に叩けるようにしておくと ISUCON では便利かと思います。個人的にはインフラ領域から離れて久しいのでキャッチアップできてなかっただけで、今ではみんな当たり前に使ってるんだろうなと思ったんですが、参加者のレポートを見てると思いのほかまだ pt-query-digest が使われているようだったのであえて書きました。

感想

ISUCON といえば予選+本選方式が定番化していましたが、ここにきて一本化されました。この変更については僕は歓迎しています。出題を含む運営側を何度か経験しましたが、予選と本選の両方を作問し、運営するのは膨大な労力がかかり、持続可能とは言いづらい負担を有志で持ち回っている状態であるためです。そのような状況を見てきているため ISUCON が今年も開催された、それに万全で参加できた。それだけであまりにもありがたいことです。

Ruby について。ついに上位30チームで僕らを除いてみんな Go になってしまったとのことです。Go は速いけど Ruby は遅いから向いてないんだねというような下馬評はあるかと思いますが、僕は Ruby は遅いから不利とは思っていません。ただ、動的型付けなインタプリタ言語は不利と感じているのは正直なところです。というのも、実行しないとエラーが分からない言語であるにもかかわらず、テストは無く、かつ手元で動作確認することが困難なアプリケーション（これは今回に限らず ISUCON ではありがちですが…）であるからです。これに加えて今回はベンチマーカーが詰まっていてなかなか負荷走行が走らなかったという状況が重なりました。運営の視点ではベンチマーカーを詰まらせないというのはそれ自体が高難易度な技術課題なので、ベンチマーカーが詰まることは参加者としては予期できるトラブルであり、それで手が遅れてしまうことは今後は避けたい。次回以降も Ruby で臨むはずの我々としてはこの問題について何らかの備えをして立ち回る必要があると感じています。出題者への要望としては、手元で各エンドポイントのレスポンスをチェックできるツールを用意してもらえるとありがたいです…（参考実装の移植開発時にも欲しいやつ）。

最後に、僕個人としては今年はキャリアに大きな変化がありました。2023年1月からは執行役 CTO を降りて肩書のない一エンジニアとしてクックパッドでのキャリアを再スタートしました。この一年は CTO の6年間で開発から離れていたところから、エンジニアとしての自分を取り戻していく一年でした。まだリハビリ中というかキャッチアップ中な部分もありますが、ISUCON という自分のホームである場所にまた選手として、ここ数年で一番頭も手も動く状態で参加できたことは純粋に嬉しかったです。これからも sorah, rosylilly とワーワー言いながらベンチ回していきたい。白金動物園は ISUCON に並々ならぬ思い入れを持ってしまっている3人であるので、次回また選手として参加するのか、運営をするのかは分かりませんが、何らかの形で関わり続けたいです。僕は選手したいけど…（願望）。