Tracking Slow Queries with Yeller
This is a blog about the development of Yeller, The Exception Tracker with Answers
We’ve all had it. That call from a client, a customer or a boss where they say:
This page took over a minute to load. That needs fixing
Often, modern web apps have slow pageloads because of particularly bad database queries. Maybe they’re doing a SELECT * from ...
without an offset or a limit set, and the data size grew more than you expected. Maybe some tables need indexes adding to them.
How do you track down a particularly slow database query?
Yeller can help you track down slow queries, if you hook it into your web framework, and report slow queries. This post will cover doing that with Rails and ActiveRecord, but the principles are similar in most web frameworks.
This post was inspired by this recent post by Sam Lambert, an engineer at GitHub, on how they work on queries there. Many thanks for the inspiration Sam.
Tracking slow queries in Yeller and Rails
One of my favorite features of Rails is ActiveSupport::Notifications
, and the instrumentation Rails sends via that mechanism. We’re going to be using the sql.active_record notification here:, along with the start_processing.action_controller notification to track which controller is affected, and what page it’s on.
# put this in config/initializers/yeller_slow_query.rb
class SlowQueryLogger
MAX_DURATION = 5 # queries that take longer than this number of seconds will be logged
class SlowQuery < StandardError; end
def self.initialize!
ActiveSupport::Notifications.subscribe "start_processing.action_controller" do |name, start, finish, id, payload|
Thread.current[:_yeller_controller] = payload[:controller]
Thread.current[:_yeller_action] = payload[:action]
Thread.current[:_yeller_path] = payload[:path]
end
ActiveSupport::Notifications.subscribe('sql.active_record') do |name, start, finish, id, payload|
duration = finish.to_f - start.to_f
if duration >= MAX_DURATION
begin
raise SlowQuery.new("query took #{duration}, which is more than the max limit: #{MAX_DURATION}")
rescue SlowQuery => e
Yeller::Rails.client.report(
e,
:location => "#{Thread.current[:_yeller_controller]}##{Thread.current[:_yeller_action]}",
:url => Thread.current[:_yeller_path],
:custom_data => {
:slow_query => payload
}
)
end
end
end
end
end
SlowQueryLogger.initialize!
That’s relatively straight forwards - just hook into the notifications, and log an event to Yeller if the sql query takes over 5 seconds.
Now, let’s cover some big wins you get out of using Yeller in particular to log your slow queries:
1. Automatic Diagnosis of Particular bind parameters causing slowness
The above code sends Rails’ SQL bind parameters to Yeller. That means, if you have a query that has something like Post.where("created_at > ?", Time.parse(params[:starting_at])).to_a
, and all the slowness comes from a particular bind parameter (which is noted by ?
in the raw SQL), Yeller will tell you which bind parameter was causing the slowness
2. No more trawling through logs for slow queries
Yeller tracks all your events in one centralized place, doing smart deduplication on your events, so you can tell exactly how often particular slow queries show up.
3. Always know which controller action, and URL caused a slow query
The above code reports both the controller action, and the URL that the query shows up on, so you can track down the exact code that caused it quickly.
4. Know when a slow query started happening, how often it happens and when it finished happening
Yeller ships with full graphs for when events were recorded. It’s easy to figure out if a slow query has happened a lot, happened a few times, or never happened.
Sign up to Yeller Today
I think using an error tracker to log slow queries is super great - it gives you a lot of wins compared to traditional log files, and this lets you fix your slow queries, and get back to working on features that actively benefit your customers.
Of course, many of those wins apply to user facing errors as well as slow queries. You should sign up to Yeller to track your errors..
This is a blog about the development of Yeller, the Exception Tracker with Answers.