Fixes #14133: Fixed bug when calculating timings with mixed nested profile begin and end in `yii\log\Logger::calculateTimings()`

framework/CHANGELOG.md

@@ -57,6 +57,7 @@ Yii Framework 2 Change Log
 - Bug #14052: Fixed processing parse errors on PHP 7 since these are instances of `\ParseError` (samdark)
 - Bug #14074: Fixed default value of `yii\console\controllers\FixtureController::$globalFixtures` to contain valid class name (lynicidn)
 - Bug #14094: Fixed bug when single `yii\web\UrlManager::createUrl()` call my result multiple calls of `yii\web\UrlRule::createUrl()` for the same rule (rossoneri)
+- Bug #14133: Fixed bug when calculating timings with mixed nested profile begin and end in `yii\log\Logger::calculateTimings()` (bizley)
 - Enh #8641: Enhanced `yii\console\Request::resolve()` to prevent passing parameters, that begin from digits (silverfire)
 - Enh #11288: Added support for caching of `yii\web\UrlRule::createUrl()` results in `yii\web\UrlManager` for rules with defaults (rob006)
 - Enh #12528: Added option to disable query logging and profiling in DB command (cebe)

framework/log/Logger.php

@@ -278,20 +278,22 @@ class Logger extends Component
             list($token, $level, $category, $timestamp, $traces) = $log;
             $memory = isset($log[5]) ? $log[5] : 0;
             $log[6] = $i;
+            $hash = md5($token);
             if ($level == Logger::LEVEL_PROFILE_BEGIN) {
-                $stack[] = $log;
+                $stack[$hash] = $log;
             } elseif ($level == Logger::LEVEL_PROFILE_END) {
-                if (($last = array_pop($stack)) !== null && $last[0] === $token) {
-                    $timings[$last[6]] = [
-                        'info' => $last[0],
-                        'category' => $last[2],
-                        'timestamp' => $last[3],
-                        'trace' => $last[4],
-                        'level' => count($stack),
-                        'duration' => $timestamp - $last[3],
+                if (isset($stack[$hash])) {
+                    $timings[$stack[$hash][6]] = [
+                        'info' => $stack[$hash][0],
+                        'category' => $stack[$hash][2],
+                        'timestamp' => $stack[$hash][3],
+                        'trace' => $stack[$hash][4],
+                        'level' => count($stack) - 1,
+                        'duration' => $timestamp - $stack[$hash][3],
                         'memory' => $memory,
-                        'memoryDiff' => $memory - (isset($last[5]) ? $last[5] : 0),
+                        'memoryDiff' => $memory - (isset($stack[$hash][5]) ? $stack[$hash][5] : 0),
                     ];
+                    unset($stack[$hash]);
                 }
             }
         }

tests/framework/log/LoggerTest.php

@@ -241,6 +241,45 @@ class LoggerTest extends TestCase
     }
 
     /**
+     * See https://github.com/yiisoft/yii2/issues/14133
+     *
+     * @covers yii\log\Logger::calculateTimings()
+     */
+    public function testCalculateTimingsWithProfileBeginEndAndNestedMixedLevels()
+    {
+        $messages = [
+            ['firstLevel', Logger::LEVEL_PROFILE_BEGIN, 'firstLevelCategory', 10, 'firstTrace', 1048576],
+            ['secondLevel', Logger::LEVEL_PROFILE_BEGIN, 'secondLevelCategory', 15, 'secondTrace', 2097152],
+            ['firstLevel', Logger::LEVEL_PROFILE_END, 'firstLevelCategory', 80, 'firstTrace', 4194304],
+            ['secondLevel', Logger::LEVEL_PROFILE_END, 'secondLevelCategory', 55, 'secondTrace', 3145728],
+        ];
+        $this->assertEquals([
+            [
+                'info' => 'firstLevel',
+                'category' => 'firstLevelCategory',
+                'timestamp' => 10,
+                'trace' => 'firstTrace',
+                'level' => 1,
+                'duration' => 70,
+                'memory' => 4194304,
+                'memoryDiff' => 3145728
+            ],
+            [
+                'info' => 'secondLevel',
+                'category' => 'secondLevelCategory',
+                'timestamp' => 15,
+                'trace' => 'secondTrace',
+                'level' => 0,
+                'duration' => 40,
+                'memory' => 3145728,
+                'memoryDiff' => 1048576
+            ]
+        ],
+            $this->logger->calculateTimings($messages)
+        );
+    }
+
+    /**
      * @covers yii\log\Logger::getElapsedTime()
      */
     public function testGetElapsedTime()