newrelic_rpmのしくみ

https://speakerdeck.com/k0kubun/number-ginzarb の資料作成のためのnewrelic_rpmのコードリーディングメモ。バージョンはv4.3.0。

Railtie→Agent#start まで

require 'newrelic_rpm'でRailtieが作られる

まずRailsの場合、普通にGemfileにgem 'newrelic_rpm'を書くと、Bundler.requireされた時にNewRelic::Railtieが定義される。

  if Rails::VERSION::MAJOR.to_i >= 3
    module NewRelic
      class Railtie < Rails::Railtie

        initializer "newrelic_rpm.start_plugin" do |app|
          NewRelic::Control.instance.init_plugin(:config => app.config)
        end
      end
    end
  else

Railsのinitializerの発火

config/environment.rb でrequire File.expand_path('../application', __FILE__)された時にBundler.requireされた後、Rails.application.initialize!でRailtieのinitializerが発火される。

上述のinitializerの中で、シングルトンのNewRelic::Control.instanceが作られ、NewRelic::Control::InstanceMethods#init_pluginが呼ばれる。

#init_plugin

このメソッドの最後で、agentがまだ起動してない時、NewRelic::Agent.agent.startする。

        if Agent.config[:agent_enabled] && !NewRelic::Agent.instance.started?
          start_agent
          install_instrumentation
        elsif !Agent.config[:agent_enabled]

      def start_agent
        @started_in_env = self.env
        NewRelic::Agent.agent.start
      end

NewRelic::Agent#start

forkをしない場合はここでstartする。unicornやpumaなど、forkを使う"dispatcher"を使う場合、このメソッドではstartをしない。

        def start
          return unless agent_should_start?

          log_startup
          check_config_and_start_agent
          log_version_and_pid

          events.subscribe(:finished_configuring) do
            log_ignore_url_regexes
          end
        end

          def check_config_and_start_agent
            return unless monitoring? && has_correct_license_key?
            return if using_forking_dispatcher?
            setup_and_start_agent
          end

          def using_forking_dispatcher?
            if [:puma, :passenger, :rainbows, :unicorn].include? Agent.config[:dispatcher]
              ::NewRelic::Agent.logger.info "Deferring startup of agent reporting thread because #{Agent.config[:dispatcher]} may fork."
              true
            else
              false
            end
          end

forkをする場合のAgentの起動パス

では、productionでよく使うであろうunicornやpumaではいつどのように起動されるのか。

#init_plugin

        if Agent.config[:agent_enabled] && !NewRelic::Agent.instance.started?
          start_agent
          install_instrumentation
        elsif !Agent.config[:agent_enabled]

start_agentでの起動をスキップしたあと、install_instrumentationというのが呼ばれている。

install_instrumentation

      def install_instrumentation
        _install_instrumentation
      end

      private

      def _install_instrumentation
        return if @instrumented

        @instrumented = true

        # Instrumentation for the key code points inside rails for monitoring by NewRelic.
        # note this file is loaded only if the newrelic agent is enabled (through config/newrelic.yml)
        instrumentation_path = File.expand_path(File.join(File.dirname(__FILE__), '..', 'agent','instrumentation'))
        @instrumentation_files <<
        File.join(instrumentation_path, '*.rb') <<
        File.join(instrumentation_path, app.to_s, '*.rb')
        @instrumentation_files.each { | pattern |  load_instrumentation_files pattern }
        DependencyDetection.detect!
        ::NewRelic::Agent.logger.info "Finished instrumentation"
      end

DependencyDetection.detect!という奴が呼ばれる。

DependencyDetection

DependencyDetection.defer do
  named :rack

  depends_on do
    defined?(::Rack) && defined?(::Rack::Builder)
  end

  executes do
    ::NewRelic::Agent::Instrumentation::RackHelpers.instrument_builder ::Rack::Builder
  end
end

DependencyDetection.detect!は、こういうDSLを書いておくと、depends_onを満たす時にexecutesを実行するようだ。なので、::NewRelic::Agent::Instrumentation::RackHelpers.instrument_builder ::Rack::Builderが呼ばれる。

instrument_builder

        def self.instrument_builder builder_class
          ::NewRelic::Agent.logger.info "Installing deferred #{builder_class} instrumentation"

          builder_class.class_eval do
            class << self
              attr_accessor :_nr_deferred_detection_ran
            end
            self._nr_deferred_detection_ran = false

            include ::NewRelic::Agent::Instrumentation::RackBuilder

            alias_method :to_app_without_newrelic, :to_app
            alias_method :to_app, :to_app_with_newrelic_deferred_dependency_detection

            if ::NewRelic::Agent::Instrumentation::RackHelpers.middleware_instrumentation_enabled?
              ::NewRelic::Agent.logger.info "Installing #{builder_class} middleware instrumentation"
              alias_method :run_without_newrelic, :run
              alias_method :run, :run_with_newrelic

              alias_method :use_without_newrelic, :use
              alias_method :use, :use_with_newrelic
            end
          end

          def self.instrument_url_map url_map_class
            url_map_class.class_eval do
              alias_method :initialize_without_newrelic, :initialize

              def initialize(map = {})
                traced_map = ::NewRelic::Agent::Instrumentation::RackURLMap.generate_traced_map(map)
                initialize_without_newrelic(traced_map)
              end
            end
          end
        end

このメソッドはRack::Builderにモンキーパッチをやりまくる。見ておく必要があるのは、include ::NewRelic::Agent::Instrumentation::RackBuilderとかalias_method :run, :run_with_newrelicのあたり。

Rack::Builder#run

config.ruにrunというDSLが書いてあるのをご存知だろうか。それがRack::Builder#runである。Rackサーバーを起動するとこれが評価されてRackアプリケーションがビルドされる。詳細は僕の別の記事をどうぞ。
Rackとは何か

で、重要なのはinstrument_builderでこの#runがモンキーパッチされて::NewRelic::Agent::Instrumentation::RackBuilder#run_with_newrelicが呼びだされること。

      module RackBuilder
        def run_with_newrelic(app, *args)
          if ::NewRelic::Agent::Instrumentation::RackHelpers.middleware_instrumentation_enabled?
            wrapped_app = ::NewRelic::Agent::Instrumentation::MiddlewareProxy.wrap(app, true)
            run_without_newrelic(wrapped_app, *args)
          else
            run_without_newrelic(app, *args)
          end
        end

ここで、Rackアプリケーションを::NewRelic::Agent::Instrumentation::MiddlewareProxyというRackミドルウェアでラップしている。

NewRelic::Agent::Instrumentation::MiddlewareTracing#call

NewRelic::Agent::Instrumentation::MiddlewareProxyはNewRelic::Agent::Instrumentation::MiddlewareTracingをincludeしていて、#callの実装はそっちにある。

RackサーバーはRackアプリケーションでリクエストを処理するために#callを呼ぶので、最初にリクエストが来た時にNewRelic::Agent::Instrumentation::MiddlewareTracing#callが呼ばれることになる。

        def call(env)
          first_middleware = note_transaction_started(env)

          state = NewRelic::Agent::TransactionState.tl_get

          begin
            Transaction.start(state, category, build_transaction_options(env, first_middleware))
            events.notify(:before_call, env) if first_middleware

            result = (target == self) ? traced_call(env) : target.call(env)

            if first_middleware
              capture_response_attributes(state, result)
              events.notify(:after_call, env, result)
            end

            result
          rescue Exception => e
            NewRelic::Agent.notice_error(e)
            raise e
          ensure
            Transaction.stop(state)
          end
        end

ここでTransaction.startが呼ばれる。

Transaction.start

      def self.start(state, category, options)
        category ||= :controller
        txn = state.current_transaction

        if txn
          txn.create_nested_frame(state, category, options)
        else
          txn = start_new_transaction(state, category, options)
        end

        txn
      rescue => e
        NewRelic::Agent.logger.error("Exception during Transaction.start", e)
        nil
      end

      def self.start_new_transaction(state, category, options)
        txn = Transaction.new(category, options)
        state.reset(txn)
        txn.state = state
        txn.start(state)
        txn
      end

      def start(state)
        return if !state.is_execution_traced?

        transaction_sampler.on_start_transaction(state, start_time)
        sql_sampler.on_start_transaction(state, start_time, request_path)
        NewRelic::Agent.instance.events.notify(:start_transaction)
        NewRelic::Agent::BusyCalculator.dispatcher_start(start_time)

        ignore! if user_defined_rules_ignore?

        create_initial_segment @default_name
      end

NewRelic::Agent.instance.events.notify(:start_transaction)が呼ばれる。

NewRelic::Agent::Harvester#on_transactionの発火

最初にAgentのインスタンスが作られる時、NewRelic::Agent::Agent#initializeで、NewRelic::Agent::Harvesterのインスタンスが作られる。

        @harvester       = NewRelic::Agent::Harvester.new(@events)

で、これのインスタンス生成時にeventをsubscribeする。

      def initialize(events, after_forker=NewRelic::Agent)
        # We intentionally don't set our pid as started at this point.
        # Startup routines must call mark_started when they consider us set!
        @starting_pid = nil
        @after_forker = after_forker

        if events
          events.subscribe(:start_transaction, &method(:on_transaction))
        end
      end

なので、NewRelic::Agent.instance.events.notify(:start_transaction)で#on_transactionが呼ばれる。

      def on_transaction(*_)
        return unless restart_in_children_enabled? &&
                        needs_restart? &&
                        harvest_thread_enabled?

        restart_harvest_thread
      end

      def restart_harvest_thread
        @after_forker.after_fork(:force_reconnect => true)
      end

@after_forkerにはNewRelic::Agentが入っているので、NewRelic::Agent::InstanceMethods#after_forkが呼ばれることになる。

NewRelic::Agent::InstanceMethods#after_fork

        def after_fork(options={})
          needs_restart = false
          @after_fork_lock.synchronize do
            needs_restart = @harvester.needs_restart?
            @harvester.mark_started
          end

          return if !needs_restart ||
            !Agent.config[:agent_enabled] ||
            !Agent.config[:monitor_mode] ||
            disconnected?

          ::NewRelic::Agent.logger.debug "Starting the worker thread in #{Process.pid} (parent #{Process.ppid}) after forking."

          channel_id = options[:report_to_channel]
          install_pipe_service(channel_id) if channel_id

          # Clear out locks and stats left over from parent process
          reset_objects_with_locks
          drop_buffered_data

          setup_and_start_agent(options)
        end

          def setup_and_start_agent(options={})
            @started = true
            @harvester.mark_started

            unless in_resque_child_process?
              generate_environment_report
              install_exit_handler
              @harvest_samplers.load_samplers unless Agent.config[:disable_samplers]
            end

            connect_in_foreground if Agent.config[:sync_startup]
            start_worker_thread(options)
          end

start_worker_threadが呼ばれることがわかる。

start_worker_thread

        def start_worker_thread(connection_options = {})
          if disable = NewRelic::Agent.config[:disable_harvest_thread]
            NewRelic::Agent.logger.info "Not starting Ruby Agent worker thread because :disable_harvest_thread is #{disable}"
            return
          end

          ::NewRelic::Agent.logger.debug "Creating Ruby Agent worker thread."
          @worker_thread = NewRelic::Agent::Threading::AgentThread.create('Worker Loop') do
            deferred_work!(connection_options)
          end
        end

ハイ。というわけで、pumaやunicornを使っていると、最初にリクエストが来た時にスレッドが立ち上がり、そのスレッドはdeferred_work!をやる、という挙動になっている。

NewRelicのワーカースレッドは何をやっているか

AgentThread.create

中では普通にThread.new { deferred_work!(connection_options) }のようなことが起きる。

deferred_work!

          def deferred_work!(connection_options)
            catch_errors do
              NewRelic::Agent.disable_all_tracing do
                connect(connection_options)
                if connected?
                  create_and_run_event_loop
                  # never reaches here unless there is a problem or
                  # the agent is exiting
                else
                  ::NewRelic::Agent.logger.debug "No connection.  Worker thread ending."
                end
              end
            end
          end

これはあんまちゃんと見てないがconnectはNewRelicに接続できるか確認するぽい。NewRelicにデータが送れる状況でのみワーカーがcreate_and_run_event_loopをするようになっているのだと思う。

create_and_run_event_loop

          def create_and_run_event_loop
            @event_loop = create_event_loop
            @event_loop.on(:report_data) do
              transmit_data
            end
            @event_loop.on(:report_event_data) do
              transmit_event_data
            end
            @event_loop.on(:reset_log_once_keys) do
              ::NewRelic::Agent.logger.clear_already_logged
            end
            @event_loop.fire_every(Agent.config[:data_report_period],       :report_data)
            @event_loop.fire_every(report_period_for(:analytic_event_data), :report_event_data)
            @event_loop.fire_every(LOG_ONCE_KEYS_RESET_PERIOD,              :reset_log_once_keys)

            @event_loop.run
          end

          def create_event_loop
            EventLoop.new
          end

なるほどね

EventLoop#run

      def run
        ::NewRelic::Agent.logger.debug "Running event loop"
        while !stopped?
          run_once
        end
      end

      def run_once(nonblock=false)
        wait_to_run(nonblock)

        prune_timers
        fire_timers

        until @event_queue.empty?
          evt, args = @event_queue.pop
          dispatch_event(evt, args)
          reschedule_timer_for_event(evt)
        end
      end

      def wait_to_run(nonblock)
        timeout = nonblock ? 0 : next_timeout
        ready = IO.select([@self_pipe_rd], nil, nil, timeout)

        if ready && ready[0] && ready[0][0] && ready[0][0] == @self_pipe_rd
          @self_pipe_rd.read(1)
        end
      end

@event_loop.runのところでwhile !stopped?な無限ループに入る。

で、このループは基本的にIO.selectでブロックする。@self_pipe_rdにはIO.pipeした奴が入ってて、これの書き込み側は以下のようになっており、#fireによってイベントが発火されるとブロックが解除される。

      def fire(event, *args)
        @event_queue << [event, args]
        wakeup
      end

      def wakeup
        begin
          @self_pipe_wr.write_nonblock '.'
        rescue Errno::EAGAIN
          ::NewRelic::Agent.logger.debug "Failed to wakeup event loop"
        end
      end

CRubyではブロッキングIOの間GVLが開放されるので、イベントが発火されるまでは本体の処理を邪魔しないということになる。また、このIO.selectのタイムアウトは以下のようにして決まり、設定しておいたTimerのうち最初に発火されるTimerまでの時間が経つと解除されるようになっている。

      def next_timeout
        return nil if @timers.empty?
        timeout = @timers.values.map(&:next_fire_time).min - Time.now
        timeout < 0 ? 0 : timeout
      end

Timerによるイベントの発火

create_and_run_event_loopが呼ばれた際、イベントループが始まった時にTimerがセットされるように仕向けられている。

            @event_loop.fire_every(Agent.config[:data_report_period],       :report_data)
            @event_loop.fire_every(report_period_for(:analytic_event_data), :report_event_data)
            @event_loop.fire_every(LOG_ONCE_KEYS_RESET_PERIOD,              :reset_log_once_keys)

      # Timer.newを作って__add_timerイベントにしている
      def fire_every(interval, event)
        ::NewRelic::Agent.logger.debug "Firing event #{event} every #{interval} seconds."
        fire(:__add_timer, Timer.new(interval, event, true))
      end

      # __add_timerがsubscribeされている
      def initialize
        @self_pipe_rd, @self_pipe_wr = IO.pipe
        @event_queue = Queue.new
        @stopped     = false
        @timers      = {}

        @subscriptions = Hash.new { |h,k| h[k] = [] }
        @subscriptions[:__add_timer] << Proc.new { |t| set_timer(t) }
        @subscriptions[:__add_event] << Proc.new { |e, blk| @subscriptions[e] << blk }
      end

      # イベントループで、queueからpopされ、dispatch_eventされる
      def run_once(nonblock=false)
        wait_to_run(nonblock)

        prune_timers
        fire_timers

        until @event_queue.empty?
          evt, args = @event_queue.pop
          dispatch_event(evt, args)
          reschedule_timer_for_event(evt)
        end
      end

      # dispatchされると、callで`set_timer(t)`が呼ばれる
      def dispatch_event(event, args)
        NewRelic::Agent.logger.debug("EventLoop: Dispatching event '#{event}' with #{@subscriptions[event].size} callback(s).")

        errors = []
        @subscriptions[event].each do |s|
          begin
            s.call(*args)
          rescue NewRelic::Agent::ForceRestartException, NewRelic::Agent::ForceDisconnectException
            raise
          rescue => e
            errors << e
          end
        end

        if !errors.empty?
          ::NewRelic::Agent.logger.error "#{errors.size} error(s) running task for event '#{event}' in Agent Event Loop:", *errors
        end
      end

      # ここで @timers にtimerがセットされる。すると、event loopのfire_timers呼び出しでもfire_timerが呼ばれるようになる
      def set_timer(timer)
        existing_timer = @timers[timer.event]

        if existing_timer
          elapsed_interval = Time.now - existing_timer.last_interval_start
          timer.advance(elapsed_interval)
        end

        @timers[timer.event] = timer

        fire_timer(timer)
      end

      # timer.due?であればイベントをキューにつっこむ
      def fire_timer(timer)
        if timer.due?
          @event_queue << [timer.event]
          timer.set_fired_time
        end
      end

まあつまり、設定しておいたインターバルでnext_fire_timeが計算され、その時間の間IO.selectでブロックし、その後イベントが発火されてそのイベントがディスパッチされる、というようになっている。

NewRelicのワーカースレッドがタイマーでディスパッチしているイベント

create_and_run_event_loopをよく見るとイベントを3つsubscribeし、これらを発火するタイマーイベントを3つ作っているだけなのだ。それぞれのイベントの内容を見ていく。

:report_data

@event_loop.fire_every(Agent.config[:data_report_period],       :report_data)

インターバルは以下のようにデフォルトでは60秒になっている。

        :data_report_period => {
          :default => 60,
          :public => false,
          :type => Integer,
          :allowed_from_server => true,
          :description => 'Number of seconds betwixt connections to the New Relic data collection service. Note that transaction events have a separate report period, specified by data_report_periods.analytic_event_data.'
        },

イベントのsubscriptionはこうなっている。

            @event_loop.on(:report_data) do
              transmit_data
            end

        def transmit_data
          now = Time.now
          ::NewRelic::Agent.logger.debug "Sending data to New Relic Service"

          @events.notify(:before_harvest)
          @service.session do # use http keep-alive
            harvest_and_send_errors
            harvest_and_send_error_event_data
            harvest_and_send_transaction_traces
            harvest_and_send_slowest_sql
            harvest_and_send_timeslice_data

            check_for_and_handle_agent_commands
            harvest_and_send_for_agent_commands
          end
        ensure
          NewRelic::Agent::Database.close_connections
          duration = (Time.now - now).to_f
          NewRelic::Agent.record_metric('Supportability/Harvest', duration)
        end

あんまちゃんと読んでないけど、収集したデータをNewRelicに飛ばすのはこれがやっているようだ。

:report_event_data

@event_loop.fire_every(report_period_for(:analytic_event_data), :report_event_data)

これも60秒おき。

        :'data_report_periods.analytic_event_data' => {
          :default => 60,
          :public => false,
          :type => Integer,
          :dynamic_name => true,
          :allowed_from_server => true,
          :description => 'Number of seconds between connections to the New Relic data collection service for sending transaction event data.'
        },

イベントの処理はこう。

            @event_loop.on(:report_event_data) do
              transmit_event_data
            end

        def transmit_event_data
          transmit_single_data_type(:harvest_and_send_analytic_event_data, "TransactionEvent")
        end

        def transmit_single_data_type(harvest_method, supportability_name)
          now = Time.now

          msg = "Sending #{harvest_method.to_s.gsub("harvest_and_send_", "")} to New Relic Service"
          ::NewRelic::Agent.logger.debug msg

          @service.session do # use http keep-alive
            self.send(harvest_method)
          end
        ensure
          duration = (Time.now - now).to_f
          NewRelic::Agent.record_metric("Supportability/#{supportability_name}Harvest", duration)
        end

        def harvest_and_send_analytic_event_data
          harvest_and_send_from_container(transaction_event_aggregator, :analytic_event_data)
          harvest_and_send_from_container(synthetics_event_aggregator, :analytic_event_data)
          harvest_and_send_from_container(@custom_event_aggregator,      :custom_event_data)
        end

なんかアナリティクスっぽいデータを送るようだ(読みたいところが別のとこであるということが読めてしまったので興味を失っている)

:reset_log_once_keys

            @event_loop.on(:reset_log_once_keys) do
              ::NewRelic::Agent.logger.clear_already_logged
            end

これも60秒おき。

          LOG_ONCE_KEYS_RESET_PERIOD = 60.0

      def log_once(level, key, *msgs)
        @already_logged_lock.synchronize do
          return if @already_logged.include?(key)

          if @already_logged.size >= NUM_LOG_ONCE_KEYS && key.kind_of?(String)
            # The reason for preventing too many keys in `logged` is for
            # memory concerns.
            # The reason for checking the type of the key is that we always want
            # to allow symbols to log, since there are very few of them.
            # The assumption here is that you would NEVER pass dynamically-created
            # symbols, because you would never create symbols dynamically in the
            # first place, as that would already be a memory leak in most Rubies,
            # even if we didn't hang on to them all here.
            return
          end

          @already_logged[key] = true
        end

        self.send(level, *msgs)
      end

      def clear_already_logged
        @already_logged_lock.synchronize do
          @already_logged = {}
        end
      end

メモリが気になるのでログを定期的に消しているようだ。これ別のイベントでちゃんとNewRelicに飛ばされたりしてるのかなあ(全く読んでない)。

Transactionのプロファイリングはどうなっているか

Rackミドルウェアのフック

なんとなくワーカースレッドがサンプリングしてるのかと勝手に思ってたけど全然違うっぽいことに気付いた(1分おきにサンプリングとかだったら粗すぎる…)。Rackミドルウェアをもう一度見てみる。

        def call(env)
          first_middleware = note_transaction_started(env)

          state = NewRelic::Agent::TransactionState.tl_get

          begin
            Transaction.start(state, category, build_transaction_options(env, first_middleware))
            events.notify(:before_call, env) if first_middleware

            result = (target == self) ? traced_call(env) : target.call(env)

            if first_middleware
              capture_response_attributes(state, result)
              events.notify(:after_call, env, result)
            end

            result
          rescue Exception => e
            NewRelic::Agent.notice_error(e)
            raise e
          ensure
            Transaction.stop(state)
          end
        end

      def self.start(state, category, options)
        category ||= :controller
        txn = state.current_transaction

        if txn
          txn.create_nested_frame(state, category, options)
        else
          txn = start_new_transaction(state, category, options)
        end

        txn
      rescue => e
        NewRelic::Agent.logger.error("Exception during Transaction.start", e)
        nil
      end

      def self.start_new_transaction(state, category, options)
        txn = Transaction.new(category, options)
        state.reset(txn)
        txn.state = state
        txn.start(state)
        txn
      end

      def start(state)
        return if !state.is_execution_traced?

        transaction_sampler.on_start_transaction(state, start_time)
        sql_sampler.on_start_transaction(state, start_time, request_path)
        NewRelic::Agent.instance.events.notify(:start_transaction)
        NewRelic::Agent::BusyCalculator.dispatcher_start(start_time)

        ignore! if user_defined_rules_ignore?

        create_initial_segment @default_name
      end

      def agent
        NewRelic::Agent.instance
      end

      def transaction_sampler
        agent.transaction_sampler
      end

      def sql_sampler
        agent.sql_sampler
      end

シングルトンのtransaction_samplerとsql_samplerを参照し、on_start_transactionを呼ぶようだ。

まあ、stopも似たようなことをやっておき、1回のリクエストごとの結果を取れるようにしているのだろう。

そして、ここを読んでもプロファイリングをやっている場所はわからなかったのでまた別の場所を読む。

プロファイリングを行う場所

こういう感じだろうと期待していたのが全然違ったのでかなり迷走していたが、いろいろやってたらなんとなく読めた。 new_relic/agent/instrumentation に色々なgem向けのintegrationがとにかくいっぱい入っている。

で、前述したように、Railtieから呼ばれる#init_pluginの最後に呼ばれるinstall_instrumentationでDependencyDetection.detect!が呼ばれ、それぞれのgemのクラスが定義されていた場合はRackの時に前述したような感じでモンキーパッチを行う。というか、RackはNewRelicが収集している数あるメトリクスの中の1つにすぎなかったようだ。

で、モンキーパッチをしたメソッドが呼ばれた時に、大抵は開始と終了の時間を計測し、その計測結果を保存しておいて、ワーカースレッドが送信する、という挙動のようだ。例えばActiveRecordの奴を見てみる。

module NewRelic
  module Agent
    module Instrumentation
      module ActiveRecord
        ACTIVE_RECORD = "ActiveRecord".freeze

        module BaseExtensions
          def save(*args, &blk)
            ::NewRelic::Agent.with_database_metric_name(self.class.name, nil, ACTIVE_RECORD) do
              super
            end
          end

          def save!(*args, &blk)
            ::NewRelic::Agent.with_database_metric_name(self.class.name, nil, ACTIVE_RECORD) do
              super
            end
          end
        end

        module RelationExtensions
          def update_all(*args, &blk)
            ::NewRelic::Agent.with_database_metric_name(self.name, nil, ACTIVE_RECORD) do
              super
            end
          end

          def delete_all(*args, &blk)
            ::NewRelic::Agent.with_database_metric_name(self.name, nil, ACTIVE_RECORD) do
              super
            end
          end

          def destroy_all(*args, &blk)
            ::NewRelic::Agent.with_database_metric_name(self.name, nil, ACTIVE_RECORD) do
              super
            end
          end

          def calculate(*args, &blk)
            ::NewRelic::Agent.with_database_metric_name(self.name, nil, ACTIVE_RECORD) do
              super
            end
          end

          def pluck(*args, &blk)
            ::NewRelic::Agent.with_database_metric_name(self.name, nil, ACTIVE_RECORD) do
              super
            end
          end
        end
      end
    end
  end
end

DependencyDetection.defer do
  named :active_record_5

  depends_on do
    defined?(::ActiveRecord) && defined?(::ActiveRecord::Base) &&
      defined?(::ActiveRecord::VERSION) &&
      ::ActiveRecord::VERSION::MAJOR.to_i == 5
  end

  depends_on do
    !NewRelic::Agent.config[:disable_activerecord_instrumentation] &&
      !NewRelic::Agent::Instrumentation::ActiveRecordSubscriber.subscribed?
  end

  executes do
    ::NewRelic::Agent.logger.info 'Installing ActiveRecord 5 instrumentation'
  end

  executes do
    ActiveSupport::Notifications.subscribe('sql.active_record',
      NewRelic::Agent::Instrumentation::ActiveRecordSubscriber.new)

    ActiveSupport.on_load(:active_record) do
      ::ActiveRecord::Base.prepend ::NewRelic::Agent::Instrumentation::ActiveRecord::BaseExtensions
      ::ActiveRecord::Relation.prepend ::NewRelic::Agent::Instrumentation::ActiveRecord::RelationExtensions
    end
  end
end

これは大分わかりやすい。こういうのがいろんなgemに対してひたすら入っており、それらを全て送信しておけば、まあ当然NewRelicが出しているような集計結果は出せる。

(NewRelicの)transactionをstopするところでbinding.pryとかしてみればわかるが、そういういろんな種類のメトリクスがいろいろ入ってる奴がNewRelicのメトリクスになっていた。

それぞれ丁寧にintegrationを作っている以上、オーバーヘッドはあるもののそこそこ正確な計測結果が得られるので、割といいものだなあと思った。