ltsv access log summary tool

isucon2夏期講習 http://blog.nomadscafe.jp/2013/08/isucon.html で遊んだ時に作った。

--since='2013-11-05T02:23' とかやるとその時刻以前のログを無視する。単純な辞書比較だが、秒を指定する必要のないときに省略できたりするのでこれはこれでいいかも。ltsvのtimeの部分がtime_localとかtime_iso8601とかあって対応するの面倒だったし。

#!/usr/bin/env ruby

# cat access.log | ruby parse.rb
# if --since is given, logs before the specified time are ignored
#  (by string comparison)
# eg. --since='2013-11-05T02:23'

# supported accesslog format : http://i2bskn.hateblo.jp/entry/2013/05/14/003726 style
#
#  log_format ltsv "time:$time_iso8601"
#                  "\thost:$remote_addr"
#                  "\txff:$http_x_forwarded_for"
#                  "\tmethod:$request_method"
#                  "\tpath:$request_uri"
#                  "\tstatus:$status"
#                  "\tua:$http_user_agent"
#                  "\treq_size:$request_length"
#                  "\treq_time:$request_time"
#                  "\tres_size:$bytes_sent"
#                  "\tbody_size:$body_bytes_sent"
#                  "\tapp_time:$upstream_response_time";
#
# time:2013-11-05T02:23:14+09:00  host:202.232.134.129    xff:-   method:GET      path:/  status:200      ua:Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/30.0.1599.101 Safari/537.36  req_size:599    req_time:0.005  res_size:2951   body_size:2711  app_time:0.005

since = nil
if ARGV.length
        m = /--since=(.*)/.match(ARGV[0])
        since = m[1] if m
end

logs = []
while l = STDIN.gets
        l.strip!
        log = {}
        l.split("\t").each{|kv|
                k,v = kv.split(":", 2)
                k = k.to_sym
                if k == :req_time || k == :app_time
                        log[k] = v.to_f
                else
                        log[k] = v
                end
        }
        if !since.nil? && log[:time] < since
                next
        end
        logs.push(log)
end

template = {
        :path => '',
        :mathod => '',
        :total_time => 0,
        :total_count => 0,
        :avg_time => 0,
}
tmp = {}

logs.each {|log|
        path = log[:path]
        method = log[:method]
        key = method+'::'+path
        if tmp[key].nil?
                tmp[key] = template.clone
                tmp[key][:path] = path
                tmp[key][:method] = method
        end
        tmp[key][:total_time] += log[:req_time]
        tmp[key][:total_count] += 1
}

paths = []
tmp.to_a.each {|path, detail|
        detail[:avg_time] = detail[:total_time] / detail[:total_count]
        paths.push(detail)
}

def print_paths(paths)
        puts "\tavg\ttotal\tcount\tmethod\tpath"
        paths.each {|path|
                puts "\t#{sprintf("%.2f",path[:avg_time])}\t#{sprintf("%.2f",path[:total_time])}\t#{path[:total_count]}\t#{path[:method]}\t#{path[:path]}"
        }
end

puts "==============="
puts "sort by avg_time"
paths.sort! {|a, b| b[:avg_time] <=> a[:avg_time] }
print_paths(paths)

puts "==============="
puts "sort by total_time"
paths.sort! {|a, b| b[:total_time] <=> a[:total_time] }
print_paths(paths)

puts "==============="
puts "sort by total_count"
paths.sort! {|a, b| b[:total_count] <=> a[:total_count] }
print_paths(paths)

出力されるログ

sort by avg_time
        avg     total   count   method  path
        9.46    2753.95 291     GET     /ticket/1
        5.28    1510.27 286     GET     /artist/1
        4.54    1329.08 293     GET     /
        4.37    454.62  104     POST    /buy
        3.82    3.82    1       GET     /admin/order.csv
        1.22    2.45    2       POST    /admin
        0.15    0.15    1       GET     /artist/2
        0.03    4.28    130     GET     /js/jquery-ui-1.8.24.custom.min.js
        0.02    2.88    136     GET     /js/jquery-1.8.2.min.js
        0.02    2.62    143     GET     /images/isucon_title.jpg
        0.02    2.44    134     GET     /css/ui-lightness/jquery-ui-1.8.24.custom.css
        0.01    1.11    122     GET     /css/isucon2.css
        0.01    0.86    114     GET     /js/isucon2.js
===============
sort by total_time
        avg     total   count   method  path
        9.46    2753.95 291     GET     /ticket/1
        5.28    1510.27 286     GET     /artist/1
        4.54    1329.08 293     GET     /
        4.37    454.62  104     POST    /buy
        0.03    4.28    130     GET     /js/jquery-ui-1.8.24.custom.min.js
        3.82    3.82    1       GET     /admin/order.csv
        0.02    2.88    136     GET     /js/jquery-1.8.2.min.js
        0.02    2.62    143     GET     /images/isucon_title.jpg
        1.22    2.45    2       POST    /admin
        0.02    2.44    134     GET     /css/ui-lightness/jquery-ui-1.8.24.custom.css
        0.01    1.11    122     GET     /css/isucon2.css
        0.01    0.86    114     GET     /js/isucon2.js
        0.15    0.15    1       GET     /artist/2
===============
sort by total_count
        avg     total   count   method  path
        4.54    1329.08 293     GET     /
        9.46    2753.95 291     GET     /ticket/1
        5.28    1510.27 286     GET     /artist/1
        0.02    2.62    143     GET     /images/isucon_title.jpg
        0.02    2.88    136     GET     /js/jquery-1.8.2.min.js
        0.02    2.44    134     GET     /css/ui-lightness/jquery-ui-1.8.24.custom.css
        0.03    4.28    130     GET     /js/jquery-ui-1.8.24.custom.min.js
        0.01    1.11    122     GET     /css/isucon2.css
        0.01    0.86    114     GET     /js/isucon2.js
        4.37    454.62  104     POST    /buy
        1.22    2.45    2       POST    /admin
        3.82    3.82    1       GET     /admin/order.csv
        0.15    0.15    1       GET     /artist/2