超長クエリでのRegexp::TimeoutErrorを防ぐ`sql_color`の正規表現最適化

2026年03月31日 18:46 JST rails/rails

https://github.com/rails/rails/pull/57105

ActiveRecord::LogSubscriber#sql_colorの正規表現を先頭ワード抽出方式に変更し、極端に長いSQLクエリでもRegexp::TimeoutErrorが発生しないようにしました。これにより、大量データの一括INSERT等で発生していた「クエリがログに残らない」問題が解消されます。

背景

sql_colorの旧実装は非アンカー正規表現を含んでおり、極端に長いSQLに対してタイムアウトを引き起こす可能性がありました。#57092で報告されたように、"select " + 'a' * 1000を10万回繰り返した96MBのSQLに対して、正規表現の評価だけで約3.3秒かかるケースが確認されています。

RailsはデフォルトでRegexp.timeout = 1を設定しているため、この遅延はRegexp::TimeoutErrorに発展します。このエラーはインストゥルメンテーション層でキャッチされ、対象クエリはログに一切残らず、代わりに以下のエラーのみが記録されます。

Could not log "sql.active_record" event. Regexp::TimeoutError: regexp match timeout

大容量テキストやバイナリデータを一括挿入するユースケースでは、デバッグが困難になる実害があることがIssueで指摘されています。

技術的な変更

sql_colorの実装を、文字列全体に対する正規表現マッチングから、先頭ワードを1回だけ抽出する方式に刷新しました。

変更前:

def sql_color(sql)
  case sql
  when /\A\s*rollback/mi
    RED
  when /select .*for update/mi, /\A\s*lock/mi
    WHITE
  when /\A\s*select/i
    BLUE
  when /\A\s*insert/i
    GREEN
  when /\A\s*update/i
    YELLOW
  when /\A\s*delete/i
    RED
  when /transaction\s*\Z/i
    CYAN
  else
    MAGENTA
  end
end

変更後:

def sql_color(sql)
  color = if (match = sql.match(/\A\s*(\w+)(?:\s|\Z)/))
    case match[1].downcase
    when "rollback"
      RED
    when "lock"
      WHITE
    when "select"
      if sql.match?(/for update/mi)
        WHITE
      else
        BLUE
      end
    when "insert"
      GREEN
    when "update"
      YELLOW
    when "delete"
      RED
    end
  end

  if color
    color
  else
    if sql.match?(/transaction\s*\Z/i)
      CYAN
    else
      MAGENTA
    end
  end
end

旧実装ではcase/whenの各節がSQLの全文に対してパターンマッチングを試みていました。特に/select .*for update/miはドット.が何にでもマッチするため、長い文字列では線形以上のバックトラックが発生するリスクがあります。また/transaction\s*\Z/iの\Zアンカーも文字列末尾への到達が必要で、長い文字列では評価コストが高くなります。

新実装では、まず/\A\s*(\w+)(?:\s|\Z)/で先頭ワードのみを抽出します。このパターンは文字列の先頭に固定されているため、SQLの長さに依存しません。for updateの検出はSELECTに絞った場合のみ実行され、transactionの末尾検索もMAGENTA（デフォルト色）のフォールバックパスにのみ残っています。

テスト側では、SQL_COLORINGSのループを1つのメソッド内に持つ構造から、動的に生成された個別テストメソッドに変更されています。

SQL_COLORINGS.each do |verb, color_regex|
  test "basic_query_logging_coloration_#{verb}" do
    # ...
  end
end

これにより、カラーリングの検証が動詞ごとに独立したテストケースとして実行されるようになり、失敗箇所の特定が容易になります。

設計判断

問題の根本をフォールバックではなく正規表現の計算量削減で解決する方針が採用されました。

#57102では、Regexp::TimeoutErrorをrescueして未着色のSQLをフォールバックとしてログする案が提案されていました。このPRはクローズされ、代わりに本PRのアプローチが採用されています。フォールバック方式ではタイムアウトが発生した際に着色なしでログされるため、根本原因が残り続ける点が課題でした。

先頭ワード抽出方式は、/\A/アンカーにより評価範囲を文字列先頭に限定し、SQLの長さに対して実質的に定数時間で動作します。for updateとtransactionのパターンは依然として非アンカーですが、前者はSELECT確定後のみ、後者はデフォルト色決定時のみ評価されるため、問題が顕在化する状況は大幅に限定されます。

まとめ

SQLの先頭ワードのみで色を決定するという単純な設計変更により、クエリ長に依存しない安定したログ着色が実現されました。Regexp.timeoutというRailsのグローバル設定がロギング自体を阻害するという微妙なインタラクションを、正規表現の計算量削減によって根本から断ち切った変更といえます。