Disable Rails “CACHE” Logging

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:

Post.first.comments.size
Post.first.comments.size

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 config/initializers/active_record_logger.rb:

# 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!