HAProxy log analyzer to show response latency distribution from the console

analyze_haproxy_performance.pl

#!/usr/bin/perl
# HAProxy Performance Statistics
# by Steve Kamerman
#
# To use, pipe your HAProxy log with timing information (like "0/0/1/1/3 200") to 
# this script.  It will output min, max, med, avg and a latency distribution graph.
#
# Info on timing logging in HAProxy: http://code.google.com/p/haproxy-docs/wiki/TimingEvents
#

my @timings;
@dist_breakpoints = (5,10,20,30,40,50,60,70,80,90,100,110,120,130,140,150,160,170,180,190,200);
my %dist;

foreach (@dist_breakpoints) {
	$dist{$_} = 0;
}
$dist{'Over'} = 0;

while (<>) {
	if (m#\d+/\d+/\d+/(\d+)/\d+ (\d+)#){
		next if ($2 >= 300);
		push(@timings, $1);
		$dist{get_breakpoint($1)}++;
	}
}

sort(@timings);
$total = scalar(@timings);
$med = $timings[int($total/2)];
$sum = 0;
$min = 1000;
$max = 0;
foreach (@timings) {
	$sum += $_;
	if ($_ < $min) {$min=$_;}
	if ($_ > $max) {$max=$_;}
}
$avg = int($sum / $total);

$max_count = 0;
foreach (@dist_breakpoints) {
	if ($dist{$_} > $max_count) {$max_count=$dist{$_};}
}
if ($dist{'Over'} > $max_count) {$max_count=$dist{'Over'};}

print "Total Requests: $total\n";
print "Min: $min ms\n";
print "Max: $max ms\n";
print "Med: $med ms\n";
print "Avg: $avg ms\n";
print "+----------------------\n";
print "| Latency Distribution \n";
print "+----------------------\n";

foreach (@dist_breakpoints) {
	printf("%5s: %s\n", $_, dist_line($dist{$_}, $total, $max_count));
}
printf("%5s: %s\n", 'Over', dist_line($dist{'Over'}, $total, $max_count));

sub dist_line {
	($count, $total, $max_count) = @_;
	$max_char = 100;
	$pct = ($count/$total)*100;
	$chars = ($count/$max_count)*$max_char;
	$line = '';
	foreach (0..$chars) {$line .= '#';}
	$line .= sprintf(" (%.2f%%, %s)", $pct, $count);
	return $line;
}

sub get_breakpoint {
	$val = shift;
	foreach (@dist_breakpoints) {
		if ($val < $_) {return $_;}
	}
	return 'Over';
}

sample_output.txt

# cat haproxy.log.1 | ./analyze_haproxy_performance.pl
Total Requests: 502199
Min: 0 ms
Max: 2563 ms
Med: 5 ms
Avg: 14 ms
+----------------------
| Latency Distribution
+----------------------
    5: ##################################################################################### (33.33%, 167369)
   10: ##################################################################################################### (39.40%, 197883)
   20: ##### (1.77%, 8887)
   30: ###### (1.98%, 9937)
   40: #################### (7.59%, 38097)
   50: ################################### (13.71%, 68852)
   60: ##### (1.71%, 8605)
   70: # (0.35%, 1733)
   80: # (0.08%, 406)
   90: # (0.02%, 124)
  100: # (0.02%, 104)
  110: # (0.01%, 73)
  120: # (0.01%, 36)
  130: # (0.01%, 38)
  140: # (0.00%, 12)
  150: # (0.00%, 3)
  160: # (0.00%, 4)
  170: # (0.00%, 7)
  180: # (0.00%, 0)
  190: # (0.00%, 1)
  200: # (0.00%, 2)
 Over: # (0.01%, 26)

I'm not sure what the difference is, but you only need to tweak like 21: if (m#\d+/\d+/\d+/(\d+)/\d+ (\d+)#){. The regular expression can be modified to capture the field that you want to analyze. Currently it's looking at the fourth numeric field in the timing data.

[Edit] According to the documentation (http://www.haproxy.org/download/1.4/doc/configuration.txt), the tcp log format looks something like this:

Feb  6 12:12:56 localhost \
          haproxy[14387]: 10.0.1.2:33313 [06/Feb/2009:12:12:51.443] fnt \
          bck/srv1 0/0/5007 212 -- 0/0/0/0/3 0/0

in this case, the 0/0/5007 bit is the timing data, and the 5007 is the total request duration from start to finish, so you can change line 21 like this:

# Old line for HTTP log: 
if (m#\d+/\d+/\d+/(\d+)/\d+ (\d+)#){

# New line for TCP log
if (m# \d+/\d+/(\d+) \d+#){

# Also, delete this line (22) as it ignores irrelevant HTTP requests:
next if ($2 >= 300);

That should do it :)

Awesome tool, thanks a lot. It was very useful to debug some issues.