SpringOnion: Railsの遅そうなEXPLAINをログ出力するgem

SpringOnionというRailsの遅そうなEXPLAINをログ出力するgemを作りました。

github.com

某kamopoさんのMySQLCasualLog.pmの移植?です。

cf. ふつうのWeb開発者のためのクエリチューニング

以前の移植とは異なって、Arproxyを必要とせず、単体で動きます。

何年前の話だよといわれそうですが、未だにスロークエリと戦っていたりするので…

Rails 3以前に搭載されていた、遅かったクエリを自動的にEXPLAINする機能とは異なり、フィルタで選別されたすべてのクエリに対してEXPLAINを実行し、まずそうなキーワードが出現したらログに出力します。

また、EXPLAINの実行先は開発用のDBだけでなく任意のDBに向けられます(例: ステージング環境のDBなど)。

使い方

GemfileにSpringOnionを追加して

group :development, :test do
  gem 'spring_onion'
end

enviroments/*.rbinitializersにSpringOnionのEXPLAIN実行先DB情報を記述します。

if Rails.env.development? || Rails.env.test?
  # EXPLAINを実行するDB
  SpringOnion.connection = Mysql2::Client.new(host: 'my-host', ...)

  # ActiveRecordの接続先と同じにする場合は↓な感じで
  #SpringOnion.connection = ActiveRecord::Base.connection.raw_connection
end

SpringOnion.enabled = trueにするかSPRING_ONION_ENABLED=1で、遅そうなEPLAINがログ出力されるようになります。

実行例

#!/usr/bin/env ruby
require 'active_record'
require 'spring_onion'

ActiveRecord::Base.establish_connection(
  adapter:  'mysql2',
  host: 'db',
  username: 'root',
  database: 'sakila'
)

SpringOnion.enabled = true # or `SPRING_ONION_ENABLED=1`
SpringOnion.connection = ActiveRecord::Base.connection.raw_connection
SpringOnion.source_filter_re = //

class Actor < ActiveRecord::Base
  self.table_name = 'actor'
  self.primary_key = 'actor_id'
end

Actor.all.to_a
root@d786c737d8a4:/mnt# bundle exec ./test.rb

SpringOnion   INFO  2020-07-19 03:19:05 +0000   {"sql":"SELECT `actor`.* FROM `actor`","explain":[{"line":1,"select_type":"SIMPLE","table":"actor","partitions":null,"type":"ALL","possible_keys":null,"key":null,"key_len":null,"ref":null,"rows":16,"filtered":100.0,"Extra":null}],"warnings":{"line 1":["slow_type"]},"backtrace":["/mnt/lib/spring_onion/explainer.rb:6:in `execute'","/mnt/test.rb:21:in `<top (required)>'"]}

SPRING_ONION_JSON_PRETTY=1で見やすく。

root@d786c737d8a4:/mnt# SPRING_ONION_JSON_PRETTY=1 bundle exec ./test.rb

SpringOnion   INFO  2020-07-19 03:19:43 +0000   {
  "sql": "SELECT `actor`.* FROM `actor`",
  "explain": [
    {
      "line": 1,
      "select_type": "SIMPLE",
      "table": "actor",
      "partitions": null,
      "type": "ALL",
      "possible_keys": null,
      "key": null,
      "key_len": null,
      "ref": null,
      "rows": 16,
      "filtered": 100.0,
      "Extra": null
    }
  ],
  "warnings": {
    "line 1": [
      "slow_type"
    ]
  },
  "backtrace": [
    "/mnt/lib/spring_onion/explainer.rb:6:in `execute'",
    "/mnt/test.rb:21:in `<top (required)>'"
  ]
}

上記の場合、"type": "ALL"が引っかかってwarningが出ています。

warning

https://github.com/winebarrel/spring_onion/blob/d659b2ca4ef2fda68a08179c9a3c8323299f604c/lib/spring_onion/config.rb#L4-L26

warningにはMySQLCasualLog.pmと同じルールを設定していますが、新しく追加することも可能です。

例えば、rowsが10,000行を超えていたら、warningするなど。

SpringOnion.warnings[:too_many_rows] = lambda do |exp|
  exp['rows'] > 10000
end

フィルタ

SQLとbacktraceのソースコードのパスでフィルタリング可能です。

たとえばSPRING_ONION_SQL_FILTER_RE=actor bundle exec ./test.rbと実行すると、actorが含まれるクエリだけEXPLAINします。

また、SPRING_ONION_SOURCE_FILTER_RE=my_path bundle exec ./test.rbと実行すると、パスにmy_pathが含まれるソースコード経由で実行されたクエリだけEXPLAINします。(デフォルトは/app/

その他

ログ出力先は標準出力がデフォルトですが、ファイルなどに変更可能です。

SpringOnion.logger = Logger.new('/foo/bar/zoo.log')