Приглашаем посетить
Романтизм (19v-euro-lit.niv.ru)

Passive Identification of Bottlenecks

Previous
Table of Contents
Next

Passive Identification of Bottlenecks

The easiest place to start in identifying large-scale bottlenecks in an existing application is to use passive methods that exploit data you are already collecting or that you can collect easily. The easiest of such methods is to collect page delivery times through Apache access logs.

The common log format does not contain an elapsed time field, but the logger itself supports it. To add the time taken to serve the page (in seconds), you need to add a %T to the LogFormat line:

LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\" %T"
         combinedplus

Then you set the logging mechanism to use this new format:

CustomLog /var/apache-logs/default/access_log combinedplus

You are done. Now your access logs look like this:

66.80.117.2 - - [23/Mar/2003:17:56:44 -0500]
  "GET /~george/index2.php HTTP/1.1" 200 14039 "-" "-" 1
66.80.117.2 - - [23/Mar/2003:17:56:44 -0500]
  "GET /~george/blog/ HTTP/1.1" 200 14039 "-" "-" 3
66.80.117.2 - - [23/Mar/2003:17:56:44 -0500]
  "GET /~george/examples/ HTTP/1.1" 200 14039 "-" "-" 0
66.80.117.2 - - [23/Mar/2003:17:56:44 -0500]
  "GET /~george/index2.php HTTP/1.1" 200 14039 "-" "-" 1
66.80.117.2 - - [23/Mar/2003:17:56:44 -0500]
  "GET /~george/ HTTP/1.1" 200 14039 "-" "-" 1
66.80.117.2 - - [23/Mar/2003:17:56:44 -0500]
  "GET /~george/blog/ HTTP/1.1" 200 14039 "-" "-" 2
66.80.117.2 - - [23/Mar/2003:17:56:44 -0500]
  "GET /~george/blog/ HTTP/1.1" 200 14039 "-" "-" 1
66.80.117.2 - - [23/Mar/2003:17:56:47 -0500]
  "GET /~george/php/ HTTP/1.1" 200 1149 "-" "-" 0

The generation time for the page is the last field in each entry. Clearly, visual inspection of these records will yield results only if there is a critical performance problem with a specific page; otherwise, the resolution is just too low to reach any conclusions from such a small sample size.

What you can do, though, is let the logger run for a number of hours and then post-process the log. Over a large statistical sample, the numbers will become much more relevant.

Given a decent amount of data, you can parse this format with the following script:

#!/usr/local/bin/php

##################
# parse_logs.php #
##################
<?php
$input = $_SERVER['argv'][1];
$fp = fopen($input, "r");
// Match common log format with an additional time parameter
$regex = '/^(\S+) (\S+) (\S+) \[([^:]+):(\d+:\d+:\d+) ([^\]]+)\]'.
' "(\S+) (.*?) (\S+)" (\S+) (\S+) (\S+) (\S+) (\d+)$/';
while(($line = fgets($fp)) !== false) {
    preg_match($regex, $line, $matches);
    $uri = $matches[8];
    $time = $matches[12];
    list($file, $params) = explode('?',$uri, 2);
    $requests[$file][] = $time;
    $requests[$file]['count']++;
    // compute a running average
    $requests[$file]['avg'] =
      ($requests[$file]['avg']*($requests[$file]['count'] - 1)
      + $time)/$requests[$file]['count'];
}

// create a custom sort function to sort based on average request time
$my_sort = create_function('$a, $b', '
        if($a[avg] == $b[avg]) {
            return 0;
        }
        else {
            return ($a[avg] > $b[avg]) ? 1 : -1;
        }');

uasort($requests, $my_sort);
reset($requests);
foreach($requests as $uri => $times) {
    printf("%s %d %2.5f\n", $uri, $times['count'], $times['avg']);
}
?>

You can run the script as follows:

parse_logs.php /var/apache-logs/www.schlossnagle.org/access_log

This yields a list of requested URLs with counts sorted by average delivery time:

/~george//images/016/fr4380620.JPG 105  0.00952
/~george//images/016/mc4359437.JPG 76  0.01316
/index.rdf 36  0.02778
/~george/blog/index.rdf 412  0.03641
/~george/blog/jBlog.css.php 141  0.04965
/~george/blog/archives/000022.html 19  0.05263
/~george/blog/rss.php 18  0.05556
/~george/blog/jBlog_admin.php 8  0.12500
/~george/blog/uploads/020-20d.jBlogThumb.jpg 48  0.14583
/~george/blog/ 296  0. 14865


Previous
Table of Contents
Next