ActiveRecord logging is great because it shows every SQL query that hits your database. You can easily pinpoint slow, useless, or duplicate queries and optimize your code accordingly.
However, one thing I don’t like is how cached queries are logged. Say you have the following code:
Thanks to SQL caching, ActiveRecord will hit the database only once per needed query. But it will still log them twice, prefixed with
CACHE on the second time:
Post Load (0.6ms) SELECT `posts`.* FROM `posts` LIMIT 1 (0.8ms) SELECT COUNT(*) FROM `comments` WHERE `comments`.`post_id` = 1 CACHE (0.0ms) SELECT `posts`.* FROM `posts` LIMIT 1 CACHE (0.0ms) SELECT COUNT(*) FROM `comments` WHERE `comments`.`post_id` = 1
These last two lines aren’t actual queries. They don’t hit the database, always take 0.0ms, and pollute your logs.
To fix this, here’s what I put in
# Create logger that ignores messages containing “CACHE” class CacheFreeLogger < ::Logger def debug(message, *args, &block) super unless message.include? 'CACHE' end end # Overwrite ActiveRecord’s logger ActiveRecord::Base.logger = ActiveSupport::TaggedLogging.new( CacheFreeLogger.new(STDOUT)) unless Rails.env.test?
There you go, no more
CACHE logs. Happy SQL optimizing!
7 steps to help you design websites for the modern age