From 03cd9419e3bd90a9309fffe1d6394b9e9bba2128 Mon Sep 17 00:00:00 2001
From: Dimitri Gritsajuk <gritsajuk.dimitri@gmail.com>
Date: Wed, 1 May 2019 16:32:24 +0200
Subject: [PATCH 1/3] [Profiling] Add query backtrace data

---
 Dbal/Logging/BacktraceLogger.php           | 23 +++++++++++
 DependencyInjection/Configuration.php      |  4 ++
 DependencyInjection/DoctrineExtension.php  | 13 ++++--
 Resources/config/dbal.xml                  |  1 +
 Resources/views/Collector/db.html.twig     | 47 ++++++++++++++++++++--
 Tests/Dbal/Logging/BacktraceLoggerTest.php | 20 +++++++++
 6 files changed, 100 insertions(+), 8 deletions(-)
 create mode 100644 Dbal/Logging/BacktraceLogger.php
 create mode 100644 Tests/Dbal/Logging/BacktraceLoggerTest.php

diff --git a/Dbal/Logging/BacktraceLogger.php b/Dbal/Logging/BacktraceLogger.php
new file mode 100644
index 000000000..9cd29494a
--- /dev/null
+++ 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
index b3e05944d..6f75d1b7d 100644
--- 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_backtrace')
+                    ->defaultValue(false)
+                    ->info('To enable Query backtrace record')
+                ->end()
                 ->scalarNode('server_version')->end()
                 ->scalarNode('driver_class')->end()
                 ->scalarNode('wrapper_class')->end()
diff --git a/DependencyInjection/DoctrineExtension.php b/DependencyInjection/DoctrineExtension.php
index 75fde439e..475aaf39d 100644
--- 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'));
+
+        if ($connection['profiling'] || $connection['profiling_backtrace']) {
+            $profilingAbstractId = $connection['profiling_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_backtrace']);
 
         if (isset($connection['auto_commit'])) {
             $configuration->addMethodCall('setAutoCommit', [$connection['auto_commit']]);
diff --git a/Resources/config/dbal.xml b/Resources/config/dbal.xml
index d0f2a868b..7cc724505 100644
--- 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
index 4cfb9a012..560180701 100644
--- 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
new file mode 100644
index 000000000..b06236cb1
--- /dev/null
+++ 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']);
+    }
+}

From 012835a04c9d4d8a4412309080221545a1cc8af8 Mon Sep 17 00:00:00 2001
From: Andreas Braun <git@alcaeus.org>
Date: Fri, 10 May 2019 12:23:59 +0200
Subject: [PATCH 2/3] Rename backtrace option and add tests

---
 DependencyInjection/Configuration.php                  |  4 ++--
 DependencyInjection/DoctrineExtension.php              |  6 +++---
 Resources/config/schema/doctrine-1.0.xsd               |  1 +
 .../AbstractDoctrineExtensionTest.php                  |  6 ++++++
 .../Fixtures/config/xml/dbal_logging.xml               | 10 ++++++++++
 .../Fixtures/config/yml/dbal_logging.yml               |  8 ++++++++
 6 files changed, 30 insertions(+), 5 deletions(-)

diff --git a/DependencyInjection/Configuration.php b/DependencyInjection/Configuration.php
index 6f75d1b7d..9b7c55cc2 100644
--- a/DependencyInjection/Configuration.php
+++ b/DependencyInjection/Configuration.php
@@ -143,9 +143,9 @@ private function getDbalConnectionsNode()
                 ->scalarNode('schema_filter')->end()
                 ->booleanNode('logging')->defaultValue($this->debug)->end()
                 ->booleanNode('profiling')->defaultValue($this->debug)->end()
-                ->booleanNode('profiling_backtrace')
+                ->booleanNode('profiling_collect_backtrace')
                     ->defaultValue(false)
-                    ->info('To enable Query backtrace record')
+                    ->info('Enables collecting backtraces when profiling is enabled')
                 ->end()
                 ->scalarNode('server_version')->end()
                 ->scalarNode('driver_class')->end()
diff --git a/DependencyInjection/DoctrineExtension.php b/DependencyInjection/DoctrineExtension.php
index 475aaf39d..8c7f730d8 100644
--- a/DependencyInjection/DoctrineExtension.php
+++ b/DependencyInjection/DoctrineExtension.php
@@ -133,8 +133,8 @@ protected function loadDbalConnection($name, array $connection, ContainerBuilder
         }
         unset($connection['logging']);
 
-        if ($connection['profiling'] || $connection['profiling_backtrace']) {
-            $profilingAbstractId = $connection['profiling_backtrace'] ?
+        if ($connection['profiling']) {
+            $profilingAbstractId = $connection['profiling_collect_backtrace'] ?
                 'doctrine.dbal.logger.backtrace' :
                 'doctrine.dbal.logger.profiling';
 
@@ -154,7 +154,7 @@ protected function loadDbalConnection($name, array $connection, ContainerBuilder
                 $logger = $profilingLogger;
             }
         }
-        unset($connection['profiling'], $connection['profiling_backtrace']);
+        unset($connection['profiling'], $connection['profiling_collect_backtrace']);
 
         if (isset($connection['auto_commit'])) {
             $configuration->addMethodCall('setAutoCommit', [$connection['auto_commit']]);
diff --git a/Resources/config/schema/doctrine-1.0.xsd b/Resources/config/schema/doctrine-1.0.xsd
index 1d1dcac09..ed760d0fa 100644
--- 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/Tests/DependencyInjection/AbstractDoctrineExtensionTest.php b/Tests/DependencyInjection/AbstractDoctrineExtensionTest.php
index a1fc22d56..aac21d889 100644
--- 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
index b7b17b41d..e6d86fdc0 100644
--- 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
index ee8ef2679..bdac61ead 100644
--- 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

From c9d93dfbb5e3b11e1638f323da1cd0f96d61e5e4 Mon Sep 17 00:00:00 2001
From: Andreas Braun <git@alcaeus.org>
Date: Fri, 10 May 2019 12:30:46 +0200
Subject: [PATCH 3/3] Document new backtrace profiling options

---
 Resources/doc/configuration.rst | 4 ++++
 1 file changed, 4 insertions(+)

diff --git a/Resources/doc/configuration.rst b/Resources/doc/configuration.rst
index 0387aa0b8..fc5e86cd1 100644
--- 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=""