Gotcha of the Day: A Quick and Dirty Approach to Comparing Apache Web App Running Times

For the last couple of days I've been troubleshooting a customer's server. I ended up firing up a replacement server and found myself wanting to compare the two. One simple approach I've used in the past to do this is to add a new Apache log configured to capture timing information. Adding this to Apache is easy, just add the following to the relevant virtual hosts:

CustomLog logs/ssl_timing_log "%{ms}T:%U:%a"  # « Added this custom log
ErrorLog logs/ssl_error_log
TransferLog logs/ssl_access_log

With this configuration in place, Apache now generates ssl_timing_log which has this shape:

0:/index.php:194.28.291.18
4:/report/view-all-customers:194.28.291.18
...

The leading number is the number of seconds it took to generate the page (hopefully 0!).

I collected up this timing data on both the old and new servers and then analyzed the data with this quick and dirty PHP script:

<?php
$fd = fopen($argv[1], "r");

$min = [];
$max = [];
$avg = [];
$cnt = [];
while($line = fgets($fd)) {
  $line = trim($line);
  if(!preg_match('/^[0-9]/', $line)) {
    continue;
  }
  list($t, $u, $i) = explode(":", $line);
  $min[$u] = min(g($min, $u, $t), $t);
  $max[$u] = max(g($max, $u, $t), $t);
  $avg[$u] = isset($avg[$u]) ? ($avg[$u] + $t) / 2 : $t;
  $cnt[$u] = g($cnt, $u, 0) + 1;
}

uasort($cnt, function($a, $b) {
  return $b - $a;
});

$i = 0;
foreach($cnt as $u => $t) {
  echo sprintf("%-80s %0.2f - %0.2f - %0.2f | %d\n", $u, $min[$u], $avg[$u], $max[$u], $cnt[$u]);

  $i++;
  if($i > 50) {
    exit();
  }
}


function g($a, $i, $d = false) {
  return isset($a[$i]) ? $a[$i] : $d;
}
?>

Here's a sample, yet masked, run of the script:

$ sudo php analyze_timing_log.php /var/log/httpd/ssl_timing_log
/xxxxx.xxx                                                                       0.00 - 0.00 - 1.00 | 3777
/xxxxxxxxxx/                                                                     0.00 - 2.00 - 11.00 | 889
/xxxxxxxx/xxxxxxxx/                                                              0.00 - 0.26 - 2.00 | 673
/xx-xxxxxxx/xxxxxxx/xxxxxxxxxxx/xxx/xxxxxxxxx/xx_xxxx.xxx                        0.00 - 0.00 - 0.00 | 363
/xxxxxxxx/xxxxxx/                                                                0.00 - 0.00 - 0.00 | 359
....

The values shown are min, average, max and request count for a given path. The paths are sorted with the most frequently accessed pages at the top.

The results of this testing gave me confidence in the new server. This timing_log hack may be crude, but it runs anywhere Apache does and makes for command-line friendly data sets. It just works.