It’s been a long wait, but we are back again with the Symfony2 components series. In the 12th post of the series, we cover the Stopwatch component. Even though is one of the smallest ones, that does not mean is not important, as plays a crucial role when we want to profile our code.

The Stopwatch component provides methods to measure execution time

The Stopwatch component provides methods to measure execution time

Installation

The recommended way of installing the component is through Composer:

{
    "require": {
        "symfony/stopwatch": "2.4.*"
    }
}

If you have never used Composer before check out our Composer 101 post.

The component

The Stopwatch component provides useful methods to measure the execution time of pieces of PHP code. In addition to parsing the output of the microtime() function for us, it allows tagging events, measure events in periods and get the max memory usage.

The component was added in Symfony 2.2, extracted from the HttpKernel component, so it was not written from scratch.

Simple example

Let’s see the component in action! In the following example, we try to measure the time spend by PHP to run the code sleep(1), which is obviously 1 second, but there is also some internal processing time such as looking for the function in the functions table:


use Symfony\Component\Stopwatch\Stopwatch;

$stopwatch = new Stopwatch();
$event = $stopwatch->start('test');
sleep(1);
$event->stop();
var_dump($event->getDuration()); // int(1030)
var_dump($event->getMemory()); // int(524288)

Here, we create a Stopwatch object, which returns a StopwatchEvent object when calling the start() method. Each of the events we want to measure have a unique name, in this example, ‘test’ is the event name. Then, after waiting a second, we stop the event and display both the duration in milliseconds and the maximum memory usage.

A much more useful example would be the following one. In this example, we create a function to calculate the nth number in the Fibonacci sequence. As you may know, the nth number in the Fibonacci sequence is the sum of the previous two numbers of the sequence, except the first two, which are 1. So, the complexity of calculating the nth number using a naive approach increases as the number gets bigger. If we want to measure the time spend to calculate the first 35 numbers of the series, would be as simple as this:

use Symfony\Component\Stopwatch\Stopwatch;

function fibonacci($n)
{
    if ($n <= 2) {
        return 1;
    } else {
        return fibonacci($n - 1) + fibonacci($n - 2);
    }
}

$stopwatch = new Stopwatch();
for ($i=1; $i<35;$i++) {
    $eventName = sprintf('Fibonacci %d', $i);
    $event = $stopwatch->start($eventName, 'fibonacci');
    fibonacci($i);
    $event->stop();

    printf("- %s: %dms\n", $eventName, $event->getDuration());
}

We get the expected results, being exponentially slower in every iteration.

- Fibonacci 1: 0ms
- Fibonacci 2: 0ms
...
- Fibonacci 15: 1ms
...
- Fibonacci 20: 16ms
...
- Fibonacci 25: 180ms
...
- Fibonacci 30: 2076ms
- Fibonacci 31: 3806ms
- Fibonacci 32: 5733ms
- Fibonacci 33: 8874ms
- Fibonacci 34: 15672ms
- Fibonacci 35: 24304ms

Periods

The lap() method allows us to measure the time for the same event in periods, which can be useful if what we want to measure is done is several steps. For example, we could measure the total time for reading, parsing and writing the results in another file, but divide it in different periods.

use Symfony\Component\Stopwatch\Stopwatch;
use Symfony\Component\Yaml\Yaml;

$stopwatch = new Stopwatch();

$event = $stopwatch->start('files');

// read file
$contents = file_get_contents('data.yml');
$event->lap();

// parse
$parsed = Yaml::parse($contents);
$event->lap();

// generate output
$output = '';
foreach ($parsed as $user) {
    $output .= $user['name'] . "\n";
}
$event->lap();

// write
file_put_contents('output.txt', $output);
$event->stop();

var_dump($event->getDuration());
foreach ($event->getPeriods() as $period) {
    var_dump($period->getDuration());
}

We get as an output:

int(5)
int(0)
int(4)
int(0)
int(1)

The first result is the total time, while the other four correspond to the four different periods. We can see that the most expensive ones are parsing the YAML file and writing the output to disk.

Sections

Sections are a nice way to group different events, even if they take place in separate parts of our code. For example, we may want to measure all the time spent in IO operations, so we can create a group named “io” and use openSection() and stopSection() to have a logical separation.

In the following example, we have two sections: “io” and “parsing”. Instead of using the actual functions, we call sleep() to make the example clearer.

use Symfony\Component\Stopwatch\Stopwatch;

$stopwatch = new Stopwatch();

// section io (1)
$stopwatch->openSection();
$stopwatch->start('read_file', 'read');
sleep(1);
$stopwatch->stop('read_file');
$stopwatch->stopSection('io');

// section parsing (1)
$stopwatch->openSection();
$stopwatch->start('parse_file', 'yaml');
sleep(1);
$stopwatch->stop('parse_file');
$stopwatch->stopSection('parsing');

// section io (2)
$stopwatch->openSection('io');
$stopwatch->start('write_file', 'write');
sleep(1);
$stopwatch->stop('write_file');
$stopwatch->stopSection('io');

echo "Category 'io'\n";
foreach ($stopwatch->getSectionEvents('io') as $event) {
    printf(" - %s: %d\n", $event->getCategory(), $event->getDuration());
}

echo "Category 'parsing'\n";
foreach ($stopwatch->getSectionEvents('parsing') as $event) {
    printf(" - %s: %d\n", $event->getCategory(), $event->getDuration());
}

Here, in the first two blocks, we open both sections, while in the third block, we open the previously used section “io”. Notice that we only provide the section name when closing it or if it already exists. Finally, we get each of the events for both sections and display their duration times:

Category 'io'
 - default: 2003
 - read: 1001
 - write: 1001
Category 'parsing'
 - default: 1000
 - yaml: 1000

As you see, there is an extra event, named “default”, which holds the sum of the times of all the events of the section.

Extending it

Unlike most Symfony2 components, the Stopwatch component it is really simple with only 3 classes (actually 4, but one of them is internal), and does not provide easy ways to extend it using interfaces and dependency injection, so the only way would be to use inheritance. Even with inheritance, the use of private properties makes it really hard and forces you to rewrite the component almost entirely.

It is nice that the component remains small and works most of the times, but having the option to extend it somehow would be cool for some use-cases, like having information of the number of opened files, cache status or database congestion. However, it is interesting to see how changing properties and methods to private in other components led to cleaner and better solutions.

Internals

Due to its simplicity, there is not much to say about how it works internally. To measure time uses the microtime() function, passing TRUE as an argument to get the result as a float representing the current time in seconds since the Unix epoch accurate to the nearest microsecond. To get the memory usage, the memory_get_usage() function is used, again passing TRUE as parameter to get the real size of memory allocated from system instead of just the one used by emalloc().

Who’s using it?

More info

Photo: Stopwatch, by Julian Lim