#!/usr/bin/env ruby
# A quick and dirty log file analyzer

# log file to read
log_file = File.join(File.dirname(__FILE__), '../log/production.log')

# hash of aggregated log entries; keys are Controller#action strings
aggregate_log_entries = {}

# structure to hold aggregate of log entries for a Controller#action
AggregateLogEntry = Struct.new(:completed_in_sum, :rendered_in_sum, :db_in_sum, :num_requests, 
:completed_in_avg)

# parse log file a line at a time
File.open(log_file, 'r') do |f|
  f.readlines.each do |line|
    # check whether line starts new request
    new_request_regexp = /^Processing ([\w\W]+\#[\w\W]+) \(/
    matches = new_request_regexp.match(line)
    
    # is start of a new request in the log
    if matches
      @key = matches[1]
      if aggregate_log_entries.has_key?(@key)
        @ale = aggregate_log_entries[@key]
      else
        @ale = AggregateLogEntry.new(0, 0, 0, 0, 0)
      end
    # not start of new request; check whether it's the last line of a log entry
    else
      end_request_regexp = /^Completed in ([\d\.]+) [\w\W]+ Rendering: ([\d\.]+) [\w\W]+ DB: ([\d\.]+) \(/
      matches = end_request_regexp.match(line)
      if matches
        times = matches[1..3].map { |time| time.to_f }
        @ale.completed_in_sum += times[0]
        @ale.rendered_in_sum += times[1]
        @ale.db_in_sum += times[2]
        @ale.num_requests += 1
        aggregate_log_entries[@key] = @ale
      end
    end
  end
end

# sort the aggregated log entries by average time for request (fastest first)
aggregate_log_entries = aggregate_log_entries.sort_by do |ale_key_and_value|
  ale = ale_key_and_value[1]
  completed_in_avg = ale.completed_in_sum / ale.num_requests
  ale.completed_in_avg = completed_in_avg
  completed_in_avg
end

puts "\nShowing fastest actions first; times are per request\n\n"

# show aggregate info.
aggregate_log_entries.each do |ale_key, ale|
  puts "*" * 30
  ale_rendered_in_avg = ale.rendered_in_sum / ale.num_requests
  ale_rendered_in_percent = ((ale_rendered_in_avg / ale.completed_in_avg) * 100).to_i
  ale_db_avg = ale.db_in_sum / ale.num_requests
  ale_db_percent = ((ale_db_avg / ale.completed_in_avg) * 100).to_i

  puts ale_key + ' completed in an average time of ' + ('%.3f' % ale.completed_in_avg.to_s) +
  ' seconds (' + ('%.1f' % (1 / ale.completed_in_avg).to_s) + ' requests per second)'
  puts "(times based on " + ale.num_requests.to_s + " request" + (ale.num_requests > 1 ? 's' : '') + ")"
  puts 'Rendering took on average ' + ('%.3f' % ale_rendered_in_avg.to_s) + ' seconds (' + ale_rendered_in_percent.to_s + '%)'
  puts 'Database queries took on average ' + ('%.3f' % ale_db_avg.to_s) + ' seconds (' + ale_db_percent.to_s + '%)'
end