zhuochun/html_log.rb

## html_log.rb
# this is a dirty implementation of logger that
# compiles AR queries with trace into /last_request_log.html
# the snippet is useful when optimizing performance of the endpoint

class QueryLogSubscriber < ActiveSupport::LogSubscriber
  TRACE_LEVEL = :app
  LINES = 5
  IGNORE_CACHED_QUERIES = false

  def initialize
    super

    $traced_queries = []
    if TRACE_LEVEL != :app
      # Rails by default silences all backtraces that match Rails::BacktraceCleaner::APP_DIRS_PATTERN
      Rails.backtrace_cleaner.remove_silencers!
    end
  end

  def sql(event)
    index = begin
      if LINES == 0
        0..-1
      else
        0..(LINES - 1)
      end
    end

    payload = event.payload
    return if payload[:name] == 'SCHEMA'
    return if IGNORE_CACHED_QUERIES && payload[:name] == 'CACHE'

    $traced_queries << {
      payload: payload,
      trace: clean_trace(caller)[index],
      duration: event.duration.round(1)
    }
  end

  def clean_trace(trace)
    # Rails relies on backtrace cleaner to set the application root directory filter
    # the problem is that the backtrace cleaner is initialized before the application
    # this ensures that the value of `root` used by the filter is set to the application root
    if Rails.backtrace_cleaner.instance_variable_get(:@root) == '/'
      Rails.backtrace_cleaner.instance_variable_set :@root, Rails.root.to_s
    end

    case TRACE_LEVEL
    when :full
      trace
    when :rails, :app
      Rails.respond_to?(:backtrace_cleaner) ? Rails.backtrace_cleaner.clean(trace) : trace
    else
      raise "Invalid TRACE_LEVEL value '#{TRACE_LEVEL}' - should be :full, :rails, or :app"
    end
  end
end

class HtmlLogSubscriber < ActiveSupport::LogSubscriber
  INTERNAL_PARAMS = %w(controller action format _method only_path)

  def start_processing(event)
    @request_dump = {}
    @request_dump[:request] = event.payload
  end

  class RequestRender
    def initialize(request)
      @request = request
    end

    def build
      b = binding
      ERB.new(File.read(Rails.root.join("lib/last_request_log.erb"))).result b
    end

    def request_payload
      @request[:request]
    end

    def average_query_duration
      @average_query_duration ||= begin
        @request[:queries].map { |q| q[:duration] }.inject{ |sum, el| sum + el }.to_f / @request[:queries].size
      end
    end
  end

  def process_action(event)
    @request_dump[:queries] = $traced_queries
    $traced_queries = []

    payload   = event.payload
    additions = ActionController::Base.log_process_action(payload)

    status = payload[:status]
    if status.nil? && payload[:exception].present?
      exception_class_name = payload[:exception].first
      status = ActionDispatch::ExceptionWrapper.status_code_for_exception(exception_class_name)
    end
    message = "Completed #{status} #{Rack::Utils::HTTP_STATUS_CODES[status]} in #{event.duration.round}ms"
    message << " (#{additions.join(" | ".freeze)})" unless additions.blank?
    @request_dump[:completed] = message

    File.open(Rails.root.join("public/last_request_log.html"), "w") do |f|
      f.write RequestRender.new(@request_dump).build
    end
  end
end

if Rails.env.development?
  QueryLogSubscriber.attach_to :active_record
  HtmlLogSubscriber.attach_to :action_controller
end

## last_request_log.erb
<html>
<head>
  <style media="screen">

  </style>
</head>
<body>
  <p>
    Processing by <%= request_payload[:controller] %>#<%= request_payload[:action] %> as <%= request_payload[:format].to_s.upcase %>
  </p>
  <p>
    Parameters: <%= request_payload[:params].inspect %>
  </p>
  <p>
    <strong><%= @request[:queries].count %> queries</strong>
  </p>
  <p>
    <%= @request[:completed] %>
  </p>

  <ul>
    <% @request[:queries].each do |q| %>
    <li <% if(q[:duration] > average_query_duration * 2) %>style="color: red"<% end %>>
      <p>
        <strong>[<%= q[:payload][:name] %>]</strong>
        <%= q[:payload][:sql] %>
        (<%= q[:duration] %>ms)
      </p>

      <ul>
        <% q[:trace].each do |trace| %>
        <li><%= trace %></li>
        <% end %>
      </ul>
    </li>
    <% end %>
  </ul>
</body>
</html>
	# this is a dirty implementation of logger that
	# compiles AR queries with trace into /last_request_log.html
	# the snippet is useful when optimizing performance of the endpoint

	class QueryLogSubscriber < ActiveSupport::LogSubscriber
	TRACE_LEVEL = :app
	LINES = 5
	IGNORE_CACHED_QUERIES = false

	def initialize
	super

	$traced_queries = []
	if TRACE_LEVEL != :app
	# Rails by default silences all backtraces that match Rails::BacktraceCleaner::APP_DIRS_PATTERN
	Rails.backtrace_cleaner.remove_silencers!
	end
	end

	def sql(event)
	index = begin
	if LINES == 0
	0..-1
	else
	0..(LINES - 1)
	end
	end

	payload = event.payload
	return if payload[:name] == 'SCHEMA'
	return if IGNORE_CACHED_QUERIES && payload[:name] == 'CACHE'

	$traced_queries << {
	payload: payload,
	trace: clean_trace(caller)[index],
	duration: event.duration.round(1)
	}
	end

	def clean_trace(trace)
	# Rails relies on backtrace cleaner to set the application root directory filter
	# the problem is that the backtrace cleaner is initialized before the application
	# this ensures that the value of `root` used by the filter is set to the application root
	if Rails.backtrace_cleaner.instance_variable_get(:@root) == '/'
	Rails.backtrace_cleaner.instance_variable_set :@root, Rails.root.to_s
	end

	case TRACE_LEVEL
	when :full
	trace
	when :rails, :app
	Rails.respond_to?(:backtrace_cleaner) ? Rails.backtrace_cleaner.clean(trace) : trace
	else
	raise "Invalid TRACE_LEVEL value '#{TRACE_LEVEL}' - should be :full, :rails, or :app"
	end
	end
	end

	class HtmlLogSubscriber < ActiveSupport::LogSubscriber
	INTERNAL_PARAMS = %w(controller action format _method only_path)

	def start_processing(event)
	@request_dump = {}
	@request_dump[:request] = event.payload
	end

	class RequestRender
	def initialize(request)
	@request = request
	end

	def build
	b = binding
	ERB.new(File.read(Rails.root.join("lib/last_request_log.erb"))).result b
	end

	def request_payload
	@request[:request]
	end

	def average_query_duration
	@average_query_duration \|\|= begin
	@request[:queries].map { \|q\| q[:duration] }.inject{ \|sum, el\| sum + el }.to_f / @request[:queries].size
	end
	end
	end

	def process_action(event)
	@request_dump[:queries] = $traced_queries
	$traced_queries = []

	payload = event.payload
	additions = ActionController::Base.log_process_action(payload)

	status = payload[:status]
	if status.nil? && payload[:exception].present?
	exception_class_name = payload[:exception].first
	status = ActionDispatch::ExceptionWrapper.status_code_for_exception(exception_class_name)
	end
	message = "Completed #{status} #{Rack::Utils::HTTP_STATUS_CODES[status]} in #{event.duration.round}ms"
	message << " (#{additions.join(" \| ".freeze)})" unless additions.blank?
	@request_dump[:completed] = message

	File.open(Rails.root.join("public/last_request_log.html"), "w") do \|f\|
	f.write RequestRender.new(@request_dump).build
	end
	end
	end

	if Rails.env.development?
	QueryLogSubscriber.attach_to :active_record
	HtmlLogSubscriber.attach_to :action_controller
	end
	<html>
	<head>
	<style media="screen">

	</style>
	</head>
	<body>
	<p>
	Processing by <%= request_payload[:controller] %>#<%= request_payload[:action] %> as <%= request_payload[:format].to_s.upcase %>
	</p>
	<p>
	Parameters: <%= request_payload[:params].inspect %>
	</p>
	<p>
	<strong><%= @request[:queries].count %> queries</strong>
	</p>
	<p>
	<%= @request[:completed] %>
	</p>

	<ul>
	<% @request[:queries].each do \|q\| %>
	<li <% if(q[:duration] > average_query_duration * 2) %>style="color: red"<% end %>>
	<p>
	<strong>[<%= q[:payload][:name] %>]</strong>
	<%= q[:payload][:sql] %>
	(<%= q[:duration] %>ms)
	</p>

	<ul>
	<% q[:trace].each do \|trace\| %>
	<li><%= trace %></li>
	<% end %>
	</ul>
	</li>
	<% end %>
	</ul>
	</body>
	</html>