Handyman's Secret Weapon

molasses.rb

#  Molasses
# ---------
#
# Ths tool produces log/molasses.log that records query activity and a
# concise summary of the number of calls made for the rendering of each
# page. By default this behavior is only engaged in the development
# environment.

module Molasses
  def self.logger
    @log ||= begin
      log = File.open(Rails.root.join('log/molasses.log'), 'a')
      log.sync = true
      log
    end
  end

  def self.controller_action
    Thread.current[:_controller_action]
  end

  def self.controller_action=(payload)
    Thread.current[:_controller_action] = payload && {
      time: Time.now,
      payload: payload,
      actions: Hash.new { |h,k| h[k] = { count: 0, time: 0.0 } }
    }
  end

  def self.observe(name, payload, &block)
    @depth ||= 0

    # logger.puts(' ' * (@depth * 2) + [name, payload].inspect)

    _action_stats = nil

    case (name)
    when 'process_action.action_controller'
      self.controller_action = payload
    when 'start_processing.action_controller'
      # Ignored
    else
      if (_controller_action = self.controller_action)
        _action_stats = _controller_action[:actions][name]
        _action_stats[:count] += 1
      end
    end

    start_time = Time.now
    @depth += 1

    # Block may contain a `return` statement which could cause this method to
    # prematurely exit and lose control. Adding `ensure` avoids losing track
    # of what the call stack is.
    result = yield

  ensure
    @depth -= 1

    case (name)
    when 'process_action.action_controller'
      if (_controller_action = self.controller_action)
        payload = _controller_action[:payload]

        logger.puts('%s#%s => %s %s' % [
          payload[:controller],
          payload[:action],
          payload[:method],
          payload[:path]
        ])

        _controller_action[:actions].each do |name, stats|
          logger.puts('  %-40s %6d %6dms' % [
            name,
            stats[:count],
            stats[:time] * 1000
          ])
        end

        logger.puts('  %-40s %6s %6dms' % [ 'Total', '', (Time.now.to_f - _controller_action[:time].to_f) * 1000])
      end

      self.controller_action = nil
    else
      time_diff = Time.now.to_f - start_time.to_f

      if (_action_stats)
        _action_stats[:time] += time_diff
      end

      case (name)
      when 'sql.active_record'
        logger.puts('%s[%6dms] SQL> %s' % [
          ' ' * (@depth * 2),
          time_diff * 1000,
          payload[:sql]
        ])
      when 'render_partial.action_view'
        logger.puts('%s[%6dms] RENDER> %s' % [
          ' ' * (@depth * 2),
          time_diff * 1000,
          payload[:identifier]
        ])
      end
    end

    result
  end
end

if (Rails.env.development?)
  module ActiveSupport
    module Notifications
      class Instrumenter
        alias_method :instrument__, :instrument

        def instrument(name, payload = { }, &block)
          Molasses.observe(name, payload) do
            instrument__(name, payload, &block)
          end
        end
      end
    end
  end
end