Identifying slow Rails queries with sqlcommenter
By Mike Coutermarsh, Iheanyi Ekechukwu |
In a large Rails application, it can be tricky to track down where a slow query is coming from in the app.
Solutions to this problem have been steadily improving. First, we had the Marginalia gem, which adds comments to all your queries. This allows you to see which controller or job a query came from by reading your logs.
As of Rails 7, Marginalia has become a native feature to Rails. No more gem needed. While this is a great improvement, we can still take our Rails query comments one step further.
Rails + sqlcommenter
Sqlcommenter is a query comment format created by Google and widely adopted by many tools and languages. It’s more easily read by machines than the default format currently used by Rails.
Default Rails:
SELECT * FROM `users` ORDER BY `users`.`id` DESC LIMIT 1 /*application:Api,controller:users,action:show*/
sqlcommenter:
SELECT * FROM `users` ORDER BY `users`.`id` DESC LIMIT 1 /*application='Api',controller='users',action='show'*/
It’s a small change that makes our query comments machine-readable and more valuable in logging and performance monitoring tools.
Enabling in Rails 7
To make it easier to use sqlcommenter with Rails, we’ve created a gem for Rails 7 that enables sqlcommenter.
To try it out, add the following to your Gemfile:
gem "activerecord-sql_commenter", require: "active_record/sql_commenter"
Then, in your Rails config/application.rb file, enable query log tagging:
# config/application.rb config.active_record.query_log_tags_enabled = true config.active_record.query_log_tags = [ :application, :controller, :action, :job ] config.active_record.cache_query_log_tags = true
You can learn about each config option in the Rails Query Logs documentation here.
Testing it out
Once set up, you can open up a Rails console and run a query to test it out.
$ rails console [1] pry(main)> User.first
You should see your application name in sqlcommenter format.
User Load (0.6ms) SELECT `user`.* FROM `user` ORDER BY `user`.`id` ASC LIMIT 1 /*application='ApiBb'*/
Using annotate
If you need even more detail for a specific query, Rails 7 also added the annotate method, which lets you add a comment to a query.
For example, the following query will add source='user_metrics_runner' as a comment:
[3] pry(main)> User.where(name: "iheanyi").annotate("source='user_metrics_runner'")
User Load (0.5ms) SELECT `user`.* FROM `user` WHERE `user`.`name` = 'iheanyi'
/* source='user_metrics_runner' */
This is useful in situations where the default query log tags aren’t enough.
Using with PlanetScale Query Insights
PlanetScale Query Insights, our built-in query debugging and analysis tool, is compatible with sqlcommenter. Any query that takes over 1 second to run will get recorded and tagged with the values you’ve set in your sql comments.
For example, here is a slow query from our own application:
SELECT schema_snapshot.* FROM schema_snapshot WHERE schema_snapshot.ready = true AND created_at > :created_at AND schema_snapshot.deleted_at IS NULL ORDER BY schema_snapshot.id ASC LIMIT 10000 /*application='ApiBb,job='ScheduleSnapshotJob'*/
Using Insights and tags on the slow query, we were able to find exactly where this query was coming from. This enabled us to quickly find and fix the issue in our application.
You can try out Query Insights today by signing up for a PlanetScale account and navigating to "Insights" in the dashboard.
If you're using a Rails application, be sure to check out the Rails + PlanetScale quickstart and our Rails sqlcommenter gem. This powerful combination, Rails + sqlcommenter + Insights, can greatly improve your query debugging experience.