Preventing breaking profiling messages when flushing (#18800)

framework/CHANGELOG.md

@@ -21,6 +21,7 @@ Yii Framework 2 Change Log
 - Enh #18734: Added `yii\validators\EmailValidator::$enableLocalIDN` (brandonkelly)
 - Bug #18756: Fix `\yii\validators\ExistValidator::queryValueExists` to validate against an array of unique values (DrDeath72)
 - Enh #18656: Added ability for `yii serve`'s `--router` param to take an alias (markhuot)
+- Enh #18274: Added `profilingAware` option to `yii\log\Logger` to prevent breaking the profiling block messages pair when flushing them (bizley)
 - Enh #18789: Added JSONP support in `yii\web\JsonParser::parse()` (WinterSilence)
 - Bug #18274: Fix `yii\log\Logger` to calculate profile timings no matter the value of the flush interval (bizley)
 

framework/log/Logger.php

@@ -59,7 +59,7 @@ class Logger extends Component
      */
     const LEVEL_INFO = 0x04;
     /**
-     * Tracing message level. An tracing message is one that reveals the code execution flow.
+     * Tracing message level. A tracing message is one that reveals the code execution flow.
      */
     const LEVEL_TRACE = 0x08;
     /**
@@ -67,13 +67,13 @@ class Logger extends Component
      */
     const LEVEL_PROFILE = 0x40;
     /**
-     * Profiling message level. This indicates the message is for profiling purpose. It marks the
-     * beginning of a profiling block.
+     * Profiling message level. This indicates the message is for profiling purpose. It marks the beginning
+     * of a profiling block.
      */
     const LEVEL_PROFILE_BEGIN = 0x50;
     /**
-     * Profiling message level. This indicates the message is for profiling purpose. It marks the
-     * end of a profiling block.
+     * Profiling message level. This indicates the message is for profiling purpose. It marks the end
+     * of a profiling block.
      */
     const LEVEL_PROFILE_END = 0x60;
 
@@ -95,7 +95,7 @@ class Logger extends Component
     public $messages = [];
     /**
      * @var int how many messages should be logged before they are flushed from memory and sent to targets.
-     * Defaults to 1000, meaning the [[flush]] method will be invoked once every 1000 messages logged.
+     * Defaults to 1000, meaning the [[flush()]] method will be invoked once every 1000 messages logged.
      * Set this property to be 0 if you don't want to flush messages until the application terminates.
      * This property mainly affects how much memory will be taken by the logged messages.
      * A smaller value means less memory, but will increase the execution time due to the overhead of [[flush()]].
@@ -116,13 +116,15 @@ class Logger extends Component
      * @since 2.0.41
      */
     public $dbEventNames = ['yii\db\Command::query', 'yii\db\Command::execute'];
-
     /**
-     * @var array of profiling related messages.
-     * Structure of a log message is the same as in [[$messages]].
+     * @var bool whether the profiling-aware mode should be switched on.
+     * If on, [[flush()]] makes sure that profiling blocks are flushed in pairs. In case that any dangling messages are
+     * detected these are kept for the next flush interval to find their pair. To prevent memory leaks, when number of
+     * dangling messages reaches flushInterval value, logger flushes them immediately and triggers a warning.
+     * Keep in mind that profiling-aware mode is more time and memory consuming.
      * @since 2.0.43
      */
-    protected $profileMessages = [];
+    public $profilingAware = false;
 
 
     /**
@@ -147,7 +149,7 @@ class Logger extends Component
      * @param string|array $message the message to be logged. This can be a simple string or a more
      * complex data structure that will be handled by a [[Target|log target]].
      * @param int $level the level of the message. This must be one of the following:
-     * `Logger::LEVEL_ERROR`, `Logger::LEVEL_WARNING`, `Logger::LEVEL_INFO`, `Logger::LEVEL_TRACE`,
+     * `Logger::LEVEL_ERROR`, `Logger::LEVEL_WARNING`, `Logger::LEVEL_INFO`, `Logger::LEVEL_TRACE`, `Logger::LEVEL_PROFILE`,
      * `Logger::LEVEL_PROFILE_BEGIN`, `Logger::LEVEL_PROFILE_END`.
      * @param string $category the category of the message.
      */
@@ -170,10 +172,12 @@ class Logger extends Component
             }
         }
         $data = [$message, $level, $category, $time, $traces, memory_get_usage()];
+        if ($this->profilingAware && in_array($level, [self::LEVEL_PROFILE_BEGIN, self::LEVEL_PROFILE_END])) {
+            $this->messages[($level == self::LEVEL_PROFILE_BEGIN ? 'begin-' : 'end-') . md5(json_encode($message))] = $data;
+        } else {
             $this->messages[] = $data;
-        if ($level == self::LEVEL_PROFILE_BEGIN || $level == self::LEVEL_PROFILE_END) {
-            $this->profileMessages[] = $data;
         }
+
         if ($this->flushInterval > 0 && count($this->messages) >= $this->flushInterval) {
             $this->flush();
         }
@@ -185,10 +189,40 @@ class Logger extends Component
      */
     public function flush($final = false)
     {
+        if ($this->profilingAware) {
+            $keep = [];
+            $messages = [];
+            foreach ($this->messages as $index => $message) {
+                if (is_int($index)) {
+                    $messages[] = $message;
+                } else {
+                    if (strpos($index, 'begin-') === 0) {
+                        $oppositeProfile = 'end-' . substr($index, 6);
+                    } else {
+                        $oppositeProfile = 'begin-' . substr($index, 4);
+                    }
+                    if (array_key_exists($oppositeProfile, $this->messages)) {
+                        $messages[] = $message;
+                    } else {
+                        $keep[$index] = $message;
+                    }
+                }
+            }
+            if ($this->flushInterval > 0 && count($keep) >= $this->flushInterval) {
+                $this->messages = [];
+                $this->log(
+                    'Number of dangling profiling block messages reached flushInterval value and therefore these were flushed. Please consider setting higher flushInterval value or making profiling blocks shorter.',
+                    self::LEVEL_WARNING
+                );
+                $messages = array_merge($messages, array_values($keep));
+            } else {
+                $this->messages = $keep;
+            }
+        } else {
             $messages = $this->messages;
-        // https://github.com/yiisoft/yii2/issues/5619
-        // new messages could be logged while the existing ones are being handled by targets
             $this->messages = [];
+        }
+
         if ($this->dispatcher instanceof Dispatcher) {
             $this->dispatcher->dispatch($messages, $final);
         }
@@ -224,7 +258,7 @@ class Logger extends Component
      */
     public function getProfiling($categories = [], $excludeCategories = [])
     {
-        $timings = $this->calculateTimings($this->profileMessages);
+        $timings = $this->calculateTimings($this->messages);
         if (empty($categories) && empty($excludeCategories)) {
             return $timings;
         }

tests/framework/log/LoggerTest.php

@@ -341,15 +341,16 @@ class LoggerTest extends TestCase
      */
     public function testGetProfilingWithEmptyCategoriesAndExcludeCategories()
     {
+        $messages = ['anyData'];
         $returnValue = 'return value';
         /* @var $logger Logger|\PHPUnit_Framework_MockObject_MockObject */
         $logger = $this->getMockBuilder('yii\log\Logger')
             ->setMethods(['calculateTimings'])
             ->getMock();
 
-        $logger->messages = ['anyData'];
+        $logger->messages = $messages;
         $logger->method('calculateTimings')->willReturn($returnValue);
-        $logger->expects($this->once())->method('calculateTimings')->with([]);
+        $logger->expects($this->once())->method('calculateTimings')->with($messages);
         $this->assertEquals($returnValue, $logger->getProfiling());
     }
 
@@ -376,7 +377,7 @@ class LoggerTest extends TestCase
 
         $logger->messages = $messages;
         $logger->method('calculateTimings')->willReturn($returnValue);
-        $logger->expects($this->once())->method('calculateTimings')->with([]);
+        $logger->expects($this->once())->method('calculateTimings')->with($messages);
         $this->assertEquals([], $logger->getProfiling(['not-matched-category']));
     }
 
@@ -416,7 +417,7 @@ class LoggerTest extends TestCase
 
         $logger->messages = $messages;
         $logger->method('calculateTimings')->willReturn($returnValue);
-        $logger->expects($this->once())->method('calculateTimings')->with([]);
+        $logger->expects($this->once())->method('calculateTimings')->with($messages);
         $this->assertEquals([$matchedByCategoryName], $logger->getProfiling(['category']));
 
         /*
@@ -429,7 +430,7 @@ class LoggerTest extends TestCase
 
         $logger->messages = $messages;
         $logger->method('calculateTimings')->willReturn($returnValue);
-        $logger->expects($this->once())->method('calculateTimings')->with([]);
+        $logger->expects($this->once())->method('calculateTimings')->with($messages);
         $this->assertEquals([$matchedByCategoryName, $secondCategory], $logger->getProfiling(['category*']));
     }
 
@@ -478,7 +479,7 @@ class LoggerTest extends TestCase
 
         $logger->messages = $messages;
         $logger->method('calculateTimings')->willReturn($returnValue);
-        $logger->expects($this->once())->method('calculateTimings')->with([]);
+        $logger->expects($this->once())->method('calculateTimings')->with($messages);
         $this->assertEquals([$fistCategory, $secondCategory], $logger->getProfiling(['cat*'], ['category3']));
 
         /*
@@ -491,7 +492,7 @@ class LoggerTest extends TestCase
 
         $logger->messages = $messages;
         $logger->method('calculateTimings')->willReturn($returnValue);
-        $logger->expects($this->once())->method('calculateTimings')->with([]);
+        $logger->expects($this->once())->method('calculateTimings')->with($messages);
         $this->assertEquals([$fistCategory], $logger->getProfiling(['cat*'], ['category*']));
     }
 

tests/framework/log/TargetTest.php

@@ -237,24 +237,108 @@ class TargetTest extends TestCase
         $this->assertCount(6, static::$messages[1]);
     }
 
-    public function testBreakProfilingWithFlush()
+    public function testBreakProfilingWithFlushWithProfilingDisabled()
     {
-        $logger = new Logger();
-        new Dispatcher([
-            'logger' => $logger,
-            'targets' => [new TestTarget()],
+        $dispatcher = $this->getMockBuilder('yii\log\Dispatcher')
+            ->setMethods(['dispatch'])
+            ->getMock();
+        $dispatcher->expects($this->once())->method('dispatch')->with($this->callback(function ($messages) {
+            return count($messages) === 2
+                && $messages[0][0] === 'token.a'
+                && $messages[0][1] == Logger::LEVEL_PROFILE_BEGIN
+                && $messages[1][0] === 'info';
+        }), false);
+
+        $logger = new Logger([
+            'dispatcher' => $dispatcher,
             'flushInterval' => 2,
         ]);
 
         $logger->log('token.a', Logger::LEVEL_PROFILE_BEGIN, 'category');
         $logger->log('info', Logger::LEVEL_INFO, 'category');
         $logger->log('token.a', Logger::LEVEL_PROFILE_END, 'category');
+    }
 
-        $timings = $logger->getProfiling(['category']);
+    public function testNotBreakProfilingWithFlushWithProfilingEnabled()
+    {
+        $dispatcher = $this->getMockBuilder('yii\log\Dispatcher')
+            ->setMethods(['dispatch'])
+            ->getMock();
+        $dispatcher->expects($this->exactly(2))->method('dispatch')->withConsecutive(
+            [
+                $this->callback(function ($messages) {
+                    return count($messages) === 1 && $messages[0][0] === 'info';
+                }),
+                false
+            ],
+            [
+                $this->callback(function ($messages) {
+                    return count($messages) === 2
+                        && $messages[0][0] === 'token.a'
+                        && $messages[0][1] == Logger::LEVEL_PROFILE_BEGIN
+                        && $messages[1][0] === 'token.a'
+                        && $messages[1][1] == Logger::LEVEL_PROFILE_END;
+                }),
+                false
+            ]
+        );
 
-        self::assertCount(1, $timings);
-        self::assertArrayHasKey('info', $timings[0]);
-        self::assertArrayHasKey('category', $timings[0]);
+        $logger = new Logger([
+            'profilingAware' => true,
+            'dispatcher' => $dispatcher,
+            'flushInterval' => 2,
+        ]);
+
+        $logger->log('token.a', Logger::LEVEL_PROFILE_BEGIN, 'category');
+        $logger->log('info', Logger::LEVEL_INFO, 'category');
+        $logger->log('token.a', Logger::LEVEL_PROFILE_END, 'category');
+    }
+
+    public function testFlushingWithProfilingEnabledAndOverflow()
+    {
+        $dispatcher = $this->getMockBuilder('yii\log\Dispatcher')
+            ->setMethods(['dispatch'])
+            ->getMock();
+        $dispatcher->expects($this->exactly(3))->method('dispatch')->withConsecutive(
+            [
+                $this->callback(function ($messages) {
+                    return count($messages) === 2
+                        && $messages[0][0] === 'token.a'
+                        && $messages[0][1] == Logger::LEVEL_PROFILE_BEGIN
+                        && $messages[1][0] === 'token.b'
+                        && $messages[1][1] == Logger::LEVEL_PROFILE_BEGIN;
+                }),
+                false
+            ],
+            [
+                $this->callback(function ($messages) {
+                    return count($messages) === 1
+                        && $messages[0][0] === 'Number of dangling profiling block messages reached flushInterval value and therefore these were flushed. Please consider setting higher flushInterval value or making profiling blocks shorter.';
+                }),
+                false
+            ],
+            [
+                $this->callback(function ($messages) {
+                    return count($messages) === 2
+                        && $messages[0][0] === 'token.b'
+                        && $messages[0][1] == Logger::LEVEL_PROFILE_END
+                        && $messages[1][0] === 'token.a'
+                        && $messages[1][1] == Logger::LEVEL_PROFILE_END;
+                }),
+                false
+            ]
+        );
+
+        $logger = new Logger([
+            'profilingAware' => true,
+            'dispatcher' => $dispatcher,
+            'flushInterval' => 2,
+        ]);
+
+        $logger->log('token.a', Logger::LEVEL_PROFILE_BEGIN, 'category');
+        $logger->log('token.b', Logger::LEVEL_PROFILE_BEGIN, 'category');
+        $logger->log('token.b', Logger::LEVEL_PROFILE_END, 'category');
+        $logger->log('token.a', Logger::LEVEL_PROFILE_END, 'category');
     }
 }