X-Git-Url: https://git.mxchange.org/?a=blobdiff_plain;f=src%2FUtil%2FProfiler.php;h=24289678c266a41450b751fff3b6132ff8355cd7;hb=c33611c484e2cf5a3c626566588e26a1d14e12c6;hp=2d3da3a9c0b99f762a29f9b9bb9e7288a87ab337;hpb=256e845c5dd606d6e0f1d401a0859b6f8728fb2d;p=friendica.git diff --git a/src/Util/Profiler.php b/src/Util/Profiler.php index 2d3da3a9c0..24289678c2 100644 --- a/src/Util/Profiler.php +++ b/src/Util/Profiler.php @@ -1,7 +1,29 @@ . + * + */ namespace Friendica\Util; +use Friendica\Core\Config\ValueObject\Cache; +use Friendica\Core\Config\Capability\IManageConfigValues; +use Friendica\Core\System; use Psr\Container\ContainerExceptionInterface; use Psr\Container\ContainerInterface; use Psr\Container\NotFoundExceptionInterface; @@ -11,7 +33,7 @@ use Psr\Log\LoggerInterface; * A class to store profiling data * It can handle different logging data for specific functions or global performance measures * - * It stores the data as log entries (@see LoggerInterface ) + * It stores the data as log entries (@see LoggerInterface) */ class Profiler implements ContainerInterface { @@ -32,24 +54,99 @@ class Profiler implements ContainerInterface */ private $rendertime; + private $timestamps = []; + /** - * @param bool $enabled True, if the Profiler is enabled - * @param bool $renderTime True, if the Profiler should measure the whole rendertime including functions + * True, if the Profiler should measure the whole rendertime including functions + * + * @return bool + */ + public function isRendertime() + { + return $this->rendertime; + } + + /** + * Updates the enabling of the current profiler + * + * @param IManageConfigValues $config */ - public function __construct($enabled = false, $renderTime = false) + public function update(IManageConfigValues $config) { - $this->enabled = $enabled; - $this->rendertime = $renderTime; + $this->enabled = $config->get('system', 'profiler'); + $this->rendertime = $config->get('rendertime', 'callstack'); + } + + /** + * @param \Friendica\Core\Config\ValueObject\Cache $configCache The configuration cache + */ + public function __construct(Cache $configCache) + { + $this->enabled = $configCache->get('system', 'profiler'); + $this->rendertime = $configCache->get('rendertime', 'callstack'); $this->reset(); } + /** + * Start a profiler recording + * + * @param string $value + * @return void + */ + public function startRecording(string $value) + { + if (!$this->enabled) { + return; + } + + $this->timestamps[] = ['value' => $value, 'stamp' => microtime(true), 'credit' => 0]; + } + + /** + * Stop a profiler recording + * + * @param string $callstack + * @return void + */ + public function stopRecording(string $callstack = '') + { + if (!$this->enabled || empty($this->timestamps)) { + return; + } + + $timestamp = array_pop($this->timestamps); + + $duration = floatval(microtime(true) - $timestamp['stamp'] - $timestamp['credit']); + $value = $timestamp['value']; + + foreach ($this->timestamps as $key => $stamp) { + $this->timestamps[$key]['credit'] += $duration; + } + + $callstack = $callstack ?: System::callstack(4, $value == 'rendering' ? 0 : 1); + + if (!isset($this->performance[$value])) { + $this->performance[$value] = 0; + } + + $this->performance[$value] += (float) $duration; + $this->performance['marktime'] += (float) $duration; + + if (!isset($this->callstack[$value][$callstack])) { + // Prevent ugly E_NOTICE + $this->callstack[$value][$callstack] = 0; + } + + $this->callstack[$value][$callstack] += (float) $duration; + } + /** * Saves a timestamp for a value - f.e. a call * Necessary for profiling Friendica * - * @param int $timestamp the Timestamp - * @param string $value A value to profile - * @param string $callstack The callstack of the current profiling data + * @param int $timestamp the Timestamp + * @param string $value A value to profile + * @param string $callstack A callstack string, generated if absent */ public function saveTimestamp($timestamp, $value, $callstack = '') { @@ -57,7 +154,9 @@ class Profiler implements ContainerInterface return; } - $duration = (float) (microtime(true) - $timestamp); + $callstack = $callstack ?: System::callstack(4, 1); + + $duration = floatval(microtime(true) - $timestamp); if (!isset($this->performance[$value])) { // Prevent ugly E_NOTICE @@ -91,6 +190,7 @@ class Profiler implements ContainerInterface { $this->performance = []; $this->performance['start'] = microtime(true); + $this->performance['ready'] = 0; $this->performance['database'] = 0; $this->performance['database_write'] = 0; $this->performance['cache'] = 0; @@ -98,9 +198,13 @@ class Profiler implements ContainerInterface $this->performance['network'] = 0; $this->performance['file'] = 0; $this->performance['rendering'] = 0; - $this->performance['parser'] = 0; + $this->performance['session'] = 0; $this->performance['marktime'] = 0; $this->performance['marktime'] = microtime(true); + $this->performance['classcreate'] = 0; + $this->performance['classinit'] = 0; + $this->performance['init'] = 0; + $this->performance['content'] = 0; } /** @@ -116,90 +220,112 @@ class Profiler implements ContainerInterface $this->callstack['network'] = []; $this->callstack['file'] = []; $this->callstack['rendering'] = []; - $this->callstack['parser'] = []; + $this->callstack['session'] = []; } /** - * Save the current profiling data to a log entry + * Returns the rendertime string + * @param float $limit Minimal limit for displaying the execution duration * - * @param LoggerInterface $logger The logger to save the current log - * @param string $message Additional message for the log + * @return string the rendertime */ - public function saveLog(LoggerInterface $logger, $message = '') + public function getRendertimeString(float $limit = 0) { - // Write down the performance values into the log - if (!$this->enabled) { - return; - } - $duration = microtime(true) - $this->get('start'); - $logger->info( - $message, - [ - 'action' => 'profiling', - 'database_read' => round($this->get('database') - $this->get('database_write'), 3), - 'database_write' => round($this->get('database_write'), 3), - 'cache_read' => round($this->get('cache'), 3), - 'cache_write' => round($this->get('cache_write'), 3), - 'network_io' => round($this->get('network'), 2), - 'file_io' => round($this->get('file'), 2), - 'other_io' => round($duration - ($this->get('database') - + $this->get('cache') + $this->get('cache_write') - + $this->get('network') + $this->get('file')), 2), - 'total' => round($duration, 2) - ] - ); + $output = ''; - if (!$this->rendertime) { - return; + if (!$this->enabled || !$this->rendertime) { + return $output; } - - $o = ''; + if (isset($this->callstack["database"])) { - $o .= "\nDatabase Read:\n"; + $output .= "\nDatabase Read:\n"; foreach ($this->callstack["database"] as $func => $time) { $time = round($time, 3); - if ($time > 0) { - $o .= $func . ": " . $time . "\n"; + if ($time > $limit) { + $output .= $func . ": " . $time . "\n"; } } } if (isset($this->callstack["database_write"])) { - $o .= "\nDatabase Write:\n"; + $output .= "\nDatabase Write:\n"; foreach ($this->callstack["database_write"] as $func => $time) { $time = round($time, 3); - if ($time > 0) { - $o .= $func . ": " . $time . "\n"; + if ($time > $limit) { + $output .= $func . ": " . $time . "\n"; } } } if (isset($this->callstack["cache"])) { - $o .= "\nCache Read:\n"; + $output .= "\nCache Read:\n"; foreach ($this->callstack["cache"] as $func => $time) { $time = round($time, 3); - if ($time > 0) { - $o .= $func . ": " . $time . "\n"; + if ($time > $limit) { + $output .= $func . ": " . $time . "\n"; } } } if (isset($this->callstack["cache_write"])) { - $o .= "\nCache Write:\n"; + $output .= "\nCache Write:\n"; foreach ($this->callstack["cache_write"] as $func => $time) { $time = round($time, 3); - if ($time > 0) { - $o .= $func . ": " . $time . "\n"; + if ($time > $limit) { + $output .= $func . ": " . $time . "\n"; } } } if (isset($this->callstack["network"])) { - $o .= "\nNetwork:\n"; + $output .= "\nNetwork:\n"; foreach ($this->callstack["network"] as $func => $time) { $time = round($time, 3); - if ($time > 0) { - $o .= $func . ": " . $time . "\n"; + if ($time > $limit) { + $output .= $func . ": " . $time . "\n"; } } } - $logger->info($message . ": " . $o, ['action' => 'profiling']); + + if (isset($this->callstack["rendering"])) { + $output .= "\nRendering:\n"; + foreach ($this->callstack["rendering"] as $func => $time) { + $time = round($time, 3); + if ($time > $limit) { + $output .= $func . ": " . $time . "\n"; + } + } + } + + return $output; + } + + /** + * Save the current profiling data to a log entry + * + * @param LoggerInterface $logger The logger to save the current log + * @param string $message Additional message for the log + */ + public function saveLog(LoggerInterface $logger, $message = '') + { + $duration = microtime(true) - $this->get('start'); + $logger->info( + $message, + [ + 'action' => 'profiling', + 'database_read' => round($this->get('database') - $this->get('database_write'), 3), + 'database_write' => round($this->get('database_write'), 3), + 'cache_read' => round($this->get('cache'), 3), + 'cache_write' => round($this->get('cache_write'), 3), + 'network_io' => round($this->get('network'), 2), + 'file_io' => round($this->get('file'), 2), + 'other_io' => round($duration - ($this->get('database') + + $this->get('cache') + $this->get('cache_write') + + $this->get('network') + $this->get('file')), 2), + 'total' => round($duration, 2) + ] + ); + + if ($this->isRendertime()) { + $output = $this->getRendertimeString(); + $logger->info($message . ": " . $output, ['action' => 'profiling']); + } } /** @@ -221,6 +347,11 @@ class Profiler implements ContainerInterface } } + public function set($timestamp, $id) + { + $this->performance[$id] = $timestamp; + } + /** * Returns true if the container can return an entry for the given identifier. * Returns false otherwise.