Logging MongoDB Explains in Symfony2 post

Posted on 2012-02-22 by jwage


At OpenSky.com we use MongoDB as one of our primary data stores. We use the slow query log in the profiling tools to identify to slow queries but sometimes it is hard to tell exactly where in our application it originated from. Thanks to the flexibility of Doctrine and Symfony2 we can easily listen to a few events and log the information without modifying any application code.

First lets write a simple listener class:

namespace Application\Bundle\MainBundle\ODM\MongoDB\Explainer;

use Doctrine\MongoDB\Event\EventArgs;
use Symfony\Component\DependencyInjection\ContainerInterface;

class ExplainerListener
{
    private $container;
    private $lastQuery;
    private $explains = array();

    public function __construct(ContainerInterface $container)
    {
        $this->container = $container;
    }

    public function collectionPreFind(EventArgs $args)
    {
        $this->lastQuery = $args->getData();
    }

    public function collectionPostFind(EventArgs $args)
    {
        $e = new \Exception();
        $collection = $args->getInvoker();
        $cursor = $args->getData();
        $explain = $cursor->explain();
        $this->explains[] = array(
            'explain' => $explain,
            'query' => $this->lastQuery,
            'database' => $collection->getDatabase()->getName(),
            'collection' => $collection->getName(),
            'traceAsString' => $e->getTraceAsString()
        );
    }

    private function getCollection()
    {
        $databaseName = $this->container->getParameter('doctrine.odm.mongodb.default_configuration.default_database');
        return $this->container->get('doctrine.odm.mongodb.document_manager')
            ->getConnection()
            ->selectCollection($databaseName, 'query_explains');
    }

    public function __destruct()
    {
        $this->getCollection()->batchInsert($this->explains);
    }
}

This class will listen on the Doctrine\MongoDB\Collection#find() pre and post event and capture the explain of the query.

Next just configure the listener we wrote above in the DIC:

<?xml version="1.0" encoding="utf-8" ?>
<container xmlns="http://symfony.com/schema/dic/services"
    xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
    xsi:schemaLocation="http://symfony.com/schema/dic/services http://symfony.com/schema/dic/services/services-1.0.xsd">

    <services>
        <service id="odm.explainer" class="Application\Bundle\MainBundle\ODM\MongoDB\Explainer\ExplainerListener">
            <tag name="doctrine.odm.mongodb.default_event_listener" event="collectionPreFind" method="collectionPreFind" />
            <tag name="doctrine.odm.mongodb.default_event_listener" event="collectionPostFind" method="collectionPostFind" />
            <argument type="service" id="service_container" />
        </service>
    </services>
</container>

Now all your queries will be logged in to a mongodb collection named query_explains. If you take a look in the collection after triggering a few queries in your application you will see documents that look like the following:

{
    "_id" : ObjectId("4f4480d4acee41cd6800001b"),
    "explain" : {
        "cursor" : "ForwardCappedCursor",
        "nscanned" : 0,
        "nscannedObjects" : 0,
        "n" : 0,
        "millis" : 0,
        "nYields" : 0,
        "nChunkSkips" : 0,
        "isMultiKey" : false,
        "indexOnly" : false,
        "indexBounds" : [ ],
        "allPlans" : [
            {
                "cursor" : "ForwardCappedCursor",
                "indexBounds" : [ ]
            }
        ]
    },
    "query" : [ ],
    "database" : "database_name",
    "collection" : "collection_name",
    "traceAsString" : "..."
}

The traceAsString field is a string representation of the trace that led up to the query so you can easily identify what triggered the query in your application.