feature #23659 [HttpKernel] LoggerDataCollector: splitting logs on different sub-requests (vtsykun)

This PR was merged into the 4.1-dev branch. Discussion ---------- [HttpKernel] LoggerDataCollector: splitting logs on different sub-requests | Q | A | ------------- | --- | Branch? | 4.1 | Bug fix? | yes | New feature? | no | BC breaks? | no | Deprecations? | no | Tests pass? | - | Fixed tickets | #23620 | License | MIT | Doc PR | - This PR fixed performance problem in dev mode and prevent logs serialize several times for each sub-request. STR: 1) Install any symfony application v2.8-3.4 2) Create a simple page with 20-50 sub-requests and 5k-10k logs 3) Open page in dev mode **Actual** - debug toolbar not open (404 not found) - sets of logs (in the logger debug panel) for different requests are same - log processing takes about 20-30s - gc also run about 50% of execution time **Expected** - Debug toolbar should be open - As developer, I want to see in logger panel only those logs that are relevant to the given sub-request ### Profile and performance Tested on page with 7k logs and 70 sub-request. Comparison: - v3.3.5 - this patch: https://blackfire.io/profiles/compare/b1d410b3-c4a7-4778-9b6d-514f72193e28/graph - v3.3.5 - patch #23644 https://blackfire.io/profiles/compare/d0715b04-7834-4981-8da2-9f1dcb2ef90c/graph Commits ------- d0cb1de [HttpKernel] LoggerDataCollector: splitting logs on different sub-requests
2018-04-20 11:46:43 +02:00 · 2018-04-20 11:46:43 +02:00 · d0db3879d9
commit d0db3879d9
parent 4b66721658 d0cb1de9a5
9 changed files with 183 additions and 19 deletions
--- a/src/Symfony/Bridge/Monolog/Logger.php
+++ b/src/Symfony/Bridge/Monolog/Logger.php
@ -12,6 +12,7 @@
 namespace Symfony\Bridge\Monolog;

 use Monolog\Logger as BaseLogger;
+use Symfony\Component\HttpFoundation\Request;
 use Symfony\Component\HttpKernel\Log\DebugLoggerInterface;

 /**
@ -24,10 +25,10 @@ class Logger extends BaseLogger implements DebugLoggerInterface
    /**
     * {@inheritdoc}
     */
-    public function getLogs()
+    public function getLogs(/* Request $request = null */)
    {
        if ($logger = $this->getDebugLogger()) {
-            return $logger->getLogs();
+            return \call_user_func_array(array($logger, 'getLogs'), \func_get_args());
        }

        return array();
@ -36,10 +37,10 @@ class Logger extends BaseLogger implements DebugLoggerInterface
    /**
     * {@inheritdoc}
     */
-    public function countErrors()
+    public function countErrors(/* Request $request = null */)
    {
        if ($logger = $this->getDebugLogger()) {
-            return $logger->countErrors();
+            return \call_user_func_array(array($logger, 'countErrors'), \func_get_args());
        }

        return 0;
--- a/src/Symfony/Bridge/Monolog/Processor/DebugProcessor.php
+++ b/src/Symfony/Bridge/Monolog/Processor/DebugProcessor.php
@ -12,16 +12,26 @@
 namespace Symfony\Bridge\Monolog\Processor;

 use Monolog\Logger;
+use Symfony\Component\HttpFoundation\Request;
+use Symfony\Component\HttpFoundation\RequestStack;
 use Symfony\Component\HttpKernel\Log\DebugLoggerInterface;

 class DebugProcessor implements DebugLoggerInterface
 {
    private $records = array();
-    private $errorCount = 0;
+    private $errorCount = array();
+    private $requestStack;
+
+    public function __construct(RequestStack $requestStack = null)
+    {
+        $this->requestStack = $requestStack;
+    }

    public function __invoke(array $record)
    {
-        $this->records[] = array(
+        $hash = $this->requestStack && ($request = $this->requestStack->getCurrentRequest()) ? spl_object_hash($request) : '';
+
+        $this->records[$hash][] = array(
            'timestamp' => $record['datetime']->getTimestamp(),
            'message' => $record['message'],
            'priority' => $record['level'],
@ -29,12 +39,17 @@ class DebugProcessor implements DebugLoggerInterface
            'context' => $record['context'],
            'channel' => isset($record['channel']) ? $record['channel'] : '',
        );
+
+        if (!isset($this->errorCount[$hash])) {
+            $this->errorCount[$hash] = 0;
+        }
+
        switch ($record['level']) {
            case Logger::ERROR:
            case Logger::CRITICAL:
            case Logger::ALERT:
            case Logger::EMERGENCY:
-                ++$this->errorCount;
+                ++$this->errorCount[$hash];
        }

        return $record;
@ -43,17 +58,25 @@ class DebugProcessor implements DebugLoggerInterface
    /**
     * {@inheritdoc}
     */
-    public function getLogs()
+    public function getLogs(/* Request $request = null */)
    {
-        return $this->records;
+        if (1 <= \func_num_args() && null !== ($request = \func_get_arg(0)) && isset($this->records[$hash = spl_object_hash($request)])) {
+            return $this->records[$hash];
+        }
+
+        return $this->records ? \call_user_func_array('array_merge', $this->records) : array();
    }

    /**
     * {@inheritdoc}
     */
-    public function countErrors()
+    public function countErrors(/* Request $request = null */)
    {
-        return $this->errorCount;
+        if (1 <= \func_num_args() && null !== ($request = \func_get_arg(0)) && isset($this->errorCount[$hash = spl_object_hash($request)])) {
+            return $this->errorCount[$hash];
+        }
+
+        return array_sum($this->errorCount);
    }

    /**
@ -62,6 +85,6 @@ class DebugProcessor implements DebugLoggerInterface
    public function clear()
    {
        $this->records = array();
-        $this->errorCount = 0;
+        $this->errorCount = array();
    }
 }
--- a/src/Symfony/Bridge/Monolog/Tests/LoggerTest.php
+++ b/src/Symfony/Bridge/Monolog/Tests/LoggerTest.php
@ -15,6 +15,7 @@ use Monolog\Handler\TestHandler;
 use PHPUnit\Framework\TestCase;
 use Symfony\Bridge\Monolog\Processor\DebugProcessor;
 use Symfony\Bridge\Monolog\Logger;
+use Symfony\Component\HttpFoundation\Request;

 class LoggerTest extends TestCase
 {
@ -79,6 +80,21 @@ class LoggerTest extends TestCase
        $this->assertEquals(Logger::INFO, $record['priority']);
    }

+    public function testGetLogsWithDebugProcessor3()
+    {
+        $request = new Request();
+        $processor = $this->getMockBuilder(DebugProcessor::class)->getMock();
+        $processor->expects($this->once())->method('getLogs')->with($request);
+        $processor->expects($this->once())->method('countErrors')->with($request);
+
+        $handler = new TestHandler();
+        $logger = new Logger('test', array($handler));
+        $logger->pushProcessor($processor);
+
+        $logger->getLogs($request);
+        $logger->countErrors($request);
+    }
+
    public function testClear()
    {
        $handler = new TestHandler();
--- a/src/Symfony/Bridge/Monolog/Tests/Processor/DebugProcessorTest.php
+++ b/src/Symfony/Bridge/Monolog/Tests/Processor/DebugProcessorTest.php
@ -0,0 +1,67 @@
+<?php
+
+/*
+ * This file is part of the Symfony package.
+ *
+ * (c) Fabien Potencier <fabien@symfony.com>
+ *
+ * For the full copyright and license information, please view the LICENSE
+ * file that was distributed with this source code.
+ */
+
+namespace Symfony\Bridge\Monolog\Tests\Processor;
+
+use Monolog\Logger;
+use PHPUnit\Framework\TestCase;
+use Symfony\Bridge\Monolog\Processor\DebugProcessor;
+use Symfony\Component\HttpFoundation\Request;
+use Symfony\Component\HttpFoundation\RequestStack;
+
+class DebugProcessorTest extends TestCase
+{
+    public function testDebugProcessor()
+    {
+        $processor = new DebugProcessor();
+        $processor($this->getRecord());
+        $processor($this->getRecord(Logger::ERROR));
+
+        $this->assertCount(2, $processor->getLogs());
+        $this->assertSame(1, $processor->countErrors());
+    }
+
+    public function testWithRequestStack()
+    {
+        $stack = new RequestStack();
+        $processor = new DebugProcessor($stack);
+        $processor($this->getRecord());
+        $processor($this->getRecord(Logger::ERROR));
+
+        $this->assertCount(2, $processor->getLogs());
+        $this->assertSame(1, $processor->countErrors());
+
+        $request = new Request();
+        $stack->push($request);
+
+        $processor($this->getRecord());
+        $processor($this->getRecord(Logger::ERROR));
+
+        $this->assertCount(4, $processor->getLogs());
+        $this->assertSame(2, $processor->countErrors());
+
+        $this->assertCount(2, $processor->getLogs($request));
+        $this->assertSame(1, $processor->countErrors($request));
+    }
+
+    private function getRecord($level = Logger::WARNING, $message = 'test')
+    {
+        return array(
+            'message' => $message,
+            'context' => array(),
+            'level' => $level,
+            'level_name' => Logger::getLevelName($level),
+            'channel' => 'test',
+            'datetime' => new \DateTime(),
+            'extra' => array(),
+        );
+    }
+}
--- a/src/Symfony/Bundle/FrameworkBundle/DependencyInjection/FrameworkExtension.php
+++ b/src/Symfony/Bundle/FrameworkBundle/DependencyInjection/FrameworkExtension.php
@ -671,6 +671,7 @@ class FrameworkExtension extends Extension
        if ($debug && class_exists(DebugProcessor::class)) {
            $definition = new Definition(DebugProcessor::class);
            $definition->setPublic(false);
+            $definition->addArgument(new Reference('request_stack'));
            $container->setDefinition('debug.log_processor', $definition);
        }
    }
--- a/src/Symfony/Bundle/FrameworkBundle/Resources/config/collectors.xml
+++ b/src/Symfony/Bundle/FrameworkBundle/Resources/config/collectors.xml
@ -35,6 +35,7 @@
            <tag name="monolog.logger" channel="profiler" />
            <argument type="service" id="logger" on-invalid="ignore" />
            <argument>%kernel.cache_dir%/%kernel.container_class%</argument>
+            <argument type="service" id="request_stack" on-invalid="ignore" />
        </service>

        <service id="data_collector.time" class="Symfony\Component\HttpKernel\DataCollector\TimeDataCollector">
--- a/src/Symfony/Component/HttpKernel/DataCollector/LoggerDataCollector.php
+++ b/src/Symfony/Component/HttpKernel/DataCollector/LoggerDataCollector.php
@ -13,6 +13,7 @@ namespace Symfony\Component\HttpKernel\DataCollector;

 use Symfony\Component\Debug\Exception\SilencedErrorContext;
 use Symfony\Component\HttpFoundation\Request;
+use Symfony\Component\HttpFoundation\RequestStack;
 use Symfony\Component\HttpFoundation\Response;
 use Symfony\Component\HttpKernel\Log\DebugLoggerInterface;

@ -25,14 +26,17 @@ class LoggerDataCollector extends DataCollector implements LateDataCollectorInte
 {
    private $logger;
    private $containerPathPrefix;
+    private $currentRequest;
+    private $requestStack;

-    public function __construct($logger = null, string $containerPathPrefix = null)
+    public function __construct($logger = null, string $containerPathPrefix = null, RequestStack $requestStack = null)
    {
        if (null !== $logger && $logger instanceof DebugLoggerInterface) {
            $this->logger = $logger;
        }

        $this->containerPathPrefix = $containerPathPrefix;
+        $this->requestStack = $requestStack;
    }

    /**
@ -40,7 +44,7 @@ class LoggerDataCollector extends DataCollector implements LateDataCollectorInte
     */
    public function collect(Request $request, Response $response, \Exception $exception = null)
    {
-        // everything is done as late as possible
+        $this->currentRequest = $this->requestStack && $this->requestStack->getMasterRequest() !== $request ? $request : null;
    }

    /**
@ -63,9 +67,10 @@ class LoggerDataCollector extends DataCollector implements LateDataCollectorInte
            $containerDeprecationLogs = $this->getContainerDeprecationLogs();
            $this->data = $this->computeErrorsCount($containerDeprecationLogs);
            $this->data['compiler_logs'] = $this->getContainerCompilerLogs();
-            $this->data['logs'] = $this->sanitizeLogs(array_merge($this->logger->getLogs(), $containerDeprecationLogs));
+            $this->data['logs'] = $this->sanitizeLogs(array_merge($this->logger->getLogs($this->currentRequest), $containerDeprecationLogs));
            $this->data = $this->cloneVar($this->data);
        }
+        $this->currentRequest = null;
    }

    /**
@ -229,14 +234,14 @@ class LoggerDataCollector extends DataCollector implements LateDataCollectorInte
    {
        $silencedLogs = array();
        $count = array(
-            'error_count' => $this->logger->countErrors(),
+            'error_count' => $this->logger->countErrors($this->currentRequest),
            'deprecation_count' => 0,
            'warning_count' => 0,
            'scream_count' => 0,
            'priorities' => array(),
        );

-        foreach ($this->logger->getLogs() as $log) {
+        foreach ($this->logger->getLogs($this->currentRequest) as $log) {
            if (isset($count['priorities'][$log['priority']])) {
                ++$count['priorities'][$log['priority']]['count'];
            } else {
--- a/src/Symfony/Component/HttpKernel/Log/DebugLoggerInterface.php
+++ b/src/Symfony/Component/HttpKernel/Log/DebugLoggerInterface.php
@ -11,6 +11,8 @@

 namespace Symfony\Component\HttpKernel\Log;

+use Symfony\Component\HttpFoundation\Request;
+
 /**
 * DebugLoggerInterface.
 *
@ -25,16 +27,20 @@ interface DebugLoggerInterface
     * timestamp, message, priority, and priorityName.
     * It can also have an optional context key containing an array.
     *
+     * @param Request|null $request The request to get logs for
+     *
     * @return array An array of logs
     */
-    public function getLogs();
+    public function getLogs(/* Request $request = null */);

    /**
     * Returns the number of errors.
     *
+     * @param Request|null $request The request to count logs for
+     *
     * @return int The number of errors
     */
-    public function countErrors();
+    public function countErrors(/* Request $request = null */);

    /**
     * Removes all log records.
--- a/src/Symfony/Component/HttpKernel/Tests/DataCollector/LoggerDataCollectorTest.php
+++ b/src/Symfony/Component/HttpKernel/Tests/DataCollector/LoggerDataCollectorTest.php
@ -13,7 +13,11 @@ namespace Symfony\Component\HttpKernel\Tests\DataCollector;

 use PHPUnit\Framework\TestCase;
 use Symfony\Component\Debug\Exception\SilencedErrorContext;
+use Symfony\Component\HttpFoundation\Request;
+use Symfony\Component\HttpFoundation\RequestStack;
+use Symfony\Component\HttpFoundation\Response;
 use Symfony\Component\HttpKernel\DataCollector\LoggerDataCollector;
+use Symfony\Component\HttpKernel\Log\DebugLoggerInterface;

 class LoggerDataCollectorTest extends TestCase
 {
@ -41,6 +45,46 @@ class LoggerDataCollectorTest extends TestCase
        ), $compilerLogs['Unknown Compiler Pass']);
    }

+    public function testWithMasterRequest()
+    {
+        $masterRequest = new Request();
+        $stack = new RequestStack();
+        $stack->push($masterRequest);
+
+        $logger = $this
+            ->getMockBuilder(DebugLoggerInterface::class)
+            ->setMethods(array('countErrors', 'getLogs', 'clear'))
+            ->getMock();
+        $logger->expects($this->once())->method('countErrors')->with(null);
+        $logger->expects($this->exactly(2))->method('getLogs')->with(null)->will($this->returnValue(array()));
+
+        $c = new LoggerDataCollector($logger, __DIR__.'/', $stack);
+
+        $c->collect($masterRequest, new Response());
+        $c->lateCollect();
+    }
+
+    public function testWithSubRequest()
+    {
+        $masterRequest = new Request();
+        $subRequest = new Request();
+        $stack = new RequestStack();
+        $stack->push($masterRequest);
+        $stack->push($subRequest);
+
+        $logger = $this
+            ->getMockBuilder(DebugLoggerInterface::class)
+            ->setMethods(array('countErrors', 'getLogs', 'clear'))
+            ->getMock();
+        $logger->expects($this->once())->method('countErrors')->with($subRequest);
+        $logger->expects($this->exactly(2))->method('getLogs')->with($subRequest)->will($this->returnValue(array()));
+
+        $c = new LoggerDataCollector($logger, __DIR__.'/', $stack);
+
+        $c->collect($subRequest, new Response());
+        $c->lateCollect();
+    }
+
    /**
     * @dataProvider getCollectTestData
     */