Track Memory Usage and Runtime of Symfony Commands

This article was originally published at flagbit.de.

If you write lots of Console Commands in your Symfony application you sure want to know more about their memory and time consumption. To collect the necessary data you can make use of the Stopwatch Component.

<?php
use Symfony\Component\Stopwatch\Stopwatch;

$stopwatch = Stopwatch();
$stopwatch->start('my event');
// do something important
$stopwatchEvent = $stopwatch->stop('my event');

echo $stopwatchEvent->getDuration();
echo $stopwatchEvent->getMemory();

First we need to define a service for our Stopwatch in our services.yml to have it available where we want it:

services:
    flagbit_core.stopwatch:
        class: Symfony\Component\Stopwatch\Stopwatch
services.yml

You could implement the Stopwatch in each and every command by hand but this is tiresome and error-prone. So we make use of the Console Events and attach to them:

flagbit_core.console_stopwatch.command:
  class: Flagbit\CoreBundle\EventListener\ConsoleStopwatchListener
  arguments: ["@flagbit_core.stopwatch"]
  tags:
    - { name: kernel.event_listener, event: console.command }
flagbit_core.console_stopwatch.terminate:
  class: Flagbit\CoreBundle\EventListener\ConsoleStopwatchListener
  arguments: ["@flagbit_core.stopwatch"]
  tags:
    - { name: kernel.event_listener, event: console.terminate }

Ok, let’s walk through the ConsoleStopwatchListener. First we start with the Constructor to inject the Stopwatch into our Service:

<?php
namespace Quantum\CoreBundle\EventListener;

use Symfony\Component\Console\Event\ConsoleCommandEvent;
use Symfony\Component\Console\Event\ConsoleTerminateEvent;
use Symfony\Component\Console\Output\OutputInterface;
use Symfony\Component\Stopwatch\Stopwatch;

class ConsoleStopwatchListener
{
    /**
     * @var Stopwatch
     */
    private $stopwatch;

    /**
     * @param Stopwatch $stopwatch
     */
    public function __construct(Stopwatch $stopwatch)
    {
        $this->stopwatch = $stopwatch;
    }

The console.command Event is dispatched just before command execution. So it is the perfect place to start our Stopwatch:

    /**
     * @param ConsoleCommandEvent $event
     */
    public function onConsoleCommand(ConsoleCommandEvent $event)
    {
        $this->stopwatch->start($event->getCommand()->getName());
    }

The second Event we attached to is console.terminate which is triggered after the command has been executed. So we attach our stats to the Output there:

    /**
     * @param ConsoleTerminateEvent $event
     */
    public function onConsoleTerminate(ConsoleTerminateEvent $event)
    {
        $stopwatchEvent = $this->stopwatch->stop($event->getCommand()->getName());

        $output = $event->getOutput();
        if (OutputInterface::VERBOSITY_VERBOSE <= $output->getVerbosity()) {
            $output->writeln(
                '<comment>' . $this->formatDuration($stopwatchEvent->getDuration()) . ' / '
                . $this->formatMemory($stopwatchEvent->getMemory()) . '</comment>'
            );
        }
    }

    /**
     * @param int $bytes Memory in bytes
     * @return string
     */
    private function formatMemory($bytes)
    {
        return round($bytes / 1000 / 1000, 2) . ' MB';
    }

    /**
     * @param int $microseconds Time in microseconds
     * @return string
     */
    private function formatDuration($microseconds)
    {
        return $microseconds / 1000 . ' s';
    }
}

You might also have noticed the Verbosity check which causes our stats only to be printed if the command is run with -v. Symfony >= 2.4 allows to do this a little bit cleaner with $output->isVerbose().