Adding Sidekiq Job Context to ActiveRecord Query Log Tags

Brian John -

Anyone that has worked with Rails for any significant amount of time probably knows that Rails performance tends to be tightly coupled to database query performance. For this reason, it’s extremely valuable to make friends with your local slow query log, where you can identify the queries that are taking the longest and in need of tuning. So, once you’ve identified your slow query(ies), it’s time to get tuning, right? Not so fast. First you need to find out where in the code this query is being generated. If you’re doing things the Rails way and using ActiveRecord to generate these queries, that can be pretty tough since you can’t just grep the code to find that query.

Enter Query Log Tags

Rails 7 added an amazing new feature, Query Log Tags. This feature, when turned on (it’s off by default), will add a comment to the end of every query indicating some context to help you track down where that query came from.

-- Before 
SELECT * FROM my_table_with_bajillions_of_records; 

-- After 
SELECT * FROM my_table_with_bajillions_of_records; /*application:MyApp,controller:my_controller,action:my_action*/

This can save SO much time when trying to figure out what is generating a particularly slow query. To turn it on, you just need to add the following to your config/application.rb:

config.active_record.query_log_tags_enabled = true

As usual Rails comes with sane defaults out of the box. So you’ll get the following context on every query automatically:

  1. Application Name
  2. Controller Name
  3. Controller Action
  4. ActiveJob Class

For most apps, this is all you need. However, we noticed right away that some of our nastiest queries were including only the application name in the comment, like this:

SELECT * FROM my_table_with_bajillions_of_records; /*application:MyApp*/

Great, appreciate that Rails. Pretty sure I already knew the query was coming from my app, but thanks anyway.

So what was the problem? Why weren't we getting more context on these queries?

Sidekiq

We’re big fans of Sidekiq here at BetterUp. In fact, we love it so much that we use a lot of the Enterprise and Pro features. Now, in order to use some of the more advanced features (like Bulk Queueing) you need to use the Sidekiq::Job API directly, rather than through the Rails ActiveJob abstraction. This is all well and good, but you can probably see where this is going: since we’re not using ActiveJob, we don’t get the job name automatically in the query log tags.

So, how do we work around this? ActiveSupport::ExecutionContext to the rescue! It turns out that we can put anything we want in the execution context and then configure query log tags to include that thing in our queries. So we whipped up a really simple Sidekiq Middleware that looks like this:

module SidekiqMiddleware 
  class ActiveSupportExecutionContext 
    def call(_worker_class, job, _queue, &) 
      # If `wrapped` is set, this is an `ActiveJob` which is already in the execution context 
      sidekiq_job_class = job['wrapped'].present? ? nil : job['class'].to_s
      ActiveSupport::ExecutionContext.set(sidekiq_job_class: sidekiq_job_class, &)
    end
  end
end

Then we add the following to our config/application.rb:

config.active_record.query_log_tags << :sidekiq_job_class

And tada! Now we have our Sidekiq Job Class Name in our queries! 🎉🎉🎉

SELECT * FROM my_table_with_bajillions_of_records; /*application:MyApp,sidekiq_job_class:MySidekiqJob*/

About the Author

Brian joined BetterUp in 2017 as a Senior Full Stack Engineer. He lives in the Minneapolis area with his spouse and two sons. Brian is a lover of family time, hiking, biking, video games, and serial optimization.