先月初めてISUCONに参加した

blog.kromiii.info

結果は、最終2900点と自分としては悔いの残る結果になった

年末年始で時間があったので、せっかくなのでISUCONの記憶が残っているうちに、できなかったことを復習しようと思った次第

2025/01/03現在、ISUCON14は感想戦モードが公開されていて、ベンチマーカーもそのまま残っているので、CloudFormationのスタックを作り直すだけですぐに本番と同じ環境を構築することができる

isucon.net

上位入賞チームはGo言語を使っているチームが多かったみたいだが、今回は復習ということで言語は変えずそのままRubyでやってみる

目標は大きく10000点とした

1. indexの追加
2. /api/owner/chairsの改善
3. nearby-chairsのN+1解消
4. chair_locations のバルクインサート化
5. 最新の位置情報と総走行距離を持つテーブルを作成
7. notification の retry_after_ms の延長
8. マッチングアルゴリズムの改良
最後に

1. indexの追加

まずは解説で言われている通りにindexを追加

なんとこれだけで2500点前後まで点数が上がった

ちなみにRubyの初期実装は650点前後である

indexを貼る作業も結構奥が深いので、本番でパッとできるかと言われると微妙だが、それでもこんな少数のコードの変更だけで当日の８割くらいのスコアが取れてしまうのが悔やまれた

とはいえ処理としてはまだMySQLが支配的だったのでこの時点でのスロークエリログを見てみる

当日はDatadogを使ったのだが、今回はISUCON本で紹介されていた query-digester を使ってみてみた

query-digesterをインストールする都合上、MySQLのmax connection を 500 まで増やしたら、実はもうこの時点でスコアが3000点を超えてしまった

この時点で本番の自分達の得点を超えてしまったのだからなんとも・・・

# Rank Query ID                      Response time  Calls R/Call V/M   Ite
# ==== ============================= ============== ===== ====== ===== ===
#    1 0x25D034CF58223D3C04329256... 197.9241 61.0%    87 2.2750  0.06 SELECT chairs chair_locations
#    2 0xFFFCA4D67EA0A788813031B8...  60.3413 18.6% 22433 0.0027  0.01 COMMIT
#    3 0xDCA6B16A0FC65C799EB401CB...  11.8716  3.7% 22826 0.0005  0.00 SELECT ride_statuses
#    4 0xD8DAD8AC6EDE2238F17AC39B...   8.5779  2.6% 19702 0.0004  0.00 SELECT rides
#    5 0x49D4717E21912CD8B13961B8...   5.6343  1.7% 19823 0.0003  0.00 SELECT chairs
#    6 0x780A355BC10F6DC5B57B4BBC...   5.0454  1.6%  8636 0.0006  0.00 SELECT ride_statuses

ランキングを見ると SELECT chairs chair_locations がボトルネックになっていそうだったのでここに手を入れることを考える

クエリの中身はこんな感じ

SELECT id,
owner_id,
name,
access_token,
model,
is_active,
created_at,
updated_at,
IFNULL(total_distance, 0) AS total_distance,
total_distance_updated_at
FROM chairs
LEFT JOIN (SELECT chair_id,
                   SUM(IFNULL(distance, 0)) AS total_distance,
                   MAX(created_at)          AS total_distance_updated_at
            FROM (SELECT chair_id,
                         created_at,
                         ABS(latitude - LAG(latitude) OVER (PARTITION BY chair_id ORDER BY created_at)) +
                         ABS(longitude - LAG(longitude) OVER (PARTITION BY chair_id ORDER BY created_at)) AS distance
                  FROM chair_locations) tmp
            GROUP BY chair_id) distance_table ON distance_table.chair_id = chairs.id
WHERE owner_id = '01JGD868V7D8QDP0VPM309RK6Y'\G

owner_handler.rb に当該のクエリを見つけたのでこれを修正していく

2. /api/owner/chairsの改善

chairs テーブルを確認すると index が access token にしか貼られていなかった

mysql> show index from chairs;
+--------+------------+-------------------------+--------------+--------------+-----------+-------------+----------+--------+------+------------+---------+---------------+---------+------------+
| Table  | Non_unique | Key_name                | Seq_in_index | Column_name  | Collation | Cardinality | Sub_part | Packed | Null | Index_type | Comment | Index_comment | Visible | Expression |
+--------+------------+-------------------------+--------------+--------------+-----------+-------------+----------+--------+------+------------+---------+---------------+---------+------------+
| chairs |          0 | PRIMARY                 |            1 | id           | A         |         500 |     NULL |   NULL |      | BTREE      |         |               | YES     | NULL       |
| chairs |          1 | idx_chairs_access_token |            1 | access_token | A         |         500 |     NULL |   NULL |      | BTREE      |         |               | YES     | NULL       |
+--------+------------+-------------------------+--------------+--------------+-----------+-------------+----------+--------+------+------------+---------+---------------+---------+------------+
2 rows in set (0.01 sec)

なんとなくこれは不味そうなので、先ほどのクエリを参考にindexを追加してみる

CREATE INDEX idx_chairs_owner_id ON chairs (owner_id);

が、結果はあまり変わらず

公式の解説にWITH句を使ったクエリの改善例が載っていたのでそれを試すことにした

すると以下のようにランキングが入れ替わったことを確認

# Rank Query ID                      Response time Calls R/Call V/M   Item
# ==== ============================= ============= ===== ====== ===== ====
#    1 0xFFFCA4D67EA0A788813031B8... 85.0896 48.4% 30235 0.0028  0.01 COMMIT
#    2 0xDCA6B16A0FC65C799EB401CB... 14.0101  8.0% 30699 0.0005  0.00 SELECT ride_statuses
#    3 0x4EA5EE3239EBB857C00E5CF2... 10.8239  6.2%   166 0.0652  0.03 SELECT chairs filtered_chairs chairs chair_locations filtered_chairs
#    4 0xD8DAD8AC6EDE2238F17AC39B...  9.9662  5.7% 24224 0.0004  0.00 SELECT rides
#    5 0x49D4717E21912CD8B13961B8...  7.3529  4.2% 24353 0.0003  0.00 SELECT chairs
#    6 0x780A355BC10F6DC5B57B4BBC...  5.4599  3.1% 11034 0.0005  0.00 SELECT ride_statuses

得点も3600点まで上がった

3. nearby-chairsのN+1解消

というわけで次は二番目に上がってきた ride_statuses についてみてみる

クエリの中身としては

SELECT status FROM ride_statuses WHERE ride_id = '01JGDZKRKV42N7WBWQ014TVHW4' ORDER BY created_at DESC LIMIT 1

というシンプルなものだが、いかんせん量が多い

おそらくN+1っぽい何かだろうと思いつつ解説を見ると /app/nearby-chairs にN+1があるっぽいので直してみる

解説にはGoの実装しかなかったが、見よう見まねでRubyに移植してみることにした

nearby_chairs = db.xquery(<<~SQL, latitude, longitude, distance)
        WITH near_chairs AS (
          SELECT cl.*
          FROM (
              SELECT cl.*, row_number() over (partition BY chair_id ORDER BY created_at DESC) AS rn
              FROM chair_locations cl
          ) cl
          WHERE cl.rn = 1 AND abs(cl.latitude - ?) + abs(cl.longitude - ?) < ?
        )
        SELECT
          chairs.*, near_chairs.latitude, near_chairs.longitude
        FROM 
          chairs
        INNER JOIN near_chairs ON chairs.id = near_chairs.chair_id
        LEFT JOIN rides ON chairs.id = rides.chair_id AND rides.evaluation IS NULL
        WHERE
          rides.id IS NULL AND chairs.is_active
      SQL

      json(
        chairs: nearby_chairs.map do |chair|
          {
            id: chair.fetch(:id),
            name: chair.fetch(:name),
            model: chair.fetch(:model),
            current_coordinate: {
              latitude: chair.fetch(:latitude),
              longitude: chair.fetch(:longitude),
            },
          }
        end,
        retrieved_at: time_msec(Time.now),
      )

N+1は解消されたが、代わりにこのクエリがスロークエリになってしまった（上から二番目のクエリ）

# Rank Query ID                      Response time Calls R/Call V/M   Item
# ==== ============================= ============= ===== ====== ===== ====
#    1 0xFFFCA4D67EA0A788813031B8... 69.8668 31.9% 25789 0.0027  0.01 COMMIT
#    2 0x73A3BC6FCC36E8F102A1C78C... 62.4398 28.5%    89 0.7016  0.11 SELECT chair_locations chairs near_chairs rides
#    3 0xDCA6B16A0FC65C799EB401CB... 13.1224  6.0% 24849 0.0005  0.00 SELECT ride_statuses
#    4 0x4EA5EE3239EBB857C00E5CF2... 11.7018  5.4%   166 0.0705  0.04 SELECT chairs filtered_chairs chairs chair_locations filtered_chairs
#    5 0xD8DAD8AC6EDE2238F17AC39B...  9.8566  4.5% 21368 0.0005  0.00 SELECT rides
#    6 0x49D4717E21912CD8B13961B8...  6.8888  3.1% 21489 0.0003  0.00 SELECT chairs

結果的に点数はあまり変わらず

が、ここは abs 関数と row_number 関数が足を引っ張っていると予想

ここは後続の修正で解決できるのではということでそのまま次へ進む

4. chair_locations のバルクインサート化

さて、query-digesterの結果を見てもやはりトランザクション（COMMIT）の数が多い

トランザクションの中でも一番多いのが POST /api/chair/coordinate で実行される chair_locations テーブルへの INSERT だろうと予想してこれをバルクインサート化してみる

データを溜めておくための場所としてredisを新しくインストールし、こんな感じのThreadをinitial_handler.rbに追加してみた

     Thread.new do
        loop do
          begin
            keys = redis.keys('chair_location:*')
            values = keys.map do |key|
              data = JSON.parse(redis.get(key), symbolize_names: true)
              [key.split(':').last, data[:chair_id], data[:latitude], data[:longitude]]
            end
            unless values.empty?
              placeholders = values.map { |_| "(?, ?, ?, ?)" }.join(", ")
              db.xquery("INSERT INTO chair_locations (id, chair_id, latitude, longitude) VALUES #{placeholders}", *values.flatten)
              keys.each { |key| redis.del(key) }
            end
          rescue => e
            puts "Error processing Redis data: #{e.message}"
          end
        end
      end

実はこの発想は当日ISUCONに参加していた時もあったのだが、非同期でレコードをINSERTする実装に自分が慣れていないこともあって、redisやsidekiqを使って右往左往しているうちに時間切れになってしまった部分だ

実際やってみると redis はおそらく使ったほうが良いが、sidekiqは不要で、組み込みのThread classを使うだけで十分っぽかった

これだけでも COMMIT の負荷を大きく減らすことができた（COMMITのRANKが五番目に下がっている）

# Rank Query ID                      Response time  Calls R/Call V/M   Ite
# ==== ============================= ============== ===== ====== ===== ===
#    1 0x73A3BC6FCC36E8F102A1C78C... 117.8011 54.8%    83 1.4193  0.22 SELECT chair_locations chairs near_chairs rides
#    2 0x4EA5EE3239EBB857C00E5CF2...  18.1900  8.5%   166 0.1096  0.07 SELECT chairs filtered_chairs chairs chair_locations filtered_chairs
#    3 0xDCA6B16A0FC65C799EB401CB...  13.4123  6.2% 24870 0.0005  0.00 SELECT ride_statuses
#    4 0xD8DAD8AC6EDE2238F17AC39B...   9.5144  4.4% 22607 0.0004  0.00 SELECT rides
#    5 0xFFFCA4D67EA0A788813031B8...   7.9929  3.7% 25745 0.0003  0.01 COMMIT
#    6 0x49D4717E21912CD8B13961B8...   6.9535  3.2% 22716 0.0003  0.00 SELECT chairs

とはいえこのあたりから

time=18:05:31.291 level=WARN msg="取得したオーナーの椅子一覧の情報が想定しているものと異なります (CODE=26): total_distanceが一致しないデータがあります (id: 01JGGHS1CASK8WQ9JSTDHHTCKG, got: 258, want: 136)"

というエラーが頻発するようになってしまった

想定よりも足りないならわかるが、想定よりも上回っているのはなぜ？と不思議だったがベンチマーカーの実装を見てみると chair_location_created_at が影響を与えていそうだった（ベンチマーカーの実装を直に見れるのも感想戦のいいところ）

横着してレスポンスに Time.now を使っていたところを以下のように変更して解決

{ recorded_at: time_msec(chair_location_created_at) }

他には

msg="付近の椅子情報が想定よりも足りていません (CODE=31): 不足数1台"

というエラーもちょこちょこ出てきたが、これは解説で以下のように述べられていた

ドキュメントでこのエンドポイントで返される椅子の座標は過去3秒以内に送られた POST /api/chair/coordinateであれば良いという記述がありますが、猶予されるのは位置情報のみで椅子が割り当て可能かは即時に反映される必要があったためサクッとレスポンス全体を3秒キャッシュみたいなことはできない様になっていたと思います。

ちょい気になるがクリティカルなものではないと受け入れて次へ

5. 最新の位置情報と総走行距離を持つテーブルを作成

最後まで残っているスロークエリとして /nearby-chairs で使われているnear-charisというクエリがあった

WITH near_chairs AS (
    SELECT cl.*
    FROM (
        SELECT cl.*, row_number() over (partition BY chair_id ORDER BY created_at DESC) AS rn
        FROM chair_locations cl
    ) cl
    WHERE cl.rn = 1 AND abs(cl.latitude - ?) + abs(cl.longitude - ?) < ?
 ),

これは公式の解説に書いてある通り、chair ごとの最新の座標を保存するテーブルを追加することによって改善できそうだ

というわけでサクッと作ってみる

DROP TABLE IF EXISTS latest_chair_locations;
CREATE TABLE latest_chair_locations
(
  chair_id   VARCHAR(26) NOT NULL COMMENT '椅子ID',
  latitude   INTEGER     NOT NULL COMMENT '経度',
  longitude  INTEGER     NOT NULL COMMENT '緯度',
  total_distance INTEGER NOT NULL COMMENT '移動距離',
  created_at DATETIME(6) NOT NULL DEFAULT CURRENT_TIMESTAMP(6) COMMENT '登録日時',
  updated_at DATETIME(6) NOT NULL DEFAULT CURRENT_TIMESTAMP(6) ON UPDATE CURRENT_TIMESTAMP(6) COMMENT '更新日時',
  PRIMARY KEY (chair_id)
)
  COMMENT = '最新の椅子の位置情報を表すテーブル';

これに合わせて app_handler, owner_handler の実装も変えてみる

さらっと言ってしまったが、ここが一番苦労したポイントで、というのも普段 Rails には慣れているが、Rubyで直にSQLを書いてその結果をウンタラカンタラ、というのはほぼ初めてだったのでどうやって書いたらいいのか全く検討がつかなかった

ベンチマーカーで何度も0点を出しながらも、やっとこさまともに動くコードができた

nearby_chairs = db.xquery(<<~SQL, latitude, longitude, distance)
        WITH near_chairs AS (
          SELECT cl.*
          FROM latest_chair_locations AS cl
          WHERE abs(cl.latitude - ?) + abs(cl.longitude - ?) < ?
        )
        SELECT
          chairs.*, near_chairs.latitude, near_chairs.longitude
        FROM 
          chairs
        INNER JOIN near_chairs ON chairs.id = near_chairs.chair_id
        LEFT JOIN rides ON chairs.id = rides.chair_id AND rides.evaluation IS NULL
        WHERE
          rides.id IS NULL AND chairs.is_active
      SQL

当然ながら chair_locations を非同期で更新する部分も latest_chair_locations に置き換えている

スロークエリをみると圧倒的１位だった app/nearby-chair のクエリがランキング圏外まで下がっていることが確認できた

# Rank Query ID                      Response time Calls R/Call V/M   Item
# ==== ============================= ============= ===== ====== ===== ====
#    1 0x4EA5EE3239EBB857C00E5CF2... 20.4746 17.7%   166 0.1233  0.07 SELECT chairs filtered_chairs chairs chair_locations filtered_chairs
#    2 0xDCA6B16A0FC65C799EB401CB... 13.9158 12.1% 26396 0.0005  0.00 SELECT ride_statuses
#    3 0xD8DAD8AC6EDE2238F17AC39B... 10.1616  8.8% 23234 0.0004  0.00 SELECT rides
#    4 0xFFFCA4D67EA0A788813031B8...  9.2289  8.0% 27364 0.0003  0.01 COMMIT
#    5 0xCC151F3B2CCD22AC3599F5F8...  8.4928  7.4%   955 0.0089  0.00 UPDATE latest_chair_locations
#    6 0x49D4717E21912CD8B13961B8...  7.7532  6.7% 23357 0.0003  0.00 SELECT chairs

とはいえスコアは思ったより伸びない

ということでここからスロークエリの改善以外のこともやっていくことにした（この時点ですでに復習を始めてから3日経過）

7. notification の retry_after_ms の延長

公式の解説でもここがボトルネックになっていると書いてあったので、雑に１０倍にしてみた

if ride.nil?
          halt json(data: nil, retry_after_ms: 300)
        end

なんとこれだけでスコアが6000点を超えた

topコマンドでベンチマーク中のプロセスを見ても明らかにMySQLの負荷が減っているのが確認できた

とはいえ、これは当日自分たちがやった時はせいぜい3000点止まりだったので、これまでの地道なスロークエリの改善があってのスコアだと思う

8. マッチングアルゴリズムの改良

公式の解説を参考に、マッチングアルゴリズムを改良してみる

Rubyの実装は見当たらなかったが、雑にこんな感じでマッチングするように変えてみた

# frozen_string_literal: true

require 'isuride/base_handler'

module Isuride
  class InternalHandler < BaseHandler
    get '/matching' do
      db_transaction do |tx|
        # 未マッチのライドを待ち時間順で取得
        rides = tx.query('SELECT * FROM rides WHERE chair_id IS NULL ORDER BY created_at')
        unless rides
          halt 204
        end

        # アクティブな椅子の最新位置情報を取得
        chairs = tx.query(<<~SQL)
          WITH chair_latest_status AS (
              SELECT
                  r.*,
                  rs.status AS ride_status,
                  ROW_NUMBER() OVER (PARTITION BY r.chair_id ORDER BY rs.created_at DESC) AS rn
              FROM rides r
              INNER JOIN ride_statuses rs ON r.id = rs.ride_id AND rs.chair_sent_at IS NOT NULL
          )
          SELECT
              c.id,
              c.is_active,
              COALESCE(l.latitude, 0) AS latitude,
              COALESCE(l.longitude, 0) AS longitude
          FROM chairs c
          LEFT JOIN chair_latest_status cls ON c.id = cls.chair_id AND cls.rn = 1
          LEFT JOIN latest_chair_locations l ON c.id = l.chair_id
          WHERE (cls.ride_status = 'COMPLETED' OR cls.ride_status IS NULL) AND c.is_active
        SQL

        # chairsを配列に変換
        chairs = chairs.map do |chair|
          {
            id: chair.fetch(:id),
            latitude: chair.fetch(:latitude),
            longitude: chair.fetch(:longitude),
          }
        end

        rides.each do |ride|
          # 最も近い椅子を見つける
          closest_chair = chairs.min_by do |chair|
            calculate_distance(
              chair[:latitude], chair[:longitude],
              ride.fetch(:pickup_latitude), ride.fetch(:pickup_longitude)
            )
          end

          if closest_chair
            # 距離が400以上であればマッチングをスキップする
            if calculate_distance(
              closest_chair[:latitude], closest_chair[:longitude],
              ride.fetch(:pickup_latitude), ride.fetch(:pickup_longitude)
            ) > 400
              next
            end
            tx.xquery('UPDATE rides SET chair_id = ? WHERE id = ?', 
                     closest_chair[:id], ride.fetch(:id))
            # 使用した椅子を除外
            chairs.delete(closest_chair)
          end
        end
      end

      204
    end
  end
end

ただし、これによって処理が重くなってしまい、matchingが二重に走ってしまうことがあったため env.sh を変更してマッチング間隔を500msから1sに延長した

# マッチング間隔（秒）
ISUCON_MATCHING_INTERVAL=1

そして・・・

5日目にして点数がついに10000点を超えた！

表面だけ見るとマッチングアルゴリズムの改良が一番クリティカルに効いた感じだが、何度もいうようにこれまでの地道なスロークエリの改善があってこその飛躍だと思っている

Idempotency-Key やスロークエリの改善の余地はまだまだありそうだが、目標の10000点を達成したのでいったんここで筆を置きたいと思う

他の人の参考になるかもと思ってここまでのRuby実装のソースコードを公開しておいた

github.com

最後に

というわけで12月30日から初めておよそ5日間にわたる自分とISUCONとの戦いが終わった

当日もやり切ったという達成感はあったが、これで本当に自分にとってのISUCON14が終わった感がある

最後に、感想というか思ったことをいくつか

パフォーマンス改善=スコア上昇ではない。スコアが変わらなくても地道にスロークエリの改善を続けることも大事。この積み重ねが最後のスコアの伸びに生きてくる。
計測基盤の構築に時間をかけすぎず、手を動かす時間をしっかり取ること。自分にとっては kazeburoさんの query-digester が必要十分だった。
自分が慣れているのは Ruby on Rails ではあってRubyではない。RailsのないRubyはもはや別物なので、業務で使っているからと安易にRubyを選択せず、次回からはPythonやNode.jsを選んでもいいかもしれない。

いずれにしても、ゆっくりと時間をかけて考えるのが好きな自分にとっては感想戦は本番と同じくらい楽しかった

次回は本番で１万点、感想戦で１０万点を目指したい

P.S.

改めて、本番を終えてなおこれだけ夢中になれるゲームを企画してくださった（そして今も感想戦モードを開放してくれている）運営の方ありがとうございます

くろみーの日報テンプレ

日常のつぶやき

【ISUCON14感想戦】Ruby実装で10000点をとる