activerecord-causeを詠む

activerecord-cause?

github.com

ActiveRecordの読み込みが実際にトリガーされた場所をログに記録するgem

ActiveRecordは必要になるまでDB読み込みをしません。 なのでやたら複雑なビューの中でクエリを弄ったり、コントローラーが肥大化してる状態でひどいSQLがログに流れてくると、パっと見ではどこが原因なのかすぐに分からない。 なので、SQLが実行された時にそれが実際にトリガーされたソースコードの位置も一緒にログに吐いてくれるgemを作りました。

対象

class TopController < ApplicationController
  def home
    rnd = rand(1..100)
    User.create(name:"hoge#{rnd}", age: rnd)
  end
end

Rails起動後、http://localhost:3000/top/homeにアクセスしてみる

導入前

f:id:taiki44no:20180430210805p:plain

導入後

f:id:taiki44no:20180430210817p:plain

以下の一文から、top_controllerのhomeメソッドのところだとわかる。 また、色が統一されているためログを追いかけるのが楽ちんになる。

User Create (ActiveRecord::Cause)  caused by /home/chamao/gem_test/activerecord_cause_test/app/controllers/top_controller.rb:4:in `home'

LogSubscriberを試しに作ってみる

以下のコードは下記の記事より引用しています。 (この記事、すごくわかりやすです!!)

Railsの計測を支えるActiveSupport::Notificationsについて

class SampleScriber < ActiveSupport::Subscriber
  def output(event)
    payload = event.payload
    puts "#{payload[:name]} 処理時間: #{event.duration}ms"
  end
end

# output.sampleを購読する
SampleScriber.attach_to :sample

# output.sampleを計測する
ActiveSupport::Notifications.instrument('output.sample', name: 'aaa') do
  sleep(0.1)
end

# output.sampleを計測する
ActiveSupport::Notifications.instrument('output.sample', name: 'bbb') do
  sleep(0.2)
end

# output.exampleを計測する
ActiveSupport::Notifications.instrument('output.example', name: 'ccc') do
  sleep(0.3)
end

出力結果は以下のようになります。

aaa 処理時間: 100.493189ms
bbb 処理時間: 200.373107ms

大まかに流れとしては、

1: ActiveSupport::Subscriberを継承したclassを定義する

2: 購読する(attach_to)

3: ActiveSupport::Notificationsが購読されたSubscriberたちを計測する

4: 計測されるとSubscriberたちに連絡が行く。

activerecord-causeのLogSubscriberを見てみる

ポイントとしては、

1:ActiveSupport::Subscriberを継承したclassを定義する ActiveRecordのSubscriberはActiveRecord::LogSubscriberでログ出力に特化したクラスを利用している

2:購読する(attach_to) ActiveRecord::Cause::LogSubscriberAR515.attach_to :active_record

3:ActiveSupport::Notificationsが購読されたSubscriberたちを計測する

4:計測されるとSubscriberたちに連絡が行く。

名前空間active_recordで購読しているのでSQL実行(sql.active_record)が計測された時に通知されます。

activerecord-causeのLogSubscriberを見てみましょう。

    # override: http://api.rubyonrails.org/classes/ActiveSupport/LogSubscriber.html
    class LogSubscriber < ActiveRecord::LogSubscriber
      IGNORE_PAYLOAD_NAMES = ["SCHEMA", "EXPLAIN"]

      def sql(event)
        return unless logger.debug?

        # eventにはモデルのスキーマを読み込む作業も流れる。
        # IGNORE_PAYLOAD_NAMESの時はログを履かないようにしている。

        payload = event.payload
        return if IGNORE_PAYLOAD_NAMES.include?(payload[:name])

        # get_locationメソッドでは”Kernel#caller_locations”を使って指定したパスを含むeventを選別する
        # Kernel: https://docs.ruby-lang.org/ja/latest/class/Kernel.html#M_CALLER_LOCATIONS        
        locations = get_locations

        return if locations.empty?

        if ActiveRecord::Cause.log_mode != :all
          locations = locations.take(1)
        end

        locations.each do |loc|
          @is_odd = nil
          
          unless (payload[:binds] || []).empty?
            binds = get_binds(payload)
          end

          name = name_with_color(payload[:name])
          sql = sql_with_color(payload[:sql])
          cause = color(loc.to_s, nil, true)

          output =
            if ActiveRecord::Cause.log_with_sql
              "  #{name}  #{sql}#{binds} caused by #{cause}"
            else
              "  #{name}  caused by #{cause}"
            end

          debug(output)
        end
      end

      private

      def is_odd?
        return @is_odd unless @is_odd.nil?
        @is_odd = odd?
      end

      def get_locations
        return [] if ActiveRecord::Cause.match_paths.empty?
        caller_locations.select do |l|
          ActiveRecord::Cause.match_paths.any? do |re|
            re.match(l.absolute_path)
          end
        end
      end

      # attach_toが上手くイカなければエラーを吐く?
      # この部分については下で少し詳しくあつかう
      def get_binds(payload)
        raise NotImplementedError
      end

      def name_with_color(payload_name)
        raise NotImplementedError
      end

      def sql_with_color(payload_sql)
        raise NotImplementedError
      end
    end

バージョンが見つからない場合エラーを吐かせる

上記のコードの最期のところ、ここの部分はよくわからなかったです。

module ActiveRecord
  module Cause

    class LogSubscriber < ActiveRecord::LogSubscriber
      def get_binds(payload)
        raise NotImplementedError 
      end

      def name_with_color(payload_name)
        raise NotImplementedError
      end

      def sql_with_color(payload_sql)
        raise NotImplementedError
      end
   end

   class LogSubscriberAR4 < ActiveRecord::Cause::LogSubscriber
      def sql(event)
      end

      private

      def get_binds(payload)
      end

      def name_with_color(payload_name)
      end

      def sql_with_color(payload_sql)
      end
    end

    #----------------省略----------------------
 end
end

この下に以下のように続きます。

ActiveSupport.on_load(:active_record) do
  if ActiveRecord.version >= Gem::Version.new("5.1.5")
    ActiveRecord::Cause::LogSubscriberAR515.attach_to :active_record
  elsif ActiveRecord.version >= Gem::Version.new("5.0.3")
    ActiveRecord::Cause::LogSubscriberAR503.attach_to :active_record
  elsif ActiveRecord.version >= Gem::Version.new("5.0.0")
    ActiveRecord::Cause::LogSubscriberAR502.attach_to :active_record
  else
    ActiveRecord::Cause::LogSubscriberAR4.attach_to :active_record
  end
end

バージョンの継承が対応していない時にエラー処理を行うという意図ならわかりますが、elseでどのバージョンの時も 拾ってしまうのでraise NotImplementedError部分はいらないのではないかと、個人的には思ってしまいます。 他に何か意図があるのだろうか。。。?

※(追記) コミットログを遡ってみました。

https://github.com/joker1007/activerecord-cause/commit/2ea48d4a67705fb7c89851a20283858d12ade76d

最初からこの部分は意図的に設計されているようです。 わからん。

将来的に新しいバージョンが登場した場合、新しいクラスでそのメソッドが不要になるシチュエーションもあったっりする。

そうしたケースを考えると、このようにバージョンによって異なるメソッドは、activerecord-causeが行ったようにすることで、拡張性と柔軟性を与えるのかもしれない。たぶん。

バージョンの継承が対応していない時にエラー処理を行う例を見てみます。

module Test
  class HogeVer0
    def basic_method
      puts "このメソッドはversionに関係なく呼び出せます"
    end

    def special_method
      raise "VERSIONが正しくありません"
    end
  end

  class HogeVer1 < HogeVer0
    def special_method
      puts "form ONE!!"
    end
  end

  class HogeVer2 < HogeVer0
    def special_method
      puts "form TWO!!"
    end
  end
end

def set_test_obj(version)
  case version
  when 1
    Test::HogeVer1.new
  when 2
    Test::HogeVer2.new
  else
    Test::HogeVer0.new
  end
end

実行結果はこんな感じ。

obj = set_test_obj(0)
obj.basic_method          #=> このメソッドはversionに関係なく呼び出せます
#obj.special_method       #=> VERSIONが正しくありません (RuntimeError)

obj = set_test_obj(1)
obj.special_method        #=> form ONE!!

obj = set_test_obj(2)
obj.special_method        #=> form Two!!