From afb882048efa8c4b2914a6b054b129dee57061ef Mon Sep 17 00:00:00 2001 From: Hypolite Petovan Date: Mon, 27 Jul 2020 00:22:07 -0400 Subject: [PATCH] Generate callstack value from inside Profiler::saveTimestamp - Save a massive amount of time computing callstacks when profiling is disabled --- src/Content/Text/BBCode.php | 6 +++--- src/Content/Text/Markdown.php | 2 +- src/Core/Addon.php | 2 +- src/Core/Cache/ProfilerCache.php | 16 ++++++++-------- src/Core/Renderer.php | 4 ++-- src/Core/Theme.php | 2 +- src/Database/Database.php | 8 ++++---- src/Factory/SessionFactory.php | 2 +- src/Network/HTTPRequest.php | 8 ++++---- src/Object/Image.php | 2 +- src/Util/Images.php | 2 +- src/Util/Logger/ProfilerLogger.php | 18 +++++++++--------- src/Util/Profiler.php | 9 ++++++--- 13 files changed, 42 insertions(+), 39 deletions(-) diff --git a/src/Content/Text/BBCode.php b/src/Content/Text/BBCode.php index 1181c8f47..cae3e941a 100644 --- a/src/Content/Text/BBCode.php +++ b/src/Content/Text/BBCode.php @@ -1098,7 +1098,7 @@ class BBCode @curl_exec($ch); $curl_info = @curl_getinfo($ch); - DI::profiler()->saveTimestamp($stamp1, "network", System::callstack()); + DI::profiler()->saveTimestamp($stamp1, "network"); if (substr($curl_info['content_type'], 0, 6) == 'image/') { $text = "[url=" . $match[1] . ']' . $match[1] . "[/url]"; @@ -1172,7 +1172,7 @@ class BBCode @curl_exec($ch); $curl_info = @curl_getinfo($ch); - DI::profiler()->saveTimestamp($stamp1, "network", System::callstack()); + DI::profiler()->saveTimestamp($stamp1, "network"); // if its a link to a picture then embed this picture if (substr($curl_info['content_type'], 0, 6) == 'image/') { @@ -2045,7 +2045,7 @@ class BBCode // Now convert HTML to Markdown $text = HTML::toMarkdown($text); - DI::profiler()->saveTimestamp($stamp1, "parser", System::callstack()); + DI::profiler()->saveTimestamp($stamp1, "parser"); // Libertree has a problem with escaped hashtags. $text = str_replace(['\#'], ['#'], $text); diff --git a/src/Content/Text/Markdown.php b/src/Content/Text/Markdown.php index 1b3f8ec71..45f38e4c5 100644 --- a/src/Content/Text/Markdown.php +++ b/src/Content/Text/Markdown.php @@ -57,7 +57,7 @@ class Markdown $html = $MarkdownParser->transform($text); - DI::profiler()->saveTimestamp($stamp1, "parser", System::callstack()); + DI::profiler()->saveTimestamp($stamp1, "parser"); return $html; } diff --git a/src/Core/Addon.php b/src/Core/Addon.php index dd229be28..ee70a66b6 100644 --- a/src/Core/Addon.php +++ b/src/Core/Addon.php @@ -256,7 +256,7 @@ class Addon $stamp1 = microtime(true); $f = file_get_contents("addon/$addon/$addon.php"); - DI::profiler()->saveTimestamp($stamp1, "file", System::callstack()); + DI::profiler()->saveTimestamp($stamp1, "file"); $r = preg_match("|/\*.*\*/|msU", $f, $m); diff --git a/src/Core/Cache/ProfilerCache.php b/src/Core/Cache/ProfilerCache.php index 1f77db67a..7c4802077 100644 --- a/src/Core/Cache/ProfilerCache.php +++ b/src/Core/Cache/ProfilerCache.php @@ -56,7 +56,7 @@ class ProfilerCache implements ICache, IMemoryCache $return = $this->cache->getAllKeys($prefix); - $this->profiler->saveTimestamp($time, 'cache', System::callstack()); + $this->profiler->saveTimestamp($time, 'cache'); return $return; } @@ -70,7 +70,7 @@ class ProfilerCache implements ICache, IMemoryCache $return = $this->cache->get($key); - $this->profiler->saveTimestamp($time, 'cache', System::callstack()); + $this->profiler->saveTimestamp($time, 'cache'); return $return; } @@ -84,7 +84,7 @@ class ProfilerCache implements ICache, IMemoryCache $return = $this->cache->set($key, $value, $ttl); - $this->profiler->saveTimestamp($time, 'cache', System::callstack()); + $this->profiler->saveTimestamp($time, 'cache'); return $return; } @@ -98,7 +98,7 @@ class ProfilerCache implements ICache, IMemoryCache $return = $this->cache->delete($key); - $this->profiler->saveTimestamp($time, 'cache', System::callstack()); + $this->profiler->saveTimestamp($time, 'cache'); return $return; } @@ -112,7 +112,7 @@ class ProfilerCache implements ICache, IMemoryCache $return = $this->cache->clear($outdated); - $this->profiler->saveTimestamp($time, 'cache', System::callstack()); + $this->profiler->saveTimestamp($time, 'cache'); return $return; } @@ -127,7 +127,7 @@ class ProfilerCache implements ICache, IMemoryCache $return = $this->cache->add($key, $value, $ttl); - $this->profiler->saveTimestamp($time, 'cache', System::callstack()); + $this->profiler->saveTimestamp($time, 'cache'); return $return; } else { @@ -145,7 +145,7 @@ class ProfilerCache implements ICache, IMemoryCache $return = $this->cache->compareSet($key, $oldValue, $newValue, $ttl); - $this->profiler->saveTimestamp($time, 'cache', System::callstack()); + $this->profiler->saveTimestamp($time, 'cache'); return $return; } else { @@ -163,7 +163,7 @@ class ProfilerCache implements ICache, IMemoryCache $return = $this->cache->compareDelete($key, $value); - $this->profiler->saveTimestamp($time, 'cache', System::callstack()); + $this->profiler->saveTimestamp($time, 'cache'); return $return; } else { diff --git a/src/Core/Renderer.php b/src/Core/Renderer.php index bf4cd3907..24f003417 100644 --- a/src/Core/Renderer.php +++ b/src/Core/Renderer.php @@ -92,7 +92,7 @@ class Renderer throw new InternalServerErrorException($message); } - DI::profiler()->saveTimestamp($stamp1, "rendering", System::callstack()); + DI::profiler()->saveTimestamp($stamp1, "rendering"); return $output; } @@ -121,7 +121,7 @@ class Renderer throw new InternalServerErrorException($message); } - DI::profiler()->saveTimestamp($stamp1, "file", System::callstack()); + DI::profiler()->saveTimestamp($stamp1, "file"); return $template; } diff --git a/src/Core/Theme.php b/src/Core/Theme.php index 03f1dfd9c..3548544e9 100644 --- a/src/Core/Theme.php +++ b/src/Core/Theme.php @@ -90,7 +90,7 @@ class Theme $stamp1 = microtime(true); $theme_file = file_get_contents("view/theme/$theme/theme.php"); - DI::profiler()->saveTimestamp($stamp1, "file", System::callstack()); + DI::profiler()->saveTimestamp($stamp1, "file"); $result = preg_match("|/\*.*\*/|msU", $theme_file, $matches); diff --git a/src/Database/Database.php b/src/Database/Database.php index 5ef481556..0b38c24ba 100644 --- a/src/Database/Database.php +++ b/src/Database/Database.php @@ -699,7 +699,7 @@ class Database $this->errorno = $errorno; } - $this->profiler->saveTimestamp($stamp1, 'database', System::callstack()); + $this->profiler->saveTimestamp($stamp1, 'database'); if ($this->configCache->get('system', 'db_log')) { $stamp2 = microtime(true); @@ -783,7 +783,7 @@ class Database $this->errorno = $errorno; } - $this->profiler->saveTimestamp($stamp, "database_write", System::callstack()); + $this->profiler->saveTimestamp($stamp, "database_write"); return $retval; } @@ -964,7 +964,7 @@ class Database } } - $this->profiler->saveTimestamp($stamp1, 'database', System::callstack()); + $this->profiler->saveTimestamp($stamp1, 'database'); return $columns; } @@ -1644,7 +1644,7 @@ class Database break; } - $this->profiler->saveTimestamp($stamp1, 'database', System::callstack()); + $this->profiler->saveTimestamp($stamp1, 'database'); return $ret; } diff --git a/src/Factory/SessionFactory.php b/src/Factory/SessionFactory.php index f513eef35..116afe18a 100644 --- a/src/Factory/SessionFactory.php +++ b/src/Factory/SessionFactory.php @@ -85,7 +85,7 @@ class SessionFactory $session = new Session\Native($baseURL, $handler); } } finally { - $profiler->saveTimestamp($stamp1, 'parser', System::callstack()); + $profiler->saveTimestamp($stamp1, 'parser'); return $session; } } diff --git a/src/Network/HTTPRequest.php b/src/Network/HTTPRequest.php index 839586880..87177b1a4 100644 --- a/src/Network/HTTPRequest.php +++ b/src/Network/HTTPRequest.php @@ -199,7 +199,7 @@ class HTTPRequest implements IHTTPRequest @curl_close($ch); - $this->profiler->saveTimestamp($stamp1, 'network', System::callstack()); + $this->profiler->saveTimestamp($stamp1, 'network'); return $curlResponse; } @@ -285,7 +285,7 @@ class HTTPRequest implements IHTTPRequest curl_close($ch); - $this->profiler->saveTimestamp($stamp1, 'network', System::callstack()); + $this->profiler->saveTimestamp($stamp1, 'network'); // Very old versions of Lighttpd don't like the "Expect" header, so we remove it when needed if ($curlResponse->getReturnCode() == 417) { @@ -335,7 +335,7 @@ class HTTPRequest implements IHTTPRequest $http_code = $curl_info['http_code']; curl_close($ch); - $this->profiler->saveTimestamp($stamp1, "network", System::callstack()); + $this->profiler->saveTimestamp($stamp1, "network"); if ($http_code == 0) { return $url; @@ -377,7 +377,7 @@ class HTTPRequest implements IHTTPRequest $body = curl_exec($ch); curl_close($ch); - $this->profiler->saveTimestamp($stamp1, "network", System::callstack()); + $this->profiler->saveTimestamp($stamp1, "network"); if (trim($body) == "") { return $url; diff --git a/src/Object/Image.php b/src/Object/Image.php index 8787db052..b69682ca6 100644 --- a/src/Object/Image.php +++ b/src/Object/Image.php @@ -625,7 +625,7 @@ class Image $stamp1 = microtime(true); file_put_contents($path, $string); - DI::profiler()->saveTimestamp($stamp1, "file", System::callstack()); + DI::profiler()->saveTimestamp($stamp1, "file"); } /** diff --git a/src/Util/Images.php b/src/Util/Images.php index ef171873f..f39b0db00 100644 --- a/src/Util/Images.php +++ b/src/Util/Images.php @@ -200,7 +200,7 @@ class Images $stamp1 = microtime(true); file_put_contents($tempfile, $img_str); - DI::profiler()->saveTimestamp($stamp1, "file", System::callstack()); + DI::profiler()->saveTimestamp($stamp1, "file"); $data = getimagesize($tempfile); unlink($tempfile); diff --git a/src/Util/Logger/ProfilerLogger.php b/src/Util/Logger/ProfilerLogger.php index 2f1940952..e0f18b285 100644 --- a/src/Util/Logger/ProfilerLogger.php +++ b/src/Util/Logger/ProfilerLogger.php @@ -61,7 +61,7 @@ class ProfilerLogger implements LoggerInterface { $stamp1 = microtime(true); $this->logger->emergency($message, $context); - $this->profiler->saveTimestamp($stamp1, 'file', System::callstack()); + $this->profiler->saveTimestamp($stamp1, 'file'); } /** @@ -71,7 +71,7 @@ class ProfilerLogger implements LoggerInterface { $stamp1 = microtime(true); $this->logger->alert($message, $context); - $this->profiler->saveTimestamp($stamp1, 'file', System::callstack()); + $this->profiler->saveTimestamp($stamp1, 'file'); } /** @@ -81,7 +81,7 @@ class ProfilerLogger implements LoggerInterface { $stamp1 = microtime(true); $this->logger->critical($message, $context); - $this->profiler->saveTimestamp($stamp1, 'file', System::callstack()); + $this->profiler->saveTimestamp($stamp1, 'file'); } /** @@ -91,7 +91,7 @@ class ProfilerLogger implements LoggerInterface { $stamp1 = microtime(true); $this->logger->error($message, $context); - $this->profiler->saveTimestamp($stamp1, 'file', System::callstack()); + $this->profiler->saveTimestamp($stamp1, 'file'); } /** @@ -101,7 +101,7 @@ class ProfilerLogger implements LoggerInterface { $stamp1 = microtime(true); $this->logger->warning($message, $context); - $this->profiler->saveTimestamp($stamp1, 'file', System::callstack()); + $this->profiler->saveTimestamp($stamp1, 'file'); } /** @@ -111,7 +111,7 @@ class ProfilerLogger implements LoggerInterface { $stamp1 = microtime(true); $this->logger->notice($message, $context); - $this->profiler->saveTimestamp($stamp1, 'file', System::callstack()); + $this->profiler->saveTimestamp($stamp1, 'file'); } /** @@ -121,7 +121,7 @@ class ProfilerLogger implements LoggerInterface { $stamp1 = microtime(true); $this->logger->info($message, $context); - $this->profiler->saveTimestamp($stamp1, 'file', System::callstack()); + $this->profiler->saveTimestamp($stamp1, 'file'); } /** @@ -131,7 +131,7 @@ class ProfilerLogger implements LoggerInterface { $stamp1 = microtime(true); $this->logger->debug($message, $context); - $this->profiler->saveTimestamp($stamp1, 'file', System::callstack()); + $this->profiler->saveTimestamp($stamp1, 'file'); } /** @@ -141,6 +141,6 @@ class ProfilerLogger implements LoggerInterface { $stamp1 = microtime(true); $this->logger->log($level, $message, $context); - $this->profiler->saveTimestamp($stamp1, 'file', System::callstack()); + $this->profiler->saveTimestamp($stamp1, 'file'); } } diff --git a/src/Util/Profiler.php b/src/Util/Profiler.php index 240273bde..db3e1bb97 100644 --- a/src/Util/Profiler.php +++ b/src/Util/Profiler.php @@ -23,6 +23,7 @@ namespace Friendica\Util; use Friendica\Core\Config\Cache; use Friendica\Core\Config\IConfig; +use Friendica\Core\System; use Psr\Container\ContainerExceptionInterface; use Psr\Container\ContainerInterface; use Psr\Container\NotFoundExceptionInterface; @@ -88,9 +89,9 @@ class Profiler implements ContainerInterface * 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 = '') { @@ -98,6 +99,8 @@ class Profiler implements ContainerInterface return; } + $callstack = $callstack ?: System::callstack(4, 1); + $duration = floatval(microtime(true) - $timestamp); if (!isset($this->performance[$value])) {