From 0469fac1af6cf22e4c6ca170ba04cff1fbb76f15 Mon Sep 17 00:00:00 2001 From: Denitz <197527+Denitz@users.noreply.github.com> Date: Mon, 11 Sep 2023 09:56:29 +0300 Subject: [PATCH] [4.4] Invalid timings in debug plugin (#35655) * start * phpcs fix * docblock fix * docblocks fix * custom memory collector * cs fix * fix cs * even more cs * Update plugins/system/cache/cache.php Co-authored-by: Phil E. Taylor * Update plugins/system/debug/src/DataCollector/MemoryCollector.php Co-authored-by: Phil E. Taylor * Update plugins/system/debug/src/DataCollector/MemoryCollector.php Co-authored-by: Phil E. Taylor * Update plugins/system/debug/src/DataCollector/ProfileCollector.php Co-authored-by: Phil E. Taylor * Update plugins/system/debug/src/DataCollector/ProfileCollector.php Co-authored-by: Phil E. Taylor * cs * cs * revert ProfileCollector constructor. * fix * Remove 'afterRespond' mark * fix * Phase 1 convert BRANCH to PSR-12 * Phase 2 convert BRANCH to PSR-12 * fix * fix CS * fix * short Event, try to re-start drone --------- Co-authored-by: Denitz Co-authored-by: Phil E. Taylor Co-authored-by: Joomla! Bot --- .../src/DataCollector/MemoryCollector.php | 151 ++++++++++++++++++ .../src/DataCollector/ProfileCollector.php | 65 +++++--- plugins/system/debug/src/Extension/Debug.php | 91 ++++++----- 3 files changed, 243 insertions(+), 64 deletions(-) create mode 100644 plugins/system/debug/src/DataCollector/MemoryCollector.php diff --git a/plugins/system/debug/src/DataCollector/MemoryCollector.php b/plugins/system/debug/src/DataCollector/MemoryCollector.php new file mode 100644 index 00000000000..6bac4d1644f --- /dev/null +++ b/plugins/system/debug/src/DataCollector/MemoryCollector.php @@ -0,0 +1,151 @@ + + * @license GNU General Public License version 2 or later; see LICENSE.txt + */ + +namespace Joomla\Plugin\System\Debug\DataCollector; + +use Joomla\Plugin\System\Debug\AbstractDataCollector; +use Joomla\Registry\Registry; + +// phpcs:disable PSR1.Files.SideEffects +\defined('_JEXEC') or die; +// phpcs:enable PSR1.Files.SideEffects + +/** + * Collects info about the request duration as well as providing + * a way to log duration of any operations + * + * @since __DEPLOY_VERSION__ + */ +class MemoryCollector extends AbstractDataCollector +{ + /** + * @var boolean + * @since __DEPLOY_VERSION__ + */ + protected $realUsage = false; + + /** + * @var float + * @since __DEPLOY_VERSION__ + */ + protected $peakUsage = 0; + + /** + * @param Registry $params Parameters. + * @param float $peakUsage + * @param boolean $realUsage + * + * @since __DEPLOY_VERSION__ + */ + public function __construct(Registry $params, $peakUsage = null, $realUsage = null) + { + parent::__construct($params); + + if ($peakUsage !== null) { + $this->peakUsage = $peakUsage; + } + + if ($realUsage !== null) { + $this->realUsage = $realUsage; + } + } + + /** + * Returns whether total allocated memory page size is used instead of actual used memory size + * by the application. See $real_usage parameter on memory_get_peak_usage for details. + * + * @return boolean + * + * @since __DEPLOY_VERSION__ + */ + public function getRealUsage() + { + return $this->realUsage; + } + + /** + * Sets whether total allocated memory page size is used instead of actual used memory size + * by the application. See $real_usage parameter on memory_get_peak_usage for details. + * + * @param boolean $realUsage + * + * @since __DEPLOY_VERSION__ + */ + public function setRealUsage($realUsage) + { + $this->realUsage = $realUsage; + } + + /** + * Returns the peak memory usage + * + * @return integer + * + * @since __DEPLOY_VERSION__ + */ + public function getPeakUsage() + { + return $this->peakUsage; + } + + /** + * Updates the peak memory usage value + * + * @since __DEPLOY_VERSION__ + */ + public function updatePeakUsage() + { + if ($this->peakUsage === null) { + $this->peakUsage = memory_get_peak_usage($this->realUsage); + } + } + + /** + * @return array + * + * @since __DEPLOY_VERSION__ + */ + public function collect() + { + $this->updatePeakUsage(); + + return [ + 'peak_usage' => $this->peakUsage, + 'peak_usage_str' => $this->getDataFormatter()->formatBytes($this->peakUsage, 3), + ]; + } + + /** + * @return string + * + * @since __DEPLOY_VERSION__ + */ + public function getName() + { + return 'memory'; + } + + /** + * @return array + * + * @since __DEPLOY_VERSION__ + */ + public function getWidgets() + { + return [ + 'memory' => [ + 'icon' => 'cogs', + 'tooltip' => 'Memory Usage', + 'map' => 'memory.peak_usage_str', + 'default' => "'0B'", + ], + ]; + } +} diff --git a/plugins/system/debug/src/DataCollector/ProfileCollector.php b/plugins/system/debug/src/DataCollector/ProfileCollector.php index 0c1de924b7a..381ae45ff2a 100644 --- a/plugins/system/debug/src/DataCollector/ProfileCollector.php +++ b/plugins/system/debug/src/DataCollector/ProfileCollector.php @@ -84,8 +84,9 @@ class ProfileCollector extends AbstractDataCollector * @param string|null $label Public name * @param string|null $collector The source of the collector * - * @since 4.0.0 * @return void + * + * @since 4.0.0 */ public function startMeasure($name, $label = null, $collector = null) { @@ -103,8 +104,9 @@ class ProfileCollector extends AbstractDataCollector * * @param string $name Group name. * - * @since 4.0.0 * @return bool + * + * @since 4.0.0 */ public function hasStartedMeasure($name): bool { @@ -117,9 +119,11 @@ class ProfileCollector extends AbstractDataCollector * @param string $name Measurement name. * @param array $params Parameters * - * @since 4.0.0 - * @throws DebugBarException * @return void + * + * @since 4.0.0 + * + * @throws DebugBarException */ public function stopMeasure($name, array $params = []) { @@ -129,13 +133,7 @@ class ProfileCollector extends AbstractDataCollector throw new DebugBarException("Failed stopping measure '$name' because it hasn't been started"); } - $this->addMeasure( - $this->startedMeasures[$name]['label'], - $this->startedMeasures[$name]['start'], - $end, - $params, - $this->startedMeasures[$name]['collector'] - ); + $this->addMeasure($this->startedMeasures[$name]['label'], $this->startedMeasures[$name]['start'], $end, $params, $this->startedMeasures[$name]['collector']); unset($this->startedMeasures[$name]); } @@ -149,8 +147,9 @@ class ProfileCollector extends AbstractDataCollector * @param array $params Parameters. * @param string|null $collector A collector. * - * @since 4.0.0 * @return void + * + * @since 4.0.0 */ public function addMeasure($label, $start, $end, array $params = [], $collector = null) { @@ -174,8 +173,9 @@ class ProfileCollector extends AbstractDataCollector * @param \Closure $closure A closure. * @param string|null $collector A collector. * - * @since 4.0.0 * @return void + * + * @since 4.0.0 */ public function measure($label, \Closure $closure, $collector = null) { @@ -189,8 +189,9 @@ class ProfileCollector extends AbstractDataCollector /** * Returns an array of all measures * - * @since 4.0.0 * @return array + * + * @since 4.0.0 */ public function getMeasures(): array { @@ -200,8 +201,9 @@ class ProfileCollector extends AbstractDataCollector /** * Returns the request start time * - * @since 4.0.0 * @return float + * + * @since 4.0.0 */ public function getRequestStartTime(): float { @@ -211,8 +213,9 @@ class ProfileCollector extends AbstractDataCollector /** * Returns the request end time * - * @since 4.0.0 * @return float + * + * @since 4.0.0 */ public function getRequestEndTime(): float { @@ -222,8 +225,9 @@ class ProfileCollector extends AbstractDataCollector /** * Returns the duration of a request * - * @since 4.0.0 * @return float + * + * @since 4.0.0 */ public function getRequestDuration(): float { @@ -234,15 +238,32 @@ class ProfileCollector extends AbstractDataCollector return microtime(true) - $this->requestStartTime; } + /** + * Sets request end time. + * + * @param float $time Request end time. + * + * @return $this + * + * @since __DEPLOY_VERSION__ + */ + public function setRequestEndTime($time): self + { + $this->requestEndTime = $time; + + return $this; + } + /** * Called by the DebugBar when data needs to be collected * - * @since 4.0.0 * @return array Collected data + * + * @since 4.0.0 */ public function collect(): array { - $this->requestEndTime = microtime(true); + $this->requestEndTime = $this->requestEndTime ?? microtime(true); $start = $this->requestStartTime; @@ -284,8 +305,9 @@ class ProfileCollector extends AbstractDataCollector /** * Returns the unique name of the collector * - * @since 4.0.0 * @return string + * + * @since 4.0.0 */ public function getName(): string { @@ -296,8 +318,9 @@ class ProfileCollector extends AbstractDataCollector * Returns a hash where keys are control names and their values * an array of options as defined in {@see \DebugBar\JavascriptRenderer::addControl()} * - * @since 4.0.0 * @return array + * + * @since 4.0.0 */ public function getWidgets(): array { diff --git a/plugins/system/debug/src/Extension/Debug.php b/plugins/system/debug/src/Extension/Debug.php index dfc909023f7..70ea776277e 100644 --- a/plugins/system/debug/src/Extension/Debug.php +++ b/plugins/system/debug/src/Extension/Debug.php @@ -10,7 +10,6 @@ namespace Joomla\Plugin\System\Debug\Extension; -use DebugBar\DataCollector\MemoryCollector; use DebugBar\DataCollector\MessagesCollector; use DebugBar\DebugBar; use DebugBar\OpenHandler; @@ -28,11 +27,13 @@ use Joomla\Database\DatabaseAwareTrait; use Joomla\Database\DatabaseInterface; use Joomla\Database\Event\ConnectionEvent; use Joomla\Event\DispatcherInterface; +use Joomla\Event\Event; use Joomla\Event\SubscriberInterface; use Joomla\Plugin\System\Debug\DataCollector\InfoCollector; use Joomla\Plugin\System\Debug\DataCollector\LanguageErrorsCollector; use Joomla\Plugin\System\Debug\DataCollector\LanguageFilesCollector; use Joomla\Plugin\System\Debug\DataCollector\LanguageStringsCollector; +use Joomla\Plugin\System\Debug\DataCollector\MemoryCollector; use Joomla\Plugin\System\Debug\DataCollector\ProfileCollector; use Joomla\Plugin\System\Debug\DataCollector\QueryCollector; use Joomla\Plugin\System\Debug\DataCollector\RequestDataCollector; @@ -68,7 +69,7 @@ final class Debug extends CMSPlugin implements SubscriberInterface * @var boolean * @since 3.0 */ - private $debugLang = false; + private $debugLang; /** * Holds log entries handled by the plugin. @@ -78,14 +79,6 @@ final class Debug extends CMSPlugin implements SubscriberInterface */ private $logEntries = []; - /** - * Holds SHOW PROFILES of queries. - * - * @var array - * @since 3.1.2 - */ - private $sqlShowProfiles = []; - /** * Holds all SHOW PROFILE FOR QUERY n, indexed by n-1. * @@ -102,14 +95,6 @@ final class Debug extends CMSPlugin implements SubscriberInterface */ private $explains = []; - /** - * Holds total amount of executed queries. - * - * @var int - * @since 3.2 - */ - private $totalQueries = 0; - /** * @var DebugBar * @since 4.0.0 @@ -133,7 +118,7 @@ final class Debug extends CMSPlugin implements SubscriberInterface protected $isAjax = false; /** - * Whether displaing a logs is enabled + * Whether displaying a logs is enabled * * @var bool * @since 4.0.0 @@ -141,8 +126,14 @@ final class Debug extends CMSPlugin implements SubscriberInterface protected $showLogs = false; /** - * Returns an array of events this subscriber will listen to. + * The time spent in onAfterDisconnect() * + * @var float + * @since __DEPLOY_VERSION__ + */ + protected $timeInOnAfterDisconnect = 0; + + /** * @return array * * @since 4.1.3 @@ -150,12 +141,18 @@ final class Debug extends CMSPlugin implements SubscriberInterface public static function getSubscribedEvents(): array { return [ - 'onBeforeCompileHead' => 'onBeforeCompileHead', - 'onAjaxDebug' => 'onAjaxDebug', - 'onBeforeRespond' => 'onBeforeRespond', - 'onAfterRespond' => 'onAfterRespond', - ApplicationEvents::AFTER_RESPOND => 'onAfterRespond', - 'onAfterDisconnect' => 'onAfterDisconnect', + 'onBeforeCompileHead' => 'onBeforeCompileHead', + 'onAjaxDebug' => 'onAjaxDebug', + 'onBeforeRespond' => 'onBeforeRespond', + 'onAfterRespond' => [ + 'onAfterRespond', + PHP_INT_MIN, + ], + ApplicationEvents::AFTER_RESPOND => [ + 'onAfterRespond', + PHP_INT_MIN, + ], + 'onAfterDisconnect' => 'onAfterDisconnect', ]; } @@ -181,7 +178,7 @@ final class Debug extends CMSPlugin implements SubscriberInterface return; } - $this->getApplication()->getConfig()->set('gzip', false); + $this->getApplication()->set('gzip', false); ob_start(); ob_implicit_flush(false); @@ -269,8 +266,11 @@ final class Debug extends CMSPlugin implements SubscriberInterface */ public function onAfterRespond() { + $endTime = microtime(true) - $this->timeInOnAfterDisconnect; + $endMemory = memory_get_peak_usage(false); + // Do not collect data if debugging or language debug is not enabled. - if (!JDEBUG && !$this->debugLang || $this->isAjax) { + if ((!JDEBUG && !$this->debugLang) || $this->isAjax) { return; } @@ -287,7 +287,7 @@ final class Debug extends CMSPlugin implements SubscriberInterface if (JDEBUG) { if ($this->params->get('memory', 1)) { - $this->debugBar->addCollector(new MemoryCollector()); + $this->debugBar->addCollector(new MemoryCollector($this->params, $endMemory)); } if ($this->params->get('request', 1)) { @@ -299,10 +299,13 @@ final class Debug extends CMSPlugin implements SubscriberInterface } if ($this->params->get('profile', 1)) { - $this->debugBar->addCollector(new ProfileCollector($this->params)); + $this->debugBar->addCollector((new ProfileCollector($this->params))->setRequestEndTime($endTime)); } if ($this->params->get('queries', 1)) { + // Close session to collect possible session-related queries. + $this->getApplication()->getSession()->close(); + // Call $db->disconnect() here to trigger the onAfterDisconnect() method here in this class! $this->getDatabase()->disconnect(); $this->debugBar->addCollector(new QueryCollector($this->params, $this->queryMonitor, $this->sqlShowProfileEach, $this->explains)); @@ -364,7 +367,7 @@ final class Debug extends CMSPlugin implements SubscriberInterface /** * AJAX handler * - * @param Joomla\Event\Event $event + * @param Event $event * * @return void * @@ -389,6 +392,7 @@ final class Debug extends CMSPlugin implements SubscriberInterface $result[] = $handler->handle($this->getApplication()->getInput()->request->getArray(), false, false); $event['result'] = $result; + break; } } @@ -401,7 +405,7 @@ final class Debug extends CMSPlugin implements SubscriberInterface */ private function isAuthorisedDisplayDebug(): bool { - static $result = null; + static $result; if ($result !== null) { return $result; @@ -440,13 +444,13 @@ final class Debug extends CMSPlugin implements SubscriberInterface return; } + $startTime = microtime(true); + $db = $event->getDriver(); // Remove the monitor to avoid monitoring the following queries $db->setMonitor(null); - $this->totalQueries = $db->getCount(); - if ($this->params->get('query_profiles') && $db->getServerType() === 'mysql') { try { // Check if profiling is enabled. @@ -456,13 +460,13 @@ final class Debug extends CMSPlugin implements SubscriberInterface if ($hasProfiling) { // Run a SHOW PROFILE query. $db->setQuery('SHOW PROFILES'); - $this->sqlShowProfiles = $db->loadAssocList(); + $sqlShowProfiles = $db->loadAssocList(); - if ($this->sqlShowProfiles) { - foreach ($this->sqlShowProfiles as $qn) { + if ($sqlShowProfiles) { + foreach ($sqlShowProfiles as $qn) { // Run SHOW PROFILE FOR QUERY for each query where a profile is available (max 100). $db->setQuery('SHOW PROFILE FOR QUERY ' . (int) $qn['Query_ID']); - $this->sqlShowProfileEach[(int) ($qn['Query_ID'] - 1)] = $db->loadAssocList(); + $this->sqlShowProfileEach[$qn['Query_ID'] - 1] = $db->loadAssocList(); } } } else { @@ -503,6 +507,8 @@ final class Debug extends CMSPlugin implements SubscriberInterface } } } + + $this->timeInOnAfterDisconnect = microtime(true) - $startTime; } /** @@ -530,18 +536,18 @@ final class Debug extends CMSPlugin implements SubscriberInterface /** * Collect log messages. * - * @return $this + * @return void * * @since 4.0.0 */ - private function collectLogs(): self + private function collectLogs() { $loggerOptions = ['group' => 'default']; $logger = new InMemoryLogger($loggerOptions); $logEntries = $logger->getCollectedEntries(); if (!$this->logEntries && !$logEntries) { - return $this; + return; } if ($this->logEntries) { @@ -569,6 +575,7 @@ final class Debug extends CMSPlugin implements SubscriberInterface $this->debugBar[$entry->category]->addMessage($entry->message); } break; + case 'deprecated': if (!$logDeprecated && !$logDeprecatedCore) { break; @@ -643,8 +650,6 @@ final class Debug extends CMSPlugin implements SubscriberInterface break; } } - - return $this; } /**