We have been working on PerformanceMeterBundle that logs HTTP requests. Another important metric for a web application is database query execution time. Doctrine DBAL is currently part of the Symfony standard edition (required by Doctrine ORM). Doctrine is the most commonly used ORM in Symfony applications that requires a database layer. We will add a new feature that logs queries execution time, if the application is using DoctrineBundle.

PerformanceMeterBundle V0.0.2

Before thinking about this Doctrine stuff, we need to add support for multiple loggers first. Currently, configuring performance_meter: is enough to get it to work. Since we are planning to measure database queries as well, users will need to configure which metrics they are interested in. To support multiple loggers, the bundle should be able to support a configuration like

performance_meter:
  loggers:
    logger1:
    logger2:

We should make sure that:
1. Configuration is loaded
2. Request loggers are registered
3. KernelEventSubscriber is registered
4. KernelEventSubscriber accepts and uses 2 request loggers

Multiple loggers

1. Configuration loading

Replace tests/DependencyInjection/Fixtures/config.yml with the previous configuration, now the tests fail with Unrecognized option "loggers" under "performance_meter". We just need to make the tests pass to ensure the configuration is accepted.
We update src/DependencyInjection/Configuration.php to support the new option, before the return statement, add an option loggers of type array of arrays

$loggers = $root->children()->arrayNode('loggers')->prototype('array');

2. Register request loggers

First, let’s rename Tests\DependencyInjection\PerformanceMeterExtensionTest::test_registers_request_logger() to test_registers_request_loggers since we now expect multiple loggers. Second, change the test case to reflect the new expectation, we just wrap the previous code in a foreach as following

public function test_registers_request_loggers()
{
    $container = $this->createContainer();
    $container->compile();

    foreach (array('logger1', 'logger2') as $logger) {
        $requestLoggerDefinition = $container->getDefinition('performance_meter.request.' . $logger);
        $this->assertEquals(RequestLogger::class, $requestLoggerDefinition->getClass());
        $this->assertEquals(
            array(
                new Reference('logger', ContainerInterface::NULL_ON_INVALID_REFERENCE)
            ),
            $requestLoggerDefinition->getArguments()
        );
    }
}

This change should fail the tests with You have requested a non-existent service "performance_meter.request.logger1".
Until now, we defined the request logger service in Resources/config/services.xml. This was a simple method to do it, however now we have a dynamic number of loggers, so the XML method is not a valid option anymore. We need to register those services manually.
The ContainerBuilder passed to the extension’s load method offers a flexible interface to manipulate definitions. Let’s add a method to src/DependencyInjection/PerformanceMeterExtension.php that will programatically register all the loggers

private function registerRequestLoggers(array $config, ContainerBuilder $container)
{
    $loggerReference = new Reference('logger', ContainerInterface::NULL_ON_INVALID_REFERENCE);
    foreach ($config['loggers'] as $name => $logger) {
        $id = 'performance_meter.request.' . $name;
        $container->register($id, RequestLogger::class)->addArgument($loggerReference);
    }
}

Add a call to it $this->registerRequestLoggers($config, $container) after $loader->load('services.xml').

3. KernelEventSubscriber

In Tests\DependencyInjection\PerformanceMeterExtensionTest::test_registers_kernel_event_subscriber() we expect the constructor to have one argument: a Reference to performance_meter.request_logger. Which is obviously wrong since we should expect 2 loggers with the sample configuration we have. Instead of changing the constructor argument to an array, we will use a method addLogger for an easier to use interface.
Let’s update the test case to reflect the new expectation. The class is not changing, we only need to change the second assert to:

$this->assertEquals(
    array(
        array(
            'addLogger',
            array(
                new Reference('performance_meter.request.logger1')
            )
        ),
        array(
            'addLogger',
            array(
                new Reference('performance_meter.request.logger2')
            )
        ),
    )
    ,
    $eventSubscriberDefinition->getMethodCalls()
);

We will update registerRequestLoggers and add a method call to addLogger for each logger, the final code should look like this (the 2 added lines are commented):

private function registerRequestLoggers(array $config, ContainerBuilder $container)
{
    $loggerReference = new Reference('logger', ContainerInterface::NULL_ON_INVALID_REFERENCE);
    //Get the subscriber definition
    $eventSubscriberDefinition = $container->getDefinition('performance_meter.kernel_events_subscriber');
    foreach ($config['loggers'] as $name => $logger) {
        $id = 'performance_meter.request.' . $name;
        $container->register($id, RequestLogger::class)->addArgument($loggerReference);
        //Add a method call for this logger
        $eventSubscriberDefinition->addMethodCall('addLogger', array(new Reference($id)));
    }
}

4. KernelEventSubscriber accepts multiple loggers

Next, is to make sure KernelEventSubscriber will call all loggers on kernel.response event.
In Tests\KernelEventsSubscriberTest::test_logs_request_on_kernel_response change
$mockRequestLogger->expects($this->once())
to
$mockRequestLogger->expects($this->exactly(2)).
Remove $mockRequestLogger argument when instanciating KernelEventsSubscriber. Add $eventSubscriber->addLogger($mockRequestLogger); twice right after after $eventSubscriber instantiation $eventSubscriber->addLogger($mockRequestLogger); (we add the same logger twice).

The tests should fail miserably, we need to update Skafandri\PerformanceMeterBundle\KernelEventsSubscriber.
1. Remove the request logger from the constructor
2. Rename the property requestLogger to requestLoggers and give it an initial value of array()
3. Add addLogger method

public function addLogger(RequestLogger $logger)
{
    $this->requestLoggers[] = $logger;
}
  1. In onKernelResponse method, replace $this->requestLogger->logRequest($event->getRequest(), $duration); with
foreach ($this->requestLoggers as $logger) {
    $logger->logRequest($event->getRequest(), $duration);
}

Tests are green, all good. Or not? When your tests are green, as they always should be, you are able to clean and refactor without fear. Forget about the did I possibly broke something? feeling. My favorite refactoring technique is deleting code. Nothing can make a code base cleaner than deleting unnecessary code. Let’s delete some code from Resources/config/services.xml
All the performance_meter.request_logger service definition can go away, green tests confirmed.
The EventSubscriber argument can go away, green tests confirmed.

Wait a minute, we just refactored some configuration, that’s not code. I like to answer with a question. Consider the following function:

public function getPort()
{
    $line = explode("\n", file_get_contents('config.cfg'))[1];
    return explode(":", $line)[1];
}

and the following config.cfg

host: hostname
port: 300
memory_limit: 600

A call to getPort should return 300.
If you change 1 to 2 in the first line of the function, getPort will return 600.
If you swap port and memory_limit in the config, getPort will return 600.
Now getPort started to return a different value than before, was it a code change or a configuration change?
My answer: It was a code change.

Multiple logger types

So far we support multiple loggers but we assume they are all RequestLoggers since is the only supported logger. We are about to add an SQLLogger, so the user must configure the metric for each logger. Update the configuration fixture to

performance_meter:
  loggers:
    logger1:
      metric: request
    logger2:
      metric: request
    logger3:
      metric: sql

Running our test suite, it fails with Unrecognized option "metric". To add this option, in src/DependencyInjection/Configuration.php before the return statement, for each item in loggers, add an option metric of type scalar.

$loggers = $root->children()->arrayNode('loggers')->prototype('array');
$loggers->children()->scalarNode('metric');

return $tree;

Now PerformanceMeterExtensionTest::test_registers_kernel_event_subscriber fails because the bundle registered a logger3. To fix it, in src/DependencyInjection/PerformanceMeterExtension.php registerRequestLoggers should only register loggers of metric request. So at the beginning of the foreach, we add a simple check.

if ($logger['metric'] !== 'request') {
    continue;
}

So all we did is: support a metric configuration option for each logger and load RequestLoggers only when metric=request. Now we are ready to start working on an SQLLogger, or any new logger.

SQL logger

When we worked on RequestLogger, we plugged our Logger to the application using an event subscriber. This technique works for most Symfony components and bundles. Most of them dispatch useful events (Requests, Console, Security, Twig..). Doctrine has a lot of useful events as well, except for start/finish query which is what we need now. So a quick tour in Doctrine code might be fruiteful.
We can start by requiring doctrine bundle do get the source code composer require doctrine/doctrine-bundle --dev.
We know that every interaction with the database happens through a connection. So we can start by inspecting Doctrine\DBAL\Connection. The query method’s description says Executes an SQL statement. Seems exactly what we are looking for. Method source at the time of writing:

public function query()
{
    $this->connect();
    $args = func_get_args();

    $logger = $this->_config->getSQLLogger();
    if ($logger) {
        $logger->startQuery($args[0]);
    }
    try {
        switch (func_num_args()) {
            case 1:
                $statement = $this->_conn->query($args[0]);
                break;
            case 2:
                $statement = $this->_conn->query($args[0], $args[1]);
                break;
            default:
                $statement = call_user_func_array(array($this->_conn, 'query'), $args);
                break;
        }
    } catch (\Exception $ex) {
        throw DBALException::driverExceptionDuringQuery($this->_driver, $ex, $args[0]);
    }
    $statement->setFetchMode($this->defaultFetchMode);
    if ($logger) {
        $logger->stopQuery();
    }
    return $statement;
}

The interesting lines are:

$logger = $this->_config->getSQLLogger();
$logger->startQuery($args[0]);
$logger->stopQuery();

So if a logger is configured, it will be called before and after a query. $_config is an instance of Doctrine\DBAL\Configuration which has a nice setSQLLogger method, we need to call that method with our logger and it must implement Doctrine\DBAL\Logging\SQLLogger interface. We need to find where this class is being instantiated. A search with the FQCN in the doctrine source leads to vendor/doctrine/doctrine-bundle/Resources/config/dbal.xml. The relevant part is:

<parameter key="doctrine.dbal.configuration.class">Doctrine\DBAL\Configuration</parameter>
<service id="doctrine.dbal.connection.configuration"
  class="%doctrine.dbal.configuration.class%" public="false" abstract="true" />

So DoctrineBundle registers a connection configuration as service, so all we need to do is to find the configuration definition and add the correct method call to it. But there is a little problem: that service is private and abstract. A little bit of more digging, in DoctrineBundle\DependencyInjection\DoctrineExtension::loadDbalConnection the first line looks like

$configuration = $container->setDefinition(sprintf('doctrine.dbal.%s_connection.configuration', $name), 
new DefinitionDecorator('doctrine.dbal.connection.configuration'));`

So it will create a configuration service for each connection, we should consider this finding when writing a test case. Later in the Doctrine extension, it also registers a parameter with all connections named doctrine.connections.
The Connection class accepts a single logger. Since we need multiple loggers, we will have to pass a class that implements SQLLogger but supports multiple loggers. Luckily there is Doctrine\DBAL\Logging\LoggerChain which like it’s name suggests, chains multiple loggers.

So we know what we have to do:
1. Our SQLLogger should implement Doctrine\DBAL\Logging\SQLLogger interface.
2. Register a LoggerChain with references to all loggers.
3. Add a call configuration->setSQLLogger with a reference to our LoggerChain.

1. SQLLogger interface implementation

The interface is very clear, having only 2 methods startQuery and stopQuery.On stopQuery, we expect our logger to log an info with a context matching the arguments passed to startQuery. And it shouldn’t break in case there is no logger.

tests/SQLLoggerTest.php

<?php

namespace Skafandri\PerformanceMeterBundle\Tests;

use PHPUnit\Framework\TestCase;
use Psr\Log\LoggerInterface;
use Skafandri\PerformanceMeterBundle\SQLLogger;

class SQLLoggerTest extends TestCase
{
    public function test_logs_request()
    {
        $mockLogger = $this->getMockBuilder(LoggerInterface::class)->getMock();
        $mockLogger->expects($this->once())
            ->method('info')
            ->with(
                'performance_meter.sql_query',
                $this->callback(function ($context) {
                    return
                        'sql' === $context['sql'] &&
                        array('params') === $context['params'] &&
                        is_numeric($context['duration']);
                })
            );

        $sqlLogger = new SQLLogger($mockLogger);
        $sqlLogger->startQuery('sql', array('params'));
        $sqlLogger->stopQuery();
    }

    public function test_doesnt_break_without_logger()
    {
        $sqlLogger = new SQLLogger();
        $sqlLogger->startQuery('sql', array('params'));
        $sqlLogger->stopQuery();
    }
}

The implementation is only slightly different from RequestLogger

src/SQLLogger.php

<?php

namespace Skafandri\PerformanceMeterBundle;

use Psr\Log\LoggerInterface;
use Symfony\Component\Stopwatch\Stopwatch;

class SQLLogger implements \Doctrine\DBAL\Logging\SQLLogger
{

    /** @var LoggerInterface */
    private $logger;

    /** @var Stopwatch */
    private $stopwatch;

    private $sql;
    private $params;

    /**
     * SQLLogger constructor.
     * @param LoggerInterface|null $logger
     */
    public function __construct(LoggerInterface $logger = null)
    {
        $this->logger = $logger;
        $this->stopwatch = new Stopwatch();
    }

    /**
     * @inheritdoc
     */
    public function startQuery($sql, array $params = null, array $types = null)
    {
        $this->sql = $sql;
        $this->params = $params;
        $this->stopwatch->start('query');
    }

    /**
     * @inheritdoc
     */
    public function stopQuery()
    {
        if (!$this->logger) {
            return;
        }
        $duration = $this->stopwatch->stop('query')->getDuration();
        $context = array(
            'sql' => $this->sql,
            'params' => $this->params,
            'duration' => $duration
        );
        $this->logger->info('performance_meter.sql_query', $context);
    }
}

2. Register a LoggerChain

It must be of class LoggerChain and have a method call to addLogger with logger3. We add the test case to tests/DependencyInjection/PerformanceMeterExtensionTest.php

public function test_registers_logger_chain()
{
    $container = $this->createContainer();
    $container->compile();

    $loggerChainDefinition = $container->getDefinition('performance_meter.logger_chain');

    $this->assertEquals(LoggerChain::class, $loggerChainDefinition->getClass());
    $this->assertEquals(
        array(
            array(
                'addLogger',
                array(
                    new Reference('performance_meter.sql.logger3')
                )
            ),
        )
        ,
        $loggerChainDefinition->getMethodCalls()
    );
}

The first test fails with You have requested a non-existent service "performance_meter.logger_chain", we just need to register the service in Resources/config/services.xml <service id="performance_meter.logger_chain" class="Doctrine\DBAL\Logging\LoggerChain"/>. Now it fails to assert that getMethodCalls returns the expected calls. We will add registerSQLLoggers method in src/DependencyInjection/PerformanceMeterExtension.php

private function registerSQLLoggers(array $config, ContainerBuilder $container)
{
    $loggerReference = new Reference('logger', ContainerInterface::NULL_ON_INVALID_REFERENCE);
    $loggerChainDefinition = $container->getDefinition('performance_meter.logger_chain');
    foreach ($config['loggers'] as $name => $logger) {
        if ($logger['metric'] !== 'sql') {
            continue;
        }
        $id = 'performance_meter.sql.' . $name;
        $container->register($id, SQLLogger::class)->addArgument($loggerReference);
        $loggerChainDefinition->addMethodCall('addLogger', array(new Reference($id)));
    }
}

and add a call to it right after $this->registerRequestLoggers.

3. Inject LoggerChain in connection configurations

Remember that DoctrineBundle will register a configuration service for each connection. Let’s first append a doctrine configuration to our fixture config.yml

doctrine:
  dbal:
    connections:
      conn1:
      conn2:

If we run the test suite after this change, it would fail with There is no extension able to load the configuration for "doctrine". That’s simply because the Doctrine extension is not loaded. To load it, add $container->registerExtension(new DoctrineExtension()); after $container->registerExtension(new PerformanceMeterExtension()); in PerformanceMeterExtensionTest::createContainer. Now the tests pass again.

Remember that DoctrineBundle registers configuration services with sprintf('doctrine.dbal.%s_connection.configuration', $name).
The expected result is straight forward, 'doctrine.dbal.conn1_connection.configuration' and 'doctrine.dbal.conn2_connection.configuration' should both have performance_meter.logger_chain as SQLLogger. We add another test case to PerformanceMeterExtensionTest

public function test_calls_doctrine_connection_configuration_setSQLLogger_with_logger_chain()
{
    $container = $this->createContainer();
    $container->compile();

    foreach (array('conn1', 'conn2') as $name) {
        $configurationDefinition = $container->getDefinition('doctrine.dbal.' . $name . '_connection.configuration');
        $this->assertEquals(
            array(
                array(
                    'setSQLLogger',
                    array(
                        new Reference('performance_meter.logger_chain')
                    )
                ),
            )
            ,
            $configurationDefinition->getMethodCalls()
        );
    }
}

The assert obviously fails. Let’s start with a first attempt, we know how to manipulate definitions and how to add method calls. Also DoctrineBundle registers a parameter with all connections named doctrine.connections. So in PerformanceMeterExtension::load, after $this->registerSQLLoggers($config, $container); we can add

foreach ($container->getParameter('doctrine.connections') as $connection) {
  $container->getDefinition($connection . '.configuration')
      ->addMethodCall('setSQLLogger', array(new Reference('performance_meter.logger_chain')));
}

The tests fail with You have requested a non-existent parameter "doctrine.connections". Why is that? To understand what happened let’s take a look at Symfony\Component\DependencyInjection\Compiler\MergeExtensionConfigurationPass which has a single method. But it has a lot of knowledge about Symfony bundle development.

public function process(ContainerBuilder $container)
{
    $parameters = $container->getParameterBag()->all();
    $definitions = $container->getDefinitions();
    $aliases = $container->getAliases();
    $exprLangProviders = $container->getExpressionLanguageProviders();

    foreach ($container->getExtensions() as $extension) {
        if ($extension instanceof PrependExtensionInterface) {
            $extension->prepend($container);
        }
    }

    foreach ($container->getExtensions() as $name => $extension) {

        if (!$config = $container->getExtensionConfig($name)) {
            // this extension was not called
            continue;
        }
        $config = $container->getParameterBag()->resolveValue($config);

        $tmpContainer = new ContainerBuilder($container->getParameterBag());
        $tmpContainer->setResourceTracking($container->isTrackingResources());
        $tmpContainer->addObjectResource($extension);

        foreach ($exprLangProviders as $provider) {
            $tmpContainer->addExpressionLanguageProvider($provider);
        }

        $extension->load($config, $tmpContainer);

        $container->merge($tmpContainer);
        $container->getParameterBag()->add($parameters);
    }

    $container->addDefinitions($definitions);
    $container->addAliases($aliases);
}

I recommend that you navigate (aka Ctrl-click) everything is inspect what it is doing. We can already learn couple of things from the method body.

  1. If an extension (read: bundle) doesn’t have a config (entry in config.yml), it won’t be loaded.
  2. $config = $container->getExtensionConfig($name)
    Each extension is loaded only with it’s own configuration, means it won’t see other bundles configs.
  3. $tmpContainer = new ContainerBuilder($container->getParameterBag()); then $container->merge($tmpContainer);
    Each extension will receive a copy of ContainerBuilder that will be merged later to the main ContainerBuilder. This means that extensions won’t be able to see each other definitions. This is why our test failed then!
  4. This class implements CompilerPassInterface, so if we do the same, we can have access to a full ContainerBuilder, right?

Let’s try. We will simply cut the code snippet we added to the extension and didn’t work, and add it to the new class.

src/DependencyInjection/Compiler/SetSQLLoggerPass.php

<?php
namespace Skafandri\PerformanceMeterBundle\DependencyInjection\Compiler;

use Symfony\Component\DependencyInjection\Compiler\CompilerPassInterface;
use Symfony\Component\DependencyInjection\ContainerBuilder;
use Symfony\Component\DependencyInjection\Reference;

class SetSQLLoggerPass implements CompilerPassInterface
{

    public function process(ContainerBuilder $container)
    {
      foreach ($container->getParameter('doctrine.connections') as $connection) {
          $container->getDefinition($connection . '.configuration')
              ->addMethodCall('setSQLLogger', array(new Reference('performance_meter.logger_chain')));
      }
    }
}

To load this compiler we need to override the Bundle build method in src/PerformanceMeterBundle.php

public function build(ContainerBuilder $container)
{
    parent::build($container);
    $container->addCompilerPass(new SetSQLLoggerPass());
}

An to simulate how the kernel build a container, we need to add to PerformanceMeterExtensionTest:createContainer, just before the return statement

$performanceMeterBundle = new PerformanceMeterBundle();
$performanceMeterBundle->build($container);

Previous: Part 2