Skip to content

Instantly share code, notes, and snippets.

@kirs
Created October 20, 2015 10:20
Show Gist options
  • Save kirs/d6a3721ad01800f500d9 to your computer and use it in GitHub Desktop.
Save kirs/d6a3721ad01800f500d9 to your computer and use it in GitHub Desktop.
# 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>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment