自社製 Rails アプリケーションをカスタマイズしすぎて遅くなったので、すべてのSQLを精査して何が遅いのか調べていました。その時、Rails の development mode が色々なことをやっているのがわかったので、メモしておきます。そもそも、development モードはシステムの応答速度を調べるのには向かない、というだけの話ですが…。
EXPLAIN について
PostgreSQL では、SQL の計算に際して DBMS がどのようなアルゴリズムを選択したか、各 JOIN 句にどの程度の負担があるか等を表示する EXPLAIN というコマンド（標準SQLにはない）があります。 ( https://www.postgresql.jp/document/9.1/html/using-explain.html ) 使い方は簡単で、調べたい SQL の頭に EXPLAIN とつけるだけで実行できます。しかし、これを読み解くのは難しいです。cost が増えている個所を見るくらいのことしかできませんでした。あとは、INDEX がきいているかどうか、くらいはわかるかもしれません。
Rails が自動で行う EXPLAIN について
Rails の development mode だと一定時間（デフォルトでは0.5秒）を越えた SQL に対して rails が自動的に EXPLAIN を行います。EXPLAIN には通常のSQLの数倍の時間が掛かるので、EXPLAIN の計算自体がレスポンスを悪くしていることがあります。応答速度を調べたいときには condig/environments/development.rb の下記の行をコメントアウトしておけば EXPLAIN は行われません。
config.active_record.auto_explain_threshold_in_seconds = 0.5
Rails が自動で行う奇妙な SQL について
これも Rails の development mode の話です。上記とは別に、モデルへの初回アクセスの際に奇妙な SQL が発行されていることがあります。たとえば、下のようなものです。
SELECT COUNT(*)
FROM pg_class c
LEFT JOIN pg_namespace n ON n.oid = c.relnamespace
WHERE c.relkind in ('v','r')
AND c.relname = 'users'
AND n.nspname = ANY (current_schemas(false))
SELECT a.attname, format_type(a.atttypid, a.atttypmod),
pg_get_expr(d.adbin, d.adrelid), a.attnotnull, a.atttypid, a.atttypmod
FROM pg_attribute a LEFT JOIN pg_attrdef d
ON a.attrelid = d.adrelid AND a.attnum = d.adnum
WHERE a.attrelid = '"users"'::regclass
AND a.attnum > 0 AND NOT a.attisdropped
ORDER BY a.attnum
これらは Rails が自動的に発行している SQL で、rake db:migrate が適切に行われているかを検査するためのものようです。( http://stackoverflow.com/questions/17180642/what-are-these-two-strange-queries-that-keep-running-on-every-request ) この SQL は、あらゆるモデルに対して一回ずつ発行されるため、特定の計算結果が遅くなったりすることがあります。モデルのソースコードを書き換えたりして、リロードが行われた時に呼ばれるようですが、そうではない時も呼ばれたような気がします。なので、時間を測ろうと思ってもブレが出てしまって大変でした。