画面が開かない、の正体がインデックス1本の欠落だった

データ量が数 GB しかない小さな DB だから、インデックスは多少雑でも大丈夫だろう、と思っていた。実際にはインデックス1本の欠落で、機器一覧画面の表示に4分20秒かかっていた。複合インデックスを1本足したら 513ms になった。約 500 倍である。

DB が小さいことは、インデックスを省いていい理由にならない。今回それを実測で突きつけられたので、調査から対応までを残しておく。

何が起きたか

WEBアプリのとある一覧画面が「開かない」と言われた。ロードバランサーのアクセスログに残っていたレスポンスタイムがこれ。

08-03 20:07:37   260,420 ms   (4分20秒)
08-03 20:08:40   218,350 ms
08-03 20:09:41   171,253 ms
08-04 10:33:24    61,465 ms
08-04 10:34:24    61,825 ms
08-04 10:35:49    62,691 ms
08-04 10:37:08    59,845 ms
08-04 10:38:35    60,032 ms
08-04 10:39:35    58,118 ms
08-04 10:40:36    57,215 ms
08-04 10:47:25    54,471 ms

同じ画面で1分から4分。当然ユーザーは待ちきれずリロードするので、同じ重いリクエストが積み重なってさらに遅くなっていた。

数字がばらついているのは、この画面がログインユーザーの持つ機器だけを表示する仕様で、ユーザーによって処理対象の件数が違うから。

まずスロークエリログを読む

log_min_duration_statement = 1000 を仕込んでおいたおかげで、犯人はログを開いた瞬間に見えた。

duration: 10971.128 ms  execute a33: SELECT "device_readings".* FROM "device_readings"
  WHERE "device_readings"."device_id" = $1 ORDER BY "device_readings"."time" DESC LIMIT $2
DETAIL:  parameters: $1 = '2', $2 = '1'

duration: 3465.994 ms  execute a33: SELECT ... $1 = '3'
duration: 3316.231 ms  execute a33: SELECT ... $1 = '4'
duration: 2677.863 ms  execute a33: SELECT ... $1 = '7'
（以下、一覧の件数だけ延々と続く）

最新1件を取るだけのクエリに1秒から11秒かかっている。一覧画面は件数ごとにこれを発行するので、数が積み上がって数十秒から数分になっていた。

念のため Performance Insights で負荷の内訳も見た。このクエリ1本が DB 負荷全体の 79% (0.054 / 0.068 AAS)。他は誤差レベルで、原因を1点に絞れた。

発行元のコードを追う

一覧のビューがこうなっていた。

<td><%= battery_display(device.voltage) %></td>

voltage を辿るとこう。

class Device < ApplicationRecord
  has_many :readings, class_name: "Device::Reading"
 
  def voltage
    latest_reading ? latest_reading.voltage : 0
  end
 
  def latest_reading
    readings.order(time: :desc).limit(1).first
  end
end

latest_reading が、スロークエリログに出ていたクエリそのものだった。

インデックスが1本足りていなかった

device_readings テーブルのインデックスはこれだけ。

t.index ["device_id"], name: "index_device_readings_on_device_id"

ORDER BY time DESC LIMIT 1 に効く time が入っていない。こうなると PostgreSQL は他に打つ手がない。

device_id で該当行を全部集める (1台あたり数万から数十万行)
それを time でソートする
先頭1行だけ返して、残りは捨てる

1行取るために数十万行を読んでソートしていた。これが1本あたり1秒から11秒の正体である。

なぜ見逃していたか

正直に書くと、DB 全体で 5.5 GB しかないという規模に油断していた。20 GB のボリュームに 5.5 GB。この程度ならインデックスがなくても大丈夫だろう、という感覚が普通にあった。

そしてデータが少ないうちは、実際に問題にならない。機器が増えて1台あたりの蓄積が数十万行に達したところで、ある日突然画面が開かなくなった。

直す

インデックスを1本足すだけ。

class AddDeviceIdAndTimeIndexToDeviceReadings < ActiveRecord::Migration[8.0]
  disable_ddl_transaction!
 
  def change
    add_index :device_readings, [ :device_id, :time ],
              name: "index_device_readings_on_device_id_and_time",
              algorithm: :concurrently
  end
end

(device_id, time) の複合インデックスがあれば、PostgreSQL は該当機器の位置までインデックスを降りて、time 順に並んだ末端から1行読んで終われる。ソートもいらない。

CONCURRENTLY を使った理由

普通の CREATE INDEX はテーブルに SHARE ロックを取り、作成が終わるまで INSERT/UPDATE/DELETE をブロックする。このテーブルは IoT 機器からのデータを常時受信しているので、数分間書き込みが止まればそのままデータ欠損になる。

CONCURRENTLY なら書き込みを止めずに索引を作れる。引き換えにテーブルスキャンが2回必要で全体としては遅くなるし、トランザクション内で実行できないので disable_ddl_transaction! が必須になる。今回は書き込みを止められない側の事情が圧倒的に重いので、迷う余地はなかった。

結果

08-03 20:07:37   260,420 ms   ← インデックス追加前
08-04 10:33:24    61,465 ms
   （中略）
08-04 10:47:25    54,471 ms
─────────────────────────────
08-04 12:26:48       513 ms   ← インデックス追加後

260,420 ms が 513 ms になった。約 507 倍。

事前に開発環境で同一機器に 30 万行を投入して EXPLAIN (ANALYZE) を取っていたので、効くことは分かっていた。

追加前:

Limit  (cost=8745.77..8745.88 rows=1) (actual time=13.335..14.535 rows=1)
  ->  Gather Merge
        ->  Sort  (actual time=11.975..11.975 rows=1)
              Sort Key: "time" DESC
              Sort Method: top-N heapsort  Memory: 25kB
              ->  Parallel Seq Scan on device_readings  (actual rows=100000 loops=3)
                    Filter: (device_id = 6)
Execution Time: 14.554 ms

追加後:

Limit  (cost=0.42..0.54 rows=1) (actual time=0.009..0.010 rows=1)
  ->  Index Scan Backward using index_device_readings_on_device_id_and_time
        (actual time=0.009..0.009 rows=1)
        Index Cond: (device_id = 6)
Execution Time: 0.016 ms

Seq Scan + Sort が Index Scan Backward に変わって、14.5 ms が 0.016 ms。約 900 倍。本番の行数だとこれが秒からミリ秒になる。

反省

効くのはテーブルの総量ではなく、1クエリが触る行数だった。総量 5.5 GB でも、1台に数十万行あればその数十万行を毎回読む。行数の多いテーブルには、DB が小さくてもインデックスが必要になる。逆に言えば、小さい DB のほうが油断しやすいぶん危なかったということでもある。

もうひとつ、スロークエリログを最初から入れておいてよかった。log_min_duration_statement = 1000 があったので調査は実質ログを読むだけで終わった。これがなければアプリ側の計測から始めることになって、原因特定に何倍も時間がかかっていたはず。

ただ、インデックスを足せば足すだけ良いという話でもない。書き込みのたびに索引更新が走るし、ディスクも食う。今回は「最新1件を取る」という頻繁かつ明確なアクセスパターンがあったから迷わず追加した。説明できるアクセスパターンがあるインデックスだけを足す、という線は守りたい。

ついでに見つかったストレージの I/O 上限

調査中に、この RDS が gp2 20 GB、つまりベースライン 100 IOPS で動いていることも分かった。gp2 は 3 IOPS/GB (最小 100) で、超えた分はバーストクレジットを食う。

一覧画面を1回開いたときの実測がこれ。

UTC     Read IOPS   BurstBalance
01:30         896            95%
01:35       2,614            83%   ← バースト上限 3,000 の 87%
01:40       1,244            77%
01:45         664            75%

画面を1回開くだけでボリュームの性能上限をほぼ使い切り、15 分で I/O クレジットを 99% から 75% まで削っていた。100 IOPS のベースラインだと回復に数時間かかる。

インデックスがないせいの過剰な読み込みが、ストレージ性能の限界とぶつかって症状を増幅していた形になる。ここもあわせて gp2 から gp3 に変えた (20 GB でもベースライン 3,000 IOPS で、クレジットという概念自体がなくなる。GB 単価も gp2 より安い)。ダウンタイムなしのオンライン変更で、RDS 側の反映は1分半で終わった。

とはいえこれは根本原因ではない。遅いクエリをハードウェアで殴っても、遅いクエリは遅いままである。