varnish timing stats

varnish_timing.py

# varnishncsa -a -w /var/log/varnish/timing.log -F "%{Varnish:handling}x %{Varnish:time_firstbyte}x %r"

from __future__ import print_function

def timing_log():
    with open("/var/log/varnish/timing.log") as f:
        for line in f:
            hitmiss, time, url = line.split(" ", 2)
            if hitmiss != "miss":
                continue
            time = float(time)
            _, url, _ = url.split()
            url, _, _ = url.partition("?")
            # example:
            # if url.endswith(".png"):
            #     continue
            yield time, url

timing_table = {}
for time, url in timing_log():
    n, sum, sumsq, max = timing_table.get(url, (0, 0, 0, 0))
    n += 1
    sum += time
    sumsq += time * time
    max = max if time < max else time
    timing_table[url] = n, sum, sumsq, max

stats = [(url, n, sum, sum / n, (sumsq / n - (sum / n)**2)**0.5, max)
         for url, (n, sum, sumsq, max) in timing_table.items()
         if max > 0.005]
stats.sort(key=lambda x: x[-1]) # sort by max

print("{:50} {:7} {:9} {:9} {:9} {:9}".format("url", "n", "sum", "mean", "stddev", "max"))
for line in stats:
    print("{:50} {:<7} {:<9.0f} {:<9.5} {:<9.5} {:<9.5}".format(*line))