RailsのSQLログを適当に集計するスクリプト

summarize_sql_log.rb

#!/usr/bin/env ruby

# Usage :
#   summarize_sql_log.rb <log_file_name>
#
# Output example:
#
#     User Load                     Count:1408      775.2000  ms
#     Blog Load                     Count:654       434.3000  ms
#     Comment Load                  Count:454       341.0000  ms
#     ...
#
#     --------------------------------------------------------------------------------
#
#     Worst:
#       User Load => Count:1408 => 775.2000 ms
#       Worst 5 Queries:
#         2056.9ms -> SELECT "users".* FROM "users" WHERE ...
#         1686.4ms -> SELECT "users".* FROM "users" WHERE ...
#         ...
#     --------------------------------------------------------------------------------
#
filename = ARGV.shift

log = open(filename).read

hash = log.lines.map{|_|
  _.gsub(/\e\[[0-9]+m/, '').scan(/^(.+)\((.+)ms\)(.+)$/).flatten.map(&:strip)
}.reject(&:empty?).group_by(&:first).inject({}){|h, (k, v)|
  queries = v.map{|_, t, q| [t.to_f, q]}
  h[k] = {
    :time    => queries.map(&:first).inject(0, :+),
    :count   => queries.count,
    :worst   => queries.max_by(&:first),
    :queries => queries
  }
  h
}

hash.to_a.sort_by{|k,v| v[:time]}.reverse.tap{|_|
  puts '-' * 80
  puts "Summary: "
  max_key_length   = _.map(&:first).map(&:length).max
  max_count_length = _.map(&:last).map{|h| h[:count].to_s}.map(&:length).max
  max_time_length  = _.map(&:last).map{|h| sprintf("%.4f", h[:time])}.map(&:length).max
  _.reject{|k, h| h[:time].nil?}.map{|k, h|
    puts sprintf("%-#{max_key_length}s\tCount:%-#{max_count_length}d\t%-#{max_time_length}.4f ms", k, h[:count], h[:time])
  }

  puts ""
  puts '-' * 80
  puts ""
  puts "Worst:"
  _.first.tap{|k, h|
    puts "  #{k} => Count:#{h[:count]} => #{h[:time]}ms"
    puts "  Worst 5 Queries: "
    h[:queries].sort_by(&:first).reverse[0..4].each{|t,q|
      puts "    #{t}ms -> #{q}"
    }
  }
  puts '-' * 80
}