15 4 / 2012

Running time in Rails logs

Since Rails 3.2, you can add custom tags to your logs. You can define tags by setting config.log_tags in your config file. It accepts array of symbols that matches methods of request object. Additionally, you can also pass lambdas to form custom tags. Here is how it might look like:

config.log_tags = [:uuid, :remote_ip, lambda { |req| Time.now }]

If you want to lear more about logging, I highly recommend The Logger (revised) screencast by Ryan Bates.

One gotcha here: lambdas are evaluated only once at the very beginning of request delegation (in Rails::Rack::Logger middleware. So, our lambda from above will return the same time for every log entry within same request.

I must admit I’m obsessed with performance lately :) Thats why I wanted to customize my logs to include “running time” next to each log entry. I wanted it to look something like this:

Started GET "/users/sign_in" for at 2012-04-15 11:37:21 +0200
[time:0.008] Processing by Devise::SessionsController#new as HTML
[time:0.019]   Rendered devise/_links.erb (0.5ms)
[time:0.019]   Rendered devise/sessions/new.html.erb within layouts/application (7.5ms)
[time:0.022]   Rendered layouts/_navbar.html.erb (0.4ms)
[time:0.022]   Rendered layouts/_skeleton.html.erb (2.3ms)
[time:0.022]   Rendered layouts/_public.html.erb (2.8ms)
[time:0.024] Completed 200 OK in 16ms (Views: 13.5ms | ActiveRecord: 0.0ms)

Let’s get started. First, we need to define custom log tag in our development.rb config file:

config.log_tags = [ lambda { |req| "time:#{Time.now.to_f}" } ]

This will prefix each log entry with tag like this [time:1334480797.098824]. We can later use regexp to replace this with running time.

Next, lets incude some regexp magic in TaggedLogging.tags_text method. Since this is something we only need in development, we can define this at the very bottom of development.rb file.

class ActiveSupport::TaggedLogging
  def tags_text_with_timestamp
    text = tags_text_without_timestamp
    text && text.gsub(/(?<=time\:)([\d\.]+)/) do |m|
      "%#.3f" % (Time.now.to_f - m.to_f).round(3)
  alias_method_chain :tags_text, :timestamp

Note: this code will work only in Rails 3.2.x. I’ve noticed that TaggedLogging class is currently being refactored by rails team, but it won’t be too hard to make this work in future versions of rails.