From 978f8ec203acc539e06207983f9ab1d3a91d9dfc Mon Sep 17 00:00:00 2001 From: Qiang Xue Date: Tue, 31 Dec 2013 17:49:31 -0500 Subject: [PATCH] refactored profiling timing calculation. --- extensions/yii/debug/models/search/Db.php | 2 +- extensions/yii/debug/panels/DbPanel.php | 45 +++++++------------ extensions/yii/debug/panels/ProfilingPanel.php | 49 +++------------------ .../yii/debug/views/default/panels/db/detail.php | 20 +++++++-- .../debug/views/default/panels/profile/detail.php | 2 +- framework/yii/log/Logger.php | 50 +++++++++++++--------- 6 files changed, 69 insertions(+), 99 deletions(-) diff --git a/extensions/yii/debug/models/search/Db.php b/extensions/yii/debug/models/search/Db.php index 25cdbbd..679ef77 100644 --- a/extensions/yii/debug/models/search/Db.php +++ b/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, ], diff --git a/extensions/yii/debug/panels/DbPanel.php b/extensions/yii/debug/panels/DbPanel.php index 043cfab..2366ff8 100644 --- a/extensions/yii/debug/panels/DbPanel.php +++ b/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) { - return $this->_timings; - } - $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]]; + if ($this->_timings === null) { + $this->_timings = Yii::$app->getLog()->calculateTimings($this->data['messages']); } - ksort($timings); - return $this->_timings = $timings; + return $this->_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]), - 'query' => $dbTiming[1], - 'duration' => ($dbTiming[3] * 1000), #in milliseconds - 'trace' => $dbTiming[4], + 'type' => $this->detectQueryType($dbTiming['info']), + 'query' => $dbTiming['info'], + 'duration' => ($dbTiming['duration'] * 1000), #in milliseconds + 'trace' => $dbTiming['trace'], + 'timestamp' => $dbTiming['timestamp'], + 'seq' => $seq, ]; } } diff --git a/extensions/yii/debug/panels/ProfilingPanel.php b/extensions/yii/debug/panels/ProfilingPanel.php index 740a98c..855ffd1 100644 --- a/extensions/yii/debug/panels/ProfilingPanel.php +++ b/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 - 'category' => $profileTiming[1], - 'info' => $profileTiming[0], - 'level' => $profileTiming[4], - 'timestamp' => $profileTiming[2], + 'duration' => $profileTiming['duration'] * 1000, // in milliseconds + 'category' => $profileTiming['category'], + 'info' => $profileTiming['info'], + 'level' => $profileTiming['level'], + 'timestamp' => $profileTiming['timestamp'], 'seq' => $seq, ]; } diff --git a/extensions/yii/debug/views/default/panels/db/detail.php b/extensions/yii/debug/views/default/panels/db/detail.php index 4faaae3..ad46636 100644 --- a/extensions/yii/debug/views/default/panels/db/detail.php +++ b/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,9 +54,9 @@ echo GridView::widget([ }, 'format' => 'html', 'options' => [ - 'width' => '70%', + 'width' => '60%', ], ] ], ]); -?> \ No newline at end of file +?> diff --git a/extensions/yii/debug/views/default/panels/profile/detail.php b/extensions/yii/debug/views/default/panels/profile/detail.php index 485d6af..8c4c346 100644 --- a/extensions/yii/debug/views/default/panels/profile/detail.php +++ b/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); }, ], [ diff --git a/framework/yii/log/Logger.php b/framework/yii/log/Logger.php index 1629b9b..e7c639c 100644 --- a/framework/yii/log/Logger.php +++ b/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: - * `[$token, $category, $time]`. + * @return array the profiling results. Each element is an array consisting of these elements: + * `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; - if ($level == self::LEVEL_PROFILE_BEGIN) { + + 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 == 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]]; - } else { - throw new InvalidConfigException("Unmatched profiling block: $token"); + $timings[$last[5]] = [ + 'info' => $last[0], + 'category' => $last[2], + 'timestamp' => $last[3], + 'trace' => $last[4], + 'level' => count($stack), + 'duration' => $timestamp - $last[3], + ]; } } } - $now = microtime(true); - while (($last = array_pop($stack)) !== null) { - $delta = $now - $last[3]; - $timings[] = [$last[0], $last[2], $delta]; - } + ksort($timings); - 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]].