Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[Profiling] Add query backtrace data #954

Merged
merged 3 commits into from May 10, 2019
Merged

[Profiling] Add query backtrace data #954

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
03cd941
[Profiling] Add query backtrace data
ottaviano May 1, 2019
012835a
Rename backtrace option and add tests
alcaeus May 10, 2019
c9d93df
Document new backtrace profiling options
alcaeus May 10, 2019
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
23 changes: 23 additions & 0 deletions Dbal/Logging/BacktraceLogger.php
View file
Open in desktop
@@ -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;
}
}
4 changes: 4 additions & 0 deletions DependencyInjection/Configuration.php
View file
Open in desktop
Expand Up @@ -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')
ostrolucky marked this conversation as resolved.
Show resolved Hide resolved
->defaultValue(false)
->info('Enables collecting backtraces when profiling is enabled')
->end()
->scalarNode('server_version')->end()
->scalarNode('driver_class')->end()
->scalarNode('wrapper_class')->end()
Expand Down
11 changes: 8 additions & 3 deletions DependencyInjection/DoctrineExtension.php
View file
Open in desktop
Expand Up @@ -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]);

Expand All @@ -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']]);
Expand Down
1 change: 1 addition & 0 deletions Resources/config/dbal.xml
View file
Open in desktop
Expand Up @@ -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" />
Expand Down
1 change: 1 addition & 0 deletions Resources/config/schema/doctrine-1.0.xsd
View file
Open in desktop
Expand Up @@ -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" />
Expand Down
4 changes: 4 additions & 0 deletions Resources/doc/configuration.rst
View file
Open in desktop
Expand Up @@ -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.
Expand Down Expand Up @@ -493,6 +496,7 @@ Configuration Reference
schema-filter=""
logging="%kernel.debug%"
profiling="%kernel.debug%"
profiling-collect-backtrace="false"
server-version=""
driver-class=""
wrapper-class=""
Expand Down
47 changes: 43 additions & 4 deletions Resources/views/Collector/db.html.twig
View file
Open in desktop
Expand Up @@ -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>
Expand All @@ -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>
Expand Down Expand Up @@ -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">
Expand All @@ -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): '' }) %}
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

why using |format_file(line_number) if you remove both the tags (making the file clickable) and the line number ?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

it's for making relative paths

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

but why not keeping the full feature of |format_file which makes them clickable ?

{% 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 %}
Expand Down
20 changes: 20 additions & 0 deletions Tests/Dbal/Logging/BacktraceLoggerTest.php
View file
Open in desktop
@@ -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']);
}
}
6 changes: 6 additions & 0 deletions Tests/DependencyInjection/AbstractDoctrineExtensionTest.php
View file
Open in desktop
Expand Up @@ -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')]);
}
Expand Down
10 changes: 10 additions & 0 deletions Tests/DependencyInjection/Fixtures/config/xml/dbal_logging.xml
View file
Open in desktop
Expand Up @@ -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"
Expand Down
8 changes: 8 additions & 0 deletions Tests/DependencyInjection/Fixtures/config/yml/dbal_logging.yml
View file
Open in desktop
Expand Up @@ -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