refactored profiling timing calculation.

extensions/yii/debug/models/search/Db.php

@@ -53,7 +53,7 @@ class Db extends Base
 				'pageSize' => 10,
 			],
 			'sort' => [
-				'attributes' => ['duration', 'type', 'query'],
+				'attributes' => ['duration', 'seq', 'type', 'query'],
 				'defaultOrder' => [
 					'duration' => SORT_DESC,
 				],

extensions/yii/debug/panels/DbPanel.php

@@ -62,33 +62,16 @@ class DbPanel extends Panel
 		]);
 	}
 
+	/**
+	 * Calculates given request profile messages timings.
+	 * @return array timings [token, category, timestamp, traces, nesting level, elapsed time]
+	 */
 	protected function calculateTimings()
 	{
-		if ($this->_timings !== null) {
+		if ($this->_timings === null) {
-			return $this->_timings;
+			$this->_timings = Yii::$app->getLog()->calculateTimings($this->data['messages']);
-		}
-		$messages = $this->data['messages'];
-		$timings = [];
-		$stack = [];
-		foreach ($messages as $i => $log) {
-			list($token, $level, $category, $timestamp) = $log;
-			$log[5] = $i;
-			if ($level == Logger::LEVEL_PROFILE_BEGIN) {
-				$stack[] = $log;
-			} elseif ($level == Logger::LEVEL_PROFILE_END) {
-				if (($last = array_pop($stack)) !== null && $last[0] === $token) {
-					$timings[$last[5]] = [count($stack), $token, $last[3], $timestamp - $last[3], $last[4]];
-				}
-			}
-		}
-
-		$now = microtime(true);
-		while (($last = array_pop($stack)) !== null) {
-			$delta = $now - $last[3];
-			$timings[$last[5]] = [count($stack), $last[0], $last[2], $delta, $last[4]];
 		}
-		ksort($timings);
+		return $this->_timings;
-		return $this->_timings = $timings;
 	}
 
 	public function save()
@@ -108,7 +91,7 @@ class DbPanel extends Panel
 		$queryTime = 0;
 
 		foreach ($timings as $timing) {
-			$queryTime += $timing[3];
+			$queryTime += $timing['duration'];
 		}
 
 		return $queryTime;
@@ -125,12 +108,14 @@ class DbPanel extends Panel
 			$this->_models = [];
 			$timings = $this->calculateTimings();
 
-			foreach($timings as $dbTiming) {
+			foreach($timings as $seq => $dbTiming) {
 				$this->_models[] = 	[
-					'type' => $this->detectQueryType($dbTiming[1]),
+					'type' => $this->detectQueryType($dbTiming['info']),
-					'query' => $dbTiming[1],
+					'query' => $dbTiming['info'],
-					'duration' => ($dbTiming[3] * 1000), #in milliseconds
+					'duration' => ($dbTiming['duration'] * 1000), #in milliseconds
-					'trace' => $dbTiming[4],
+					'trace' => $dbTiming['trace'],
+					'timestamp' => $dbTiming['timestamp'],
+					'seq' => $seq,
 				];
 			}
 		}

extensions/yii/debug/panels/ProfilingPanel.php

@@ -20,12 +20,6 @@ use yii\debug\models\search\Profile;
  */
 class ProfilingPanel extends Panel
 {
-
-	/**
-	 * @var array profile messages timings
-	 */
-	private $_timings;
-
 	/**
 	 * @var array current request profile timings
 	 */
@@ -59,37 +53,6 @@ class ProfilingPanel extends Panel
 		]);
 	}
 
-	/**
-	 * Calculates given request profile messages timings.
-	 * @return array timings [token, category, timestamp, traces, nesting level, elapsed time]
-	 */
-	protected function calculateTimings()
-	{
-		if ($this->_timings !== null) {
-			return $this->_timings;
-		}
-
-		$messages = $this->data['messages'];
-		$timings = [];
-		$stack = [];
-
-		foreach ($messages as $i => $log) {
-			list($token, $level, $category, $timestamp, $traces) = $log;
-			$log[5] = $i;
-			if ($level == Logger::LEVEL_PROFILE_BEGIN) {
-				$stack[] = $log;
-			} elseif ($level == Logger::LEVEL_PROFILE_END) {
-				if (($last = array_pop($stack)) !== null && $last[0] === $token) {
-					$timings[$last[5]] = [$last[0], $last[2], $last[3], $last[4], count($stack), $timestamp - $last[3]];
-				}
-			}
-		}
-
-		ksort($timings);
-
-		return $this->_timings = array_values($timings);
-	}
-
 	public function save()
 	{
 		$target = $this->module->logTarget;
@@ -109,15 +72,15 @@ class ProfilingPanel extends Panel
 	{
 		if ($this->_models === null) {
 			$this->_models = [];
-			$timings = $this->calculateTimings();
+			$timings = Yii::$app->getLog()->calculateTimings($this->data['messages']);
 
 			foreach($timings as $seq => $profileTiming) {
 				$this->_models[] = 	[
-					'duration' => $profileTiming[5] * 1000, // in milliseconds
+					'duration' => $profileTiming['duration'] * 1000, // in milliseconds
-					'category' => $profileTiming[1],
+					'category' => $profileTiming['category'],
-					'info' => $profileTiming[0],
+					'info' => $profileTiming['info'],
-					'level' => $profileTiming[4],
+					'level' => $profileTiming['level'],
-					'timestamp' => $profileTiming[2],
+					'timestamp' => $profileTiming['timestamp'],
 					'seq' => $seq,
 				];
 			}

extensions/yii/debug/views/default/panels/db/detail.php

@@ -14,15 +14,27 @@ echo GridView::widget([
 	'columns' => [
 		['class' => 'yii\grid\SerialColumn'],
 		[
+			'attribute' => 'seq',
+			'label' => 'Time',
+			'value' => function ($data) {
+				$timeInSeconds = $data['timestamp'] / 1000;
+				$millisecondsDiff = (int)(($timeInSeconds - (int)$timeInSeconds) * 1000);
+				return date('H:i:s.', $timeInSeconds) . sprintf('%03d', $millisecondsDiff);
+			},
+		],
+		[
 			'attribute' => 'duration',
 			'value' => function ($data) {
-				return sprintf('%.1f ms',$data['duration']);
+				return sprintf('%.1f ms', $data['duration']);
 			},
+			'options' => [
+				'width' => '10%',
+			],
 		],
 		[
 			'attribute' => 'type',
 			'value' => function ($data) {
-				return Html::encode(mb_strtoupper($data['type'],'utf8'));
+				return Html::encode(mb_strtoupper($data['type'], 'utf8'));
 			},
 		],
 		[
@@ -42,7 +54,7 @@ echo GridView::widget([
 			},
 			'format' => 'html',
 			'options' => [
-				'width' => '70%',
+				'width' => '60%',
 			],
 		]
 	],

extensions/yii/debug/views/default/panels/profile/detail.php

@@ -18,7 +18,7 @@ echo GridView::widget([
 			'value' => function ($data) {
 				$timeInSeconds = $data['timestamp'] / 1000;
 				$millisecondsDiff = (int)(($timeInSeconds - (int)$timeInSeconds) * 1000);
-				return date('H:i:s.',$timeInSeconds) . sprintf('%03d',$millisecondsDiff);
+				return date('H:i:s.', $timeInSeconds) . sprintf('%03d', $millisecondsDiff);
 			},
 		],
 		[

framework/yii/log/Logger.php

@@ -242,12 +242,12 @@ class Logger extends Component
 	 * For example, 'yii\db\*' will match categories starting with 'yii\db\',
 	 * such as 'yii\db\Connection'.
 	 * @param array $excludeCategories list of categories that you want to exclude
-	 * @return array the profiling results. Each array element has the following structure:
+	 * @return array the profiling results. Each element is an array consisting of these elements:
-	 *  `[$token, $category, $time]`.
+	 * `info`, `category`, `timestamp`, `trace`, `level`, `duration`.
 	 */
 	public function getProfiling($categories = [], $excludeCategories = [])
 	{
-		$timings = $this->calculateTimings();
+		$timings = $this->calculateTimings($this->messages);
 		if (empty($categories) && empty($excludeCategories)) {
 			return $timings;
 		}
@@ -256,7 +256,7 @@ class Logger extends Component
 			$matched = empty($categories);
 			foreach ($categories as $category) {
 				$prefix = rtrim($category, '*');
-				if (strpos($timing[1], $prefix) === 0 && ($timing[1] === $category || $prefix !== $category)) {
+				if (strpos($timing['category'], $prefix) === 0 && ($timing['category'] === $category || $prefix !== $category)) {
 					$matched = true;
 					break;
 				}
@@ -266,7 +266,7 @@ class Logger extends Component
 				foreach ($excludeCategories as $category) {
 					$prefix = rtrim($category, '*');
 					foreach ($timings as $i => $timing) {
-						if (strpos($timing[1], $prefix) === 0 && ($timing[1] === $category || $prefix !== $category)) {
+						if (strpos($timing['category'], $prefix) === 0 && ($timing['category'] === $category || $prefix !== $category)) {
 							$matched = false;
 							break;
 						}
@@ -294,37 +294,47 @@ class Logger extends Component
 		$count = count($timings);
 		$time = 0;
 		foreach ($timings as $timing) {
-			$time += $timing[1];
+			$time += $timing['duration'];
 		}
 		return [$count, $time];
 	}
 
-	private function calculateTimings()
+	/**
+	 * Calculates the elapsed time for the given log messages.
+	 * @param array $messages the log messages obtained from profiling
+	 * @return array timings. Each element is an array consisting of these elements:
+	 * `info`, `category`, `timestamp`, `trace`, `level`, `duration`.
+	 */
+	public function calculateTimings($messages)
 	{
 		$timings = [];
 		$stack = [];
-		foreach ($this->messages as $log) {
+
-			list($token, $level, $category, $timestamp) = $log;
+		foreach ($messages as $i => $log) {
-			if ($level == self::LEVEL_PROFILE_BEGIN) {
+			list($token, $level, $category, $timestamp, $traces) = $log;
+			$log[5] = $i;
+			if ($level == Logger::LEVEL_PROFILE_BEGIN) {
 				$stack[] = $log;
-			} elseif ($level == self::LEVEL_PROFILE_END) {
+			} elseif ($level == Logger::LEVEL_PROFILE_END) {
 				if (($last = array_pop($stack)) !== null && $last[0] === $token) {
-					$timings[] = [$token, $category, $timestamp - $last[3]];
+					$timings[$last[5]] = [
-				} else {
+						'info' => $last[0],
-					throw new InvalidConfigException("Unmatched profiling block: $token");
+						'category' => $last[2],
+						'timestamp' => $last[3],
+						'trace' => $last[4],
+						'level' => count($stack),
+						'duration' => $timestamp - $last[3],
+					];
 				}
 			}
 		}
 
-		$now = microtime(true);
+		ksort($timings);
-		while (($last = array_pop($stack)) !== null) {
-			$delta = $now - $last[3];
-			$timings[] = [$last[0], $last[2], $delta];
-		}
 
-		return $timings;
+		return array_values($timings);
 	}
 
+
 	/**
 	 * Returns the text display of the specified level.
 	 * @param integer $level the message level, e.g. [[LEVEL_ERROR]], [[LEVEL_WARNING]].