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.
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
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