Rails 2.2 Log Format + pl_analyze = Ugly

A seeming sensible choice was made in 2.2 to change the log format to show times in milliseconds instead of seconds. I can understand why a Ruby programmer would find that decimal-less output “beautiful,” and I certainly wasn’t objecting.

That is, until I used my new favorite tool, pl_analyze, to check my log times, and remembered that pl_analyze was written in the early oughts, when only seconds would do. Once the times change to milliseconds, the formatting of pl_analyze becomes fairly unparsable.

Faced with this challenge, I had to pick between the better solution (patch pl_analyze) or the faster solution (patch Rails log). Guess which choice the one-full-time-programmer-company took?

I’ve attached ugly Rails patch if anyone else wants to save a couple minutes figuring this out themselves. It makes the Rails 2.2 logging format compatible with pl_analyze again.


2 Replies to “Rails 2.2 Log Format + pl_analyze = Ugly”

  1. How about hacking the pl_analyze gem to expect milliseconds?

    sudo pico /usr/lib/ruby/gems/1.8/gems/production_log_analyzer-1.5.1/lib/production_log/analyzer.rb

    @request_times[entry_page] << entry.request_time / 1000
    @db_times[entry_page] << entry.db_time / 1000
    @render_times[entry_page] << entry.render_time / 1000

  2. Actually that doesn’t quite cut it. Don’t do it. Better to edit the parser itself.

    sudo pico /usr/lib/ruby/gems/1.8/gems/production_log_analyzer-1.5.1/lib/production_log/parser.rb

    and replace the when /^Completed clauses in the def parse(entry) function.

    when /^Completed in (d+)ms (View: (d+), DB: (d+)/ then
    next if @in_component > 0
    @request_time = $1.to_f / 1000
    @render_time = $2.to_f / 1000
    @db_time = $3.to_f / 1000
    when /^Completed in ([S]+) (DB: ([S]+)/ then # Redirect
    next if @in_component > 0
    @request_time = $1.to_f / 1000
    @render_time = 0
    @db_time = $2.to_f / 1000

Leave a Reply

Your email address will not be published. Required fields are marked *