Database queries logging in Magento 2

When discussing bottlenecks in Magento backend implementations, we often refer to the built-in profiler, which allows us to view the loading times of specific backend functional elements. There are two general factors of such bottlenecks: heavy (or repetitive) database calls or slow PHP operations such as loops and similar cases.

To identify bottlenecks on the PHP side, we can examine the code to pinpoint the “slow” sections. But in case of the database calls we usually need additional tools since it might take much time to get a pack of final database requests by checking code. For this purpose Magento 2 has a built in profiler of database calls which is disabled by default.

As you may recall, Magento 1 also has a database calls profiler that displays information about the database calls alongside the standard built-in profiler’s output. To use the database queries profiler in Magento 1 we should enable the standard profiler and then set the proper flag in our app/etc/local.xml file for the “connection” scope:

<connection>
    ...
    <profiler>true</profiler>
</connection>

In Magento 2 we have a bit different approach for database calls profiling. As you may also know, Dependency Injection (DI) system allows to set different preferences for interfaces. That means if we have some interface injected into a class constructor, we can choose the preferable class that should be instantiated for this interface upon the class creation. For example, if you check “Magento\Cms\Controller\Adminhtml\Page\InlineEdit” class, you will see that we use the following interface:

use Magento\Cms\Api\PageRepositoryInterface as PageRepository;

And in the constructor code we can see the interface injection, but not the interface implementation:

 public function __construct(
        ...
        PageRepository $pageRepository,
    ) {

However in the class methods code the system works with an instantiated implementation for this interface. So, how do the system know which implementation should be used in case if there are many implementations of the interface? That’s the exact place where a preference should be used. Check configuration in “app/code/Magento/Cms/etc/di.xml” and you will see there the following line:

<preference for="Magento\Cms\Api\PageRepositoryInterface" type="Magento\Cms\Model\PageRepository" />

By using this line we ask the system to load “Magento\Cms\Model\PageRepository” as an implementation of “Magento\Cms\Api\PageRepositoryInterface” interface. Well then, in case of the “PageRepository” we have only one implementation in the system by default. The database queries profiler is a good example of working with different implementations of some interface, let’s check it out.
In Magento 2 we have the DI preferences not only inside of the modules but in the global DI configuration as well. You can find the global DI configuration here: app/etc/di.xml. Try to search the following line inside of this file:

<preference for="Magento\Framework\DB\LoggerInterface" type="Magento\Framework\DB\Logger\Quiet"/>

As you can see, by default we have “Magento\Framework\DB\Logger\Quiet” as the database queries logger (profiler) implementation. By checking this implementation we will see that there are only few empty methods:

class Quiet implements \Magento\Framework\DB\LoggerInterface
{
    /**
     * {@inheritdoc}
     */
    public function log($str)
    {
    }

    /**
     * {@inheritdoc}
     */
    public function logStats($type, $sql, $bind = [], $result = null)
    {
    }

    /**
     * {@inheritdoc}
     */
    public function critical(\Exception $e)
    {
    }

    /**
     * {@inheritdoc}
     */
    public function startTimer()
    {
    }
}

Clearly, this class will log nothing. But there’s one more implementation of the database logger interface: \Magento\Framework\DB\Logger\File. That’s exactly what we need. This implementation writes information about the database queries into a log file. We are also able to pass different parameters to the class constructor in order to adjust the logging process. In the constructor we have the following set of arguments:

 public function __construct(
        Filesystem $filesystem,
        $debugFile = 'debug/db.log',
        $logAllQueries = false,
        $logQueryTime = 0.05,
        $logCallStack = false
    ) {
        parent::__construct($logAllQueries, $logQueryTime, $logCallStack);
        $this->dir = $filesystem->getDirectoryWrite(DirectoryList::VAR_DIR);
        $this->debugFile = $debugFile;
    }

So, we can change $debugFile, $logAllQueries, $logQueryTime and $logCallStack here. Fortunately, we can do it directly in the XML preference scope. Therefore, to enable the database calls profiler, formally, we need two movements: change the preference to the file logger instead of the “quiet” logger and change the logger settings if necessary. So, to enable database calls profiling into a custom file we need to replace the default preference with the following one:

<preference for="Magento\Framework\DB\LoggerInterface" type="Magento\Framework\DB\Logger\File"/>
<type name="Magento\Framework\DB\Logger\File">
    <arguments>
        <argument name="logAllQueries" xsi:type="boolean">true</argument>
        <argument name="debugFile" xsi:type="string">debug/atwix.log</argument>
    </arguments>
</type>

Then, clean your cache and, if you’ve done everything correctly, after visiting some page, you will see a detailed information about database queries in var/debug/atwix.log. Do not forget to switch the database profiler back to the “quiet” implementation after debugging – otherwise you will get a heavyweight log file very soon.

I hope this information helps you grasp how preferences function within the Magento 2 Dependency Injection flow and demonstrates how to activate the built-in database queries profiler using these preferences.

Feel free to share your ideas in the comments below.