Merge pull request #954 from ottaviano/backtrace-logger

[Profiling] Add query backtrace data
doctrine · May 10, 2019 · a8377d4 · a8377d4
2 parents bb9c64b + c9d93df
commit a8377d4
Show file tree

Hide file tree

Showing 11 changed files with 128 additions and 7 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;
+
+final class BacktraceLogger extends DebugStack
+{
+    /**
+     * {@inheritdoc}
+     */
+    public function startQuery($sql, ?array $params = null, ?array $types = null) : void
+    {
+        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,10 @@ private function getDbalConnectionsNode()
                 ->scalarNode('schema_filter')->end()
                 ->booleanNode('logging')->defaultValue($this->debug)->end()
                 ->booleanNode('profiling')->defaultValue($this->debug)->end()
+                ->booleanNode('profiling_collect_backtrace')
+                    ->defaultValue(false)
+                    ->info('Enables collecting backtraces when profiling is enabled')
+                ->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,14 @@ 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'));
+            $profilingAbstractId = $connection['profiling_collect_backtrace'] ?
+                'doctrine.dbal.logger.backtrace' :
+                '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 +154,7 @@ protected function loadDbalConnection($name, array $connection, ContainerBuilder
                 $logger = $profilingLogger;
             }
         }
-        unset($connection['profiling']);
+        unset($connection['profiling'], $connection['profiling_collect_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/config/schema/doctrine-1.0.xsd b/Resources/config/schema/doctrine-1.0.xsd
@@ -36,6 +36,7 @@
         <xsd:attribute name="schema-filter" type="xsd:string" />
         <xsd:attribute name="logging" type="xsd:string" default="false" />
         <xsd:attribute name="profiling" type="xsd:string" default="false" />
+        <xsd:attribute name="profiling-collect-backtrace" type="xsd:string" default="false" />
         <xsd:attribute name="server-version" type="xsd:string" />
         <xsd:attribute name="use-savepoints" type="xsd:boolean" />
         <xsd:attributeGroup ref="driver-config" />

diff --git a/Resources/doc/configuration.rst b/Resources/doc/configuration.rst
@@ -104,6 +104,9 @@ Configuration Reference
                         logging:              "%kernel.debug%"
 
                         profiling:            "%kernel.debug%"
+                        # When true, profiling also collects a backtrace for each query
+                        profiling_collect_backtrace: false
+
                         server_version:       ~
                         driver_class:         ~
                         # Allows to specify a custom wrapper implementation to use.
@@ -493,6 +496,7 @@ Configuration Reference
                         schema-filter=""
                         logging="%kernel.debug%"
                         profiling="%kernel.debug%"
+                        profiling-collect-backtrace="false"
                         server-version=""
                         driver-class=""
                         wrapper-class=""

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() : void
+    {
+        $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']);
+    }
+}
diff --git a/Tests/DependencyInjection/AbstractDoctrineExtensionTest.php b/Tests/DependencyInjection/AbstractDoctrineExtensionTest.php
@@ -358,6 +358,12 @@ public function testLoadLogging()
         $definition = $container->getDefinition('doctrine.dbal.profile_connection.configuration');
         $this->assertDICDefinitionMethodCallOnce($definition, 'setSQLLogger', [new Reference('doctrine.dbal.logger.profiling.profile')]);
 
+        $definition = $container->getDefinition('doctrine.dbal.profile_with_backtrace_connection.configuration');
+        $this->assertDICDefinitionMethodCallOnce($definition, 'setSQLLogger', [new Reference('doctrine.dbal.logger.backtrace.profile_with_backtrace')]);
+
+        $definition = $container->getDefinition('doctrine.dbal.backtrace_without_profile_connection.configuration');
+        $this->assertDICDefinitionNoMethodCall($definition, 'setSQLLogger');
+
         $definition = $container->getDefinition('doctrine.dbal.both_connection.configuration');
         $this->assertDICDefinitionMethodCallOnce($definition, 'setSQLLogger', [new Reference('doctrine.dbal.logger.chain.both')]);
     }

diff --git a/Tests/DependencyInjection/Fixtures/config/xml/dbal_logging.xml b/Tests/DependencyInjection/Fixtures/config/xml/dbal_logging.xml
@@ -16,6 +16,16 @@
                 name="profile"
                 logging="false"
                 profiling="true" />
+            <connection
+                name="profile_with_backtrace"
+                logging="false"
+                profiling="true"
+                profiling-collect-backtrace="true" />
+            <connection
+                name="backtrace_without_profile"
+                logging="false"
+                profiling="false"
+                profiling-collect-backtrace="true" />
             <connection
                 name="both"
                 logging="true"

diff --git a/Tests/DependencyInjection/Fixtures/config/yml/dbal_logging.yml b/Tests/DependencyInjection/Fixtures/config/yml/dbal_logging.yml
@@ -8,6 +8,14 @@ doctrine:
             profile:
                 logging: false
                 profiling: true
+            profile_with_backtrace:
+                logging: false
+                profiling: true
+                profiling_collect_backtrace: true
+            backtrace_without_profile:
+                logging: false
+                profiling: false
+                profiling_collect_backtrace: true
             both:
                 logging: true
                 profiling: true