[Profiling] Add query backtrace data

doctrine · May 1, 2019 · e304f01 · e304f01
1 parent 5c79bbc
commit e304f01
Show file tree

Hide file tree

Showing 6 changed files with 99 additions and 8 deletions.
diff --git a/Dbal/Logging/BacktraceLogger.php b/Dbal/Logging/BacktraceLogger.php
@@ -0,0 +1,23 @@
+<?php
+
+namespace Doctrine\Bundle\DoctrineBundle\Dbal\Logging;
+
+use Doctrine\DBAL\Logging\DebugStack;
+
+class BacktraceLogger extends DebugStack
+{
+    /**
+     * {@inheritdoc}
+     */
+    public function startQuery($sql, ?array $params = null, ?array $types = null)
+    {
+        parent::startQuery($sql, $params, $types);
+
+        $backtrace = debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS);
+
+        // skip first since it's always the current method
+        array_shift($backtrace);
+
+        $this->queries[$this->currentQuery]['backtrace'] = $backtrace;
+    }
+}
diff --git a/DependencyInjection/Configuration.php b/DependencyInjection/Configuration.php
@@ -143,6 +143,7 @@ private function getDbalConnectionsNode()
                 ->scalarNode('schema_filter')->end()
                 ->booleanNode('logging')->defaultValue($this->debug)->end()
                 ->booleanNode('profiling')->defaultValue($this->debug)->end()
+                ->booleanNode('profiling_backtrace')->defaultValue(false)->end()
                 ->scalarNode('server_version')->end()
                 ->scalarNode('driver_class')->end()
                 ->scalarNode('wrapper_class')->end()

diff --git a/DependencyInjection/DoctrineExtension.php b/DependencyInjection/DoctrineExtension.php
@@ -132,9 +132,16 @@ protected function loadDbalConnection($name, array $connection, ContainerBuilder
             $logger = new Reference('doctrine.dbal.logger');
         }
         unset($connection['logging']);
-        if ($connection['profiling']) {
-            $profilingLoggerId = 'doctrine.dbal.logger.profiling.' . $name;
-            $container->setDefinition($profilingLoggerId, new ChildDefinition('doctrine.dbal.logger.profiling'));
+
+        if ($connection['profiling'] || $connection['profiling_backtrace']) {
+            if ($connection['profiling_backtrace']) {
+                $profilingAbstractId = 'doctrine.dbal.logger.backtrace';
+            } else {
+                $profilingAbstractId = 'doctrine.dbal.logger.profiling';
+            }
+
+            $profilingLoggerId = $profilingAbstractId . '.' . $name;
+            $container->setDefinition($profilingLoggerId, new ChildDefinition($profilingAbstractId));
             $profilingLogger = new Reference($profilingLoggerId);
             $container->getDefinition('data_collector.doctrine')->addMethodCall('addLogger', [$name, $profilingLogger]);
 
@@ -149,7 +156,7 @@ protected function loadDbalConnection($name, array $connection, ContainerBuilder
                 $logger = $profilingLogger;
             }
         }
-        unset($connection['profiling']);
+        unset($connection['profiling'], $connection['profiling_backtrace']);
 
         if (isset($connection['auto_commit'])) {
             $configuration->addMethodCall('setAutoCommit', [$connection['auto_commit']]);

diff --git a/Resources/config/dbal.xml b/Resources/config/dbal.xml
@@ -30,6 +30,7 @@
         </service>
 
         <service id="doctrine.dbal.logger.profiling" class="%doctrine.dbal.logger.profiling.class%" public="false" abstract="true" />
+        <service id="doctrine.dbal.logger.backtrace" class="Doctrine\Bundle\DoctrineBundle\Dbal\Logging\BacktraceLogger" public="false" abstract="true" />
 
         <service id="doctrine.dbal.logger" class="%doctrine.dbal.logger.class%" public="false">
             <tag name="monolog.logger" channel="doctrine" />

diff --git a/Resources/views/Collector/db.html.twig b/Resources/views/Collector/db.html.twig
@@ -148,7 +148,7 @@
 
     {% if profiler_markup_version > 1 %}
         <h2>Query Metrics</h2>
-    
+
         <div class="metrics">
             <div class="metric">
                 <span class="value">{{ collector.querycount }}</span>
@@ -159,17 +159,17 @@
                 <span class="value">{{ collector.groupedQueryCount }}</span>
                 <span class="label">Different statements</span>
             </div>
-    
+
             <div class="metric">
                 <span class="value">{{ '%0.2f'|format(collector.time * 1000) }} ms</span>
                 <span class="label">Query time</span>
             </div>
-    
+
             <div class="metric">
                 <span class="value">{{ collector.invalidEntityCount }}</span>
                 <span class="label">Invalid entities</span>
             </div>
-    
+
             {% if collector.cacheEnabled %}
                 <div class="metric">
                 	<span class="value">{{ collector.cacheHitsCount }}</span>
@@ -254,6 +254,11 @@
                                         &nbsp;&nbsp;
                                         <a class="link-inverse" href="{{ path('_profiler', { panel: 'db', token: token, page: 'explain', connection: connection, query: i }) }}" onclick="return explain(this);" data-target-id="explain-{{ i }}-{{ loop.parent.loop.index }}">Explain query</a>
                                     {% endif %}
+
+                                    {% if query.backtrace is defined %}
+                                        &nbsp;&nbsp;
+                                        <a href="#" class="sf-toggle link-inverse" data-toggle-selector="#backtrace-{{ i }}-{{ loop.parent.loop.index }}" data-toggle-alt-content="Hide query backtrace">View query backtrace</a>
+                                    {% endif %}
                                 </div>
 
                                 <div id="formatted-query-{{ i }}-{{ loop.parent.loop.index }}" class="sql-runnable hidden">
@@ -267,6 +272,40 @@
                                 {% if query.explainable %}
                                     <div id="explain-{{ i }}-{{ loop.parent.loop.index }}" class="sql-explain"></div>
                                 {% endif %}
+
+                                {% if query.backtrace is defined %}
+                                    <div id="backtrace-{{ i }}-{{ loop.parent.loop.index }}" class="hidden">
+                                        <table>
+                                            <thead>
+                                                <tr>
+                                                    <th scope="col">#</th>
+                                                    <th scope="col">File/Call</th>
+                                                </tr>
+                                            </thead>
+                                            <tbody>
+                                                {% for trace in query.backtrace %}
+                                                    <tr>
+                                                        <td>{{ loop.index }}</td>
+                                                        <td>
+                                                            <span class="text-small">
+                                                                {% set line_number = trace.line|default(1) %}
+                                                                {% set file_path = trace.file|format_file(line_number)|striptags|replace({ (' at line ' ~ line_number): '' }) %}
+                                                                {% set file_path_parts = file_path|split(constant('DIRECTORY_SEPARATOR')) %}
+
+                                                                {{- file_path_parts[:-1]|join(constant('DIRECTORY_SEPARATOR')) -}}
+                                                                {{- constant('DIRECTORY_SEPARATOR') -}}
+                                                                <strong>{{ file_path_parts|last }}</strong>
+                                                                {{- trace.type ?? '::' -}}
+                                                                <span class="status-warning">{{ trace.function }}</span>
+                                                                (line {{ line_number }})
+                                                            </span>
+                                                        </td>
+                                                    </tr>
+                                                {% endfor %}
+                                            </tbody>
+                                        </table>
+                                    </div>
+                                {% endif %}
                             </td>
                         </tr>
                     {% endfor %}

diff --git a/Tests/Dbal/Logging/BacktraceLoggerTest.php b/Tests/Dbal/Logging/BacktraceLoggerTest.php
@@ -0,0 +1,20 @@
+<?php
+
+namespace Doctrine\Bundle\DoctrineBundle\Tests\Dbal\Logging;
+
+use Doctrine\Bundle\DoctrineBundle\Dbal\Logging\BacktraceLogger;
+use PHPUnit\Framework\TestCase;
+
+class BacktraceLoggerTest extends TestCase
+{
+    public function testBacktraceLogged()
+    {
+        $logger = new BacktraceLogger();
+        $logger->startQuery('SELECT column FROM table');
+        $currentQuery = current($logger->queries);
+        self::assertSame('SELECT column FROM table', $currentQuery['sql']);
+        self::assertNull($currentQuery['params']);
+        self::assertNull($currentQuery['types']);
+        self::assertCount(11, $currentQuery['backtrace']);
+    }
+}