diff --git a/bin/auth_ejabberd.php b/bin/auth_ejabberd.php index 11df438952..8a5c43c6df 100755 --- a/bin/auth_ejabberd.php +++ b/bin/auth_ejabberd.php @@ -58,8 +58,9 @@ $basedir = BasePath::create(dirname(__DIR__), $_SERVER); $configLoader = new Config\ConfigCacheLoader($basedir); $config = Factory\ConfigFactory::createCache($configLoader); $logger = Factory\LoggerFactory::create('auth_ejabberd', $config); +$profiler = Factory\ProfilerFactory::create($config); -$a = new App($config, $logger); +$a = new App($config, $logger, $profiler); if ($a->getMode()->isNormal()) { $oAuth = new ExAuth(); diff --git a/bin/console.php b/bin/console.php index 9061824d87..ceccfc823e 100755 --- a/bin/console.php +++ b/bin/console.php @@ -11,8 +11,9 @@ $basedir = BasePath::create(dirname(__DIR__), $_SERVER); $configLoader = new Config\ConfigCacheLoader($basedir); $config = Factory\ConfigFactory::createCache($configLoader); $logger = Factory\LoggerFactory::create('console', $config); +$profiler = Factory\ProfilerFactory::create($config); -$a = new Friendica\App($config, $logger); +$a = new Friendica\App($config, $logger, $profiler); \Friendica\BaseObject::setApp($a); (new Friendica\Core\Console($argv))->execute(); diff --git a/bin/daemon.php b/bin/daemon.php index 5c014a9270..3b5c04b7ab 100755 --- a/bin/daemon.php +++ b/bin/daemon.php @@ -37,8 +37,9 @@ $basedir = BasePath::create(dirname(__DIR__), $_SERVER); $configLoader = new Config\ConfigCacheLoader($basedir); $config = Factory\ConfigFactory::createCache($configLoader); $logger = Factory\LoggerFactory::create('daemon', $config); +$profiler = Factory\ProfilerFactory::create($config); -$a = new App($config, $logger); +$a = new App($config, $logger, $profiler); if ($a->getMode()->isInstall()) { die("Friendica isn't properly installed yet.\n"); diff --git a/bin/worker.php b/bin/worker.php index 553e984977..c93abaf0fe 100755 --- a/bin/worker.php +++ b/bin/worker.php @@ -35,8 +35,9 @@ $basedir = BasePath::create(dirname(__DIR__), $_SERVER); $configLoader = new Config\ConfigCacheLoader($basedir); $config = Factory\ConfigFactory::createCache($configLoader); $logger = Factory\LoggerFactory::create('worker', $config); +$profiler = Factory\ProfilerFactory::create($config); -$a = new App($config, $logger); +$a = new App($config, $logger, $profiler); // Check the database structure and possibly fixes it Update::check($a->getBasePath(), true); diff --git a/include/api.php b/include/api.php index 052d32b17b..6bd08d01d0 100644 --- a/include/api.php +++ b/include/api.php @@ -326,69 +326,7 @@ function api_call(App $a) Logger::info(API_LOG_PREFIX . 'username {username}', ['module' => 'api', 'action' => 'call', 'username' => $a->user['username'], 'duration' => round($duration, 2)]); - if (Config::get("system", "profiler")) { - $duration = microtime(true)-$a->performance["start"]; - - /// @TODO round() really everywhere? - Logger::debug( - API_LOG_PREFIX . 'performance', - [ - 'module' => 'api', - 'action' => 'call', - 'database_read' => round($a->performance["database"] - $a->performance["database_write"], 3), - 'database_write' => round($a->performance["database_write"], 3), - 'cache_read' => round($a->performance["cache"], 3), - 'cache_write' => round($a->performance["cache_write"], 3), - 'network_io' => round($a->performance["network"], 2), - 'file_io' => round($a->performance["file"], 2), - 'other_io' => round($duration - ($a->performance["database"] - + $a->performance["cache"] + $a->performance["cache_write"] - + $a->performance["network"] + $a->performance["file"]), 2), - 'total' => round($duration, 2) - ] - ); - - if (Config::get("rendertime", "callstack")) { - $o = "Database Read:\n"; - foreach ($a->callstack["database"] as $func => $time) { - $time = round($time, 3); - if ($time > 0) { - $o .= $func . ": " . $time . "\n"; - } - } - $o .= "\nDatabase Write:\n"; - foreach ($a->callstack["database_write"] as $func => $time) { - $time = round($time, 3); - if ($time > 0) { - $o .= $func . ": " . $time . "\n"; - } - } - - $o = "Cache Read:\n"; - foreach ($a->callstack["cache"] as $func => $time) { - $time = round($time, 3); - if ($time > 0) { - $o .= $func . ": " . $time . "\n"; - } - } - $o .= "\nCache Write:\n"; - foreach ($a->callstack["cache_write"] as $func => $time) { - $time = round($time, 3); - if ($time > 0) { - $o .= $func . ": " . $time . "\n"; - } - } - - $o .= "\nNetwork:\n"; - foreach ($a->callstack["network"] as $func => $time) { - $time = round($time, 3); - if ($time > 0) { - $o .= $func . ": " . $time . "\n"; - } - } - Logger::debug(API_LOG_PREFIX . $o, ['module' => 'api', 'action' => 'call']); - } - } + $a->getProfiler()->saveLog(API_LOG_PREFIX . 'performance'); if (false === $return) { /* diff --git a/index.php b/index.php index 7e7396785f..d8c233be23 100644 --- a/index.php +++ b/index.php @@ -19,9 +19,10 @@ $basedir = BasePath::create(__DIR__, $_SERVER); $configLoader = new Config\ConfigCacheLoader($basedir); $config = Factory\ConfigFactory::createCache($configLoader); $logger = Factory\LoggerFactory::create('index', $config); +$profiler = Factory\ProfilerFactory::create($config); // We assume that the index.php is called by a frontend process // The value is set to "true" by default in App -$a = new App($config, $logger, false); +$a = new App($config, $logger, $profiler, false); $a->runFrontend(); diff --git a/src/App.php b/src/App.php index 8068a1530b..6e1f83fdd6 100644 --- a/src/App.php +++ b/src/App.php @@ -13,6 +13,7 @@ use Friendica\Core\Config\ConfigCacheLoader; use Friendica\Database\DBA; use Friendica\Factory\ConfigFactory; use Friendica\Network\HTTPException\InternalServerErrorException; +use Friendica\Util\Profiler; use Psr\Log\LoggerInterface; /** @@ -53,8 +54,6 @@ class App public $identities; public $is_mobile = false; public $is_tablet = false; - public $performance = []; - public $callstack = []; public $theme_info = []; public $category; // Allow themes to control internal parameters @@ -119,6 +118,11 @@ class App */ private $config; + /** + * @var Profiler The profiler of this app + */ + private $profiler; + /** * Returns the current config cache of this node * @@ -139,6 +143,16 @@ class App return $this->basePath; } + /** + * The profiler of this app + * + * @return Profiler + */ + public function getProfiler() + { + return $this->profiler; + } + /** * Register a stylesheet file path to be included in the tag of every page. * Inclusion is done in App->initHead(). @@ -183,14 +197,16 @@ class App * * @param ConfigCache $config The Cached Config * @param LoggerInterface $logger Logger of this application + * @param Profiler $profiler The profiler of this application * @param bool $isBackend Whether it is used for backend or frontend (Default true=backend) * * @throws Exception if the Basepath is not usable */ - public function __construct(ConfigCache $config, LoggerInterface $logger, $isBackend = true) + public function __construct(ConfigCache $config, LoggerInterface $logger, Profiler $profiler, $isBackend = true) { $this->config = $config; $this->logger = $logger; + $this->profiler = $profiler; $this->basePath = $this->config->get('system', 'basepath'); if (!Core\System::isDirectoryUsable($this->basePath, false)) { @@ -203,26 +219,7 @@ class App $this->checkBackend($isBackend); $this->checkFriendicaApp(); - $this->performance['start'] = microtime(true); - $this->performance['database'] = 0; - $this->performance['database_write'] = 0; - $this->performance['cache'] = 0; - $this->performance['cache_write'] = 0; - $this->performance['network'] = 0; - $this->performance['file'] = 0; - $this->performance['rendering'] = 0; - $this->performance['parser'] = 0; - $this->performance['marktime'] = 0; - $this->performance['markstart'] = microtime(true); - - $this->callstack['database'] = []; - $this->callstack['database_write'] = []; - $this->callstack['cache'] = []; - $this->callstack['cache_write'] = []; - $this->callstack['network'] = []; - $this->callstack['file'] = []; - $this->callstack['rendering'] = []; - $this->callstack['parser'] = []; + $this->profiler->reset(); $this->mode = new App\Mode($this->basePath); @@ -489,14 +486,14 @@ class App $stamp1 = microtime(true); - if (DBA::connect($this->config, $db_host, $db_user, $db_pass, $db_data, $charset)) { + if (DBA::connect($this->config, $this->profiler, $db_host, $db_user, $db_pass, $db_data, $charset)) { // Loads DB_UPDATE_VERSION constant Database\DBStructure::definition($this->basePath, false); } unset($db_host, $db_user, $db_pass, $db_data, $charset); - $this->saveTimestamp($stamp1, 'network'); + $this->profiler->saveTimestamp($stamp1, 'network'); } public function getScheme() @@ -742,41 +739,6 @@ class App } } - /** - * 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 - */ - public function saveTimestamp($timestamp, $value) - { - $profiler = $this->config->get('system', 'profiler'); - - if (!isset($profiler) || !$profiler) { - return; - } - - $duration = (float) (microtime(true) - $timestamp); - - if (!isset($this->performance[$value])) { - // Prevent ugly E_NOTICE - $this->performance[$value] = 0; - } - - $this->performance[$value] += (float) $duration; - $this->performance['marktime'] += (float) $duration; - - $callstack = Core\System::callstack(); - - if (!isset($this->callstack[$value][$callstack])) { - // Prevent ugly E_NOTICE - $this->callstack[$value][$callstack] = 0; - } - - $this->callstack[$value][$callstack] += (float) $duration; - } - /** * Returns the current UserAgent as a String * @@ -1227,7 +1189,7 @@ class App if (!$this->isBackend()) { $stamp1 = microtime(true); session_start(); - $this->saveTimestamp($stamp1, 'parser'); + $this->profiler->saveTimestamp($stamp1, 'parser'); Core\L10n::setSessionVariable(); Core\L10n::setLangFromSession(); } else { diff --git a/src/Content/Text/BBCode.php b/src/Content/Text/BBCode.php index a8b5ec2025..75cb32b626 100644 --- a/src/Content/Text/BBCode.php +++ b/src/Content/Text/BBCode.php @@ -1027,7 +1027,7 @@ class BBCode extends BaseObject @curl_exec($ch); $curl_info = @curl_getinfo($ch); - $a->saveTimestamp($stamp1, "network"); + $a->getProfiler()->saveTimestamp($stamp1, "network"); if (substr($curl_info["content_type"], 0, 6) == "image/") { $text = "[url=" . $match[1] . "]" . $match[1] . "[/url]"; @@ -1086,7 +1086,7 @@ class BBCode extends BaseObject @curl_exec($ch); $curl_info = @curl_getinfo($ch); - $a->saveTimestamp($stamp1, "network"); + $a->getProfiler()->saveTimestamp($stamp1, "network"); // if its a link to a picture then embed this picture if (substr($curl_info["content_type"], 0, 6) == "image/") { @@ -1915,7 +1915,7 @@ class BBCode extends BaseObject // unmask the special chars back to HTML $text = str_replace(['&\_lt\_;', '&\_gt\_;', '&\_amp\_;'], ['<', '>', '&'], $text); - $a->saveTimestamp($stamp1, "parser"); + $a->getProfiler()->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 ceb5b043b3..28ee215b26 100644 --- a/src/Content/Text/Markdown.php +++ b/src/Content/Text/Markdown.php @@ -36,7 +36,7 @@ class Markdown extends BaseObject $html = $MarkdownParser->transform($text); $html = preg_replace('/getProfiler()->saveTimestamp($stamp1, "parser"); return $html; } diff --git a/src/Core/Addon.php b/src/Core/Addon.php index 6697a44aea..483882c3ed 100644 --- a/src/Core/Addon.php +++ b/src/Core/Addon.php @@ -219,7 +219,7 @@ class Addon extends BaseObject $stamp1 = microtime(true); $f = file_get_contents("addon/$addon/$addon.php"); - $a->saveTimestamp($stamp1, "file"); + $a->getProfiler()->saveTimestamp($stamp1, "file"); $r = preg_match("|/\*.*\*/|msU", $f, $m); diff --git a/src/Core/Cache.php b/src/Core/Cache.php index 39c29566d3..cd1581ef93 100644 --- a/src/Core/Cache.php +++ b/src/Core/Cache.php @@ -63,7 +63,7 @@ class Cache extends \Friendica\BaseObject $return = self::getDriver()->getAllKeys($prefix); - self::getApp()->saveTimestamp($time, 'cache'); + self::getApp()->getProfiler()->saveTimestamp($time, 'cache'); return $return; } @@ -82,7 +82,7 @@ class Cache extends \Friendica\BaseObject $return = self::getDriver()->get($key); - self::getApp()->saveTimestamp($time, 'cache'); + self::getApp()->getProfiler()->saveTimestamp($time, 'cache'); return $return; } @@ -105,7 +105,7 @@ class Cache extends \Friendica\BaseObject $return = self::getDriver()->set($key, $value, $duration); - self::getApp()->saveTimestamp($time, 'cache_write'); + self::getApp()->getProfiler()->saveTimestamp($time, 'cache_write'); return $return; } @@ -124,7 +124,7 @@ class Cache extends \Friendica\BaseObject $return = self::getDriver()->delete($key); - self::getApp()->saveTimestamp($time, 'cache_write'); + self::getApp()->getProfiler()->saveTimestamp($time, 'cache_write'); return $return; } diff --git a/src/Core/Console/AutomaticInstallation.php b/src/Core/Console/AutomaticInstallation.php index 7f2585e63a..d5c63dd990 100644 --- a/src/Core/Console/AutomaticInstallation.php +++ b/src/Core/Console/AutomaticInstallation.php @@ -146,7 +146,7 @@ HELP; $installer->resetChecks(); - if (!$installer->checkDB($a->getConfig(), $db_host, $db_user, $db_pass, $db_data)) { + if (!$installer->checkDB($a->getConfig(), $a->getProfiler(), $db_host, $db_user, $db_pass, $db_data)) { $errorMessage = $this->extractErrors($installer->getChecks()); throw new RuntimeException($errorMessage); } diff --git a/src/Core/Installer.php b/src/Core/Installer.php index 4a287a885f..dd9e3d22e9 100644 --- a/src/Core/Installer.php +++ b/src/Core/Installer.php @@ -11,6 +11,7 @@ use Friendica\Database\DBA; use Friendica\Database\DBStructure; use Friendica\Object\Image; use Friendica\Util\Network; +use Friendica\Util\Profiler; use Friendica\Util\Strings; /** @@ -583,6 +584,7 @@ class Installer * Checking the Database connection and if it is available for the current installation * * @param ConfigCache $configCache The configuration cache + * @param Profiler $profiler The profiler of this app * @param string $dbhost Hostname/IP of the Friendica Database * @param string $dbuser Username of the Database connection credentials * @param string $dbpass Password of the Database connection credentials @@ -591,9 +593,9 @@ class Installer * @return bool true if the check was successful, otherwise false * @throws Exception */ - public function checkDB(ConfigCache $configCache, $dbhost, $dbuser, $dbpass, $dbdata) + public function checkDB(ConfigCache $configCache, Profiler $profiler, $dbhost, $dbuser, $dbpass, $dbdata) { - if (!DBA::connect($configCache, $dbhost, $dbuser, $dbpass, $dbdata)) { + if (!DBA::connect($configCache, $profiler, $dbhost, $dbuser, $dbpass, $dbdata)) { $this->addCheck(L10n::t('Could not connect to database.'), false, true, ''); return false; diff --git a/src/Core/Logger.php b/src/Core/Logger.php index 6b8112796f..69be501a3d 100644 --- a/src/Core/Logger.php +++ b/src/Core/Logger.php @@ -155,7 +155,7 @@ class Logger extends BaseObject $stamp1 = microtime(true); self::$logger->emergency($message, $context); - self::getApp()->saveTimestamp($stamp1, 'file'); + self::getApp()->GetProfiler()->saveTimestamp($stamp1, 'file'); } /** @@ -179,7 +179,7 @@ class Logger extends BaseObject $stamp1 = microtime(true); self::$logger->alert($message, $context); - self::getApp()->saveTimestamp($stamp1, 'file'); + self::getApp()->getProfiler()->saveTimestamp($stamp1, 'file'); } /** @@ -202,7 +202,7 @@ class Logger extends BaseObject $stamp1 = microtime(true); self::$logger->critical($message, $context); - self::getApp()->saveTimestamp($stamp1, 'file'); + self::getApp()->getProfiler()->saveTimestamp($stamp1, 'file'); } /** @@ -225,7 +225,7 @@ class Logger extends BaseObject $stamp1 = microtime(true); self::$logger->error($message, $context); - self::getApp()->saveTimestamp($stamp1, 'file'); + self::getApp()->getProfiler()->saveTimestamp($stamp1, 'file'); } /** @@ -249,7 +249,7 @@ class Logger extends BaseObject $stamp1 = microtime(true); self::$logger->warning($message, $context); - self::getApp()->saveTimestamp($stamp1, 'file'); + self::getApp()->getProfiler()->saveTimestamp($stamp1, 'file'); } /** @@ -270,7 +270,7 @@ class Logger extends BaseObject $stamp1 = microtime(true); self::$logger->notice($message, $context); - self::getApp()->saveTimestamp($stamp1, 'file'); + self::getApp()->getProfiler()->saveTimestamp($stamp1, 'file'); } /** @@ -293,7 +293,7 @@ class Logger extends BaseObject $stamp1 = microtime(true); self::$logger->info($message, $context); - self::getApp()->saveTimestamp($stamp1, 'file'); + self::getApp()->getProfiler()->saveTimestamp($stamp1, 'file'); } /** @@ -314,7 +314,7 @@ class Logger extends BaseObject $stamp1 = microtime(true); self::$logger->debug($message, $context); - self::getApp()->saveTimestamp($stamp1, 'file'); + self::getApp()->getProfiler()->saveTimestamp($stamp1, 'file'); } /** @@ -334,7 +334,7 @@ class Logger extends BaseObject $stamp1 = microtime(true); self::$logger->log($level, $msg); - self::getApp()->saveTimestamp($stamp1, "file"); + self::getApp()->getProfiler()->saveTimestamp($stamp1, "file"); } /** @@ -355,6 +355,6 @@ class Logger extends BaseObject $stamp1 = microtime(true); self::$devLogger->log($level, $msg); - self::getApp()->saveTimestamp($stamp1, "file"); + self::getApp()->getProfiler()->saveTimestamp($stamp1, "file"); } } diff --git a/src/Core/Renderer.php b/src/Core/Renderer.php index 67bc5e3bab..c032448c98 100644 --- a/src/Core/Renderer.php +++ b/src/Core/Renderer.php @@ -74,7 +74,7 @@ class Renderer extends BaseObject exit(); } - $a->saveTimestamp($stamp1, "rendering"); + $a->getProfiler()->saveTimestamp($stamp1, "rendering"); return $output; } @@ -101,7 +101,7 @@ class Renderer extends BaseObject exit(); } - $a->saveTimestamp($stamp1, "file"); + $a->getProfiler()->saveTimestamp($stamp1, "file"); return $template; } diff --git a/src/Core/Theme.php b/src/Core/Theme.php index 62dfaa51f3..dbfc0fd908 100644 --- a/src/Core/Theme.php +++ b/src/Core/Theme.php @@ -51,7 +51,7 @@ class Theme $a = \get_app(); $stamp1 = microtime(true); $theme_file = file_get_contents("view/theme/$theme/theme.php"); - $a->saveTimestamp($stamp1, "file"); + $a->getProfiler()->saveTimestamp($stamp1, "file"); $result = preg_match("|/\*.*\*/|msU", $theme_file, $matches); diff --git a/src/Core/Worker.php b/src/Core/Worker.php index 75d4e48740..dff60e9fa5 100644 --- a/src/Core/Worker.php +++ b/src/Core/Worker.php @@ -380,20 +380,7 @@ class Worker // We use the callstack here to analyze the performance of executed worker entries. // For this reason the variables have to be initialized. - if (Config::get("system", "profiler")) { - $a->performance["start"] = microtime(true); - $a->performance["database"] = 0; - $a->performance["database_write"] = 0; - $a->performance["cache"] = 0; - $a->performance["cache_write"] = 0; - $a->performance["network"] = 0; - $a->performance["file"] = 0; - $a->performance["rendering"] = 0; - $a->performance["parser"] = 0; - $a->performance["marktime"] = 0; - $a->performance["markstart"] = microtime(true); - $a->callstack = []; - } + $a->getProfiler()->reset(); // For better logging create a new process id for every worker call // But preserve the old one for the worker @@ -452,76 +439,7 @@ class Worker Logger::log("Process ".$mypid." - Prio ".$queue["priority"]." - ID ".$queue["id"].": ".$funcname." - done in ".number_format($duration, 4)." seconds. Process PID: ".$new_process_id); - // Write down the performance values into the log - if (Config::get("system", "profiler")) { - $duration = microtime(true)-$a->performance["start"]; - - $o = ''; - if (Config::get("rendertime", "callstack")) { - if (isset($a->callstack["database"])) { - $o .= "\nDatabase Read:\n"; - foreach ($a->callstack["database"] as $func => $time) { - $time = round($time, 3); - if ($time > 0) { - $o .= $func.": ".$time."\n"; - } - } - } - if (isset($a->callstack["database_write"])) { - $o .= "\nDatabase Write:\n"; - foreach ($a->callstack["database_write"] as $func => $time) { - $time = round($time, 3); - if ($time > 0) { - $o .= $func.": ".$time."\n"; - } - } - } - if (isset($a->callstack["dache"])) { - $o .= "\nCache Read:\n"; - foreach ($a->callstack["dache"] as $func => $time) { - $time = round($time, 3); - if ($time > 0) { - $o .= $func.": ".$time."\n"; - } - } - } - if (isset($a->callstack["dache_write"])) { - $o .= "\nCache Write:\n"; - foreach ($a->callstack["dache_write"] as $func => $time) { - $time = round($time, 3); - if ($time > 0) { - $o .= $func.": ".$time."\n"; - } - } - } - if (isset($a->callstack["network"])) { - $o .= "\nNetwork:\n"; - foreach ($a->callstack["network"] as $func => $time) { - $time = round($time, 3); - if ($time > 0) { - $o .= $func.": ".$time."\n"; - } - } - } - } - - Logger::log( - "ID ".$queue["id"].": ".$funcname.": ".sprintf( - "DB: %s/%s, Cache: %s/%s, Net: %s, I/O: %s, Other: %s, Total: %s".$o, - number_format($a->performance["database"] - $a->performance["database_write"], 2), - number_format($a->performance["database_write"], 2), - number_format($a->performance["cache"], 2), - number_format($a->performance["cache_write"], 2), - number_format($a->performance["network"], 2), - number_format($a->performance["file"], 2), - number_format($duration - ($a->performance["database"] - + $a->performance["cache"] + $a->performance["cache_write"] - + $a->performance["network"] + $a->performance["file"]), 2), - number_format($duration, 2) - ), - Logger::DEBUG - ); - } + $a->getProfiler()->saveLog("ID " . $queue["id"] . ": " . $funcname); $cooldown = Config::get("system", "worker_cooldown", 0); diff --git a/src/Database/DBA.php b/src/Database/DBA.php index d2a739e931..7c24ecfd33 100644 --- a/src/Database/DBA.php +++ b/src/Database/DBA.php @@ -6,6 +6,7 @@ use Friendica\Core\Config\IConfigCache; use Friendica\Core\Logger; use Friendica\Core\System; use Friendica\Util\DateTimeFormat; +use Friendica\Util\Profiler; use mysqli; use mysqli_result; use mysqli_stmt; @@ -35,6 +36,10 @@ class DBA * @var IConfigCache */ private static $configCache; + /** + * @var Profiler + */ + private static $profiler; private static $server_info = ''; private static $connection; private static $driver; @@ -50,7 +55,7 @@ class DBA private static $db_name = ''; private static $db_charset = ''; - public static function connect($configCache, $serveraddr, $user, $pass, $db, $charset = null) + public static function connect(IConfigCache $configCache, Profiler $profiler, $serveraddr, $user, $pass, $db, $charset = null) { if (!is_null(self::$connection) && self::connected()) { return true; @@ -58,6 +63,7 @@ class DBA // We are storing these values for being able to perform a reconnect self::$configCache = $configCache; + self::$profiler = $profiler; self::$db_serveraddr = $serveraddr; self::$db_user = $user; self::$db_pass = $pass; @@ -158,7 +164,7 @@ class DBA public static function reconnect() { self::disconnect(); - $ret = self::connect(self::$configCache, self::$db_serveraddr, self::$db_user, self::$db_pass, self::$db_name, self::$db_charset); + $ret = self::connect(self::$configCache, self::$profiler, self::$db_serveraddr, self::$db_user, self::$db_pass, self::$db_name, self::$db_charset); return $ret; } @@ -392,7 +398,6 @@ class DBA * @throws \Exception */ public static function p($sql) { - $a = \get_app(); $stamp1 = microtime(true); @@ -582,7 +587,7 @@ class DBA self::$errorno = $errorno; } - $a->saveTimestamp($stamp1, 'database'); + self::$profiler->saveTimestamp($stamp1, 'database'); if (self::$configCache->get('system', 'db_log')) { $stamp2 = microtime(true); @@ -611,7 +616,6 @@ class DBA * @throws \Exception */ public static function e($sql) { - $a = \get_app(); $stamp = microtime(true); @@ -654,7 +658,7 @@ class DBA self::$errorno = $errorno; } - $a->saveTimestamp($stamp, "database_write"); + self::$profiler->saveTimestamp($stamp, "database_write"); return $retval; } @@ -777,7 +781,6 @@ class DBA * @return array current row */ public static function fetch($stmt) { - $a = \get_app(); $stamp1 = microtime(true); @@ -824,7 +827,7 @@ class DBA } } - $a->saveTimestamp($stamp1, 'database'); + self::$profiler->saveTimestamp($stamp1, 'database'); return $columns; } @@ -1534,7 +1537,6 @@ class DBA * @return boolean was the close successful? */ public static function close($stmt) { - $a = \get_app(); $stamp1 = microtime(true); @@ -1562,7 +1564,7 @@ class DBA break; } - $a->saveTimestamp($stamp1, 'database'); + self::$profiler->saveTimestamp($stamp1, 'database'); return $ret; } diff --git a/src/Factory/ProfilerFactory.php b/src/Factory/ProfilerFactory.php new file mode 100644 index 0000000000..7a63c7440c --- /dev/null +++ b/src/Factory/ProfilerFactory.php @@ -0,0 +1,25 @@ +get('system', 'profiler', false); + $renderTime = $configCache->get('rendertime', 'callstack', false); + return new Profiler($logger, $enabled, $renderTime); + } +} diff --git a/src/Module/Install.php b/src/Module/Install.php index 6948dee6e0..4fb4a932cd 100644 --- a/src/Module/Install.php +++ b/src/Module/Install.php @@ -75,7 +75,7 @@ class Install extends BaseModule $dbdata = Strings::escapeTags(trim(defaults($_POST, 'dbdata', ''))); // If we cannot connect to the database, return to the previous step - if (!self::$installer->checkDB($a->getConfig(), $dbhost, $dbuser, $dbpass, $dbdata)) { + if (!self::$installer->checkDB($a->getConfig(), $a->getProfiler(), $dbhost, $dbuser, $dbpass, $dbdata)) { self::$currentWizardStep = self::DATABASE_CONFIG; } @@ -92,7 +92,7 @@ class Install extends BaseModule $adminmail = Strings::escapeTags(trim(defaults($_POST, 'adminmail', ''))); // If we cannot connect to the database, return to the Database config wizard - if (!self::$installer->checkDB($a->getConfig(), $dbhost, $dbuser, $dbpass, $dbdata)) { + if (!self::$installer->checkDB($a->getConfig(), $a->getProfiler(), $dbhost, $dbuser, $dbpass, $dbdata)) { self::$currentWizardStep = self::DATABASE_CONFIG; return; } diff --git a/src/Object/Image.php b/src/Object/Image.php index 9143c23c16..c439553754 100644 --- a/src/Object/Image.php +++ b/src/Object/Image.php @@ -5,6 +5,7 @@ */ namespace Friendica\Object; +use Exception; use Friendica\App; use Friendica\Core\Cache; use Friendica\Core\Config; @@ -14,7 +15,6 @@ use Friendica\Core\System; use Friendica\Database\DBA; use Friendica\Model\Photo; use Friendica\Util\Network; -use Exception; use Imagick; use ImagickPixel; @@ -656,7 +656,7 @@ class Image $stamp1 = microtime(true); file_put_contents($path, $string); - $a->saveTimestamp($stamp1, "file"); + $a->getProfiler()->saveTimestamp($stamp1, "file"); } /** @@ -802,7 +802,7 @@ class Image $a = \get_app(); $stamp1 = microtime(true); file_put_contents($tempfile, $img_str); - $a->saveTimestamp($stamp1, "file"); + $a->getProfiler()->saveTimestamp($stamp1, "file"); $data = getimagesize($tempfile); unlink($tempfile); @@ -910,7 +910,7 @@ class Image $stamp1 = microtime(true); $imagedata = @file_get_contents($url); - $a->saveTimestamp($stamp1, "file"); + $a->getProfiler()->saveTimestamp($stamp1, "file"); } $maximagesize = Config::get('system', 'maximagesize'); @@ -924,7 +924,7 @@ class Image $stamp1 = microtime(true); file_put_contents($tempfile, $imagedata); - $a->saveTimestamp($stamp1, "file"); + $a->getProfiler()->saveTimestamp($stamp1, "file"); $data = getimagesize($tempfile); diff --git a/src/Util/Network.php b/src/Util/Network.php index de4b45da9a..4d5afa3a36 100644 --- a/src/Util/Network.php +++ b/src/Util/Network.php @@ -4,13 +4,13 @@ */ namespace Friendica\Util; +use DOMDocument; +use DomXPath; +use Friendica\Core\Config; use Friendica\Core\Hook; use Friendica\Core\Logger; use Friendica\Core\System; -use Friendica\Core\Config; use Friendica\Network\CurlResult; -use DOMDocument; -use DomXPath; class Network { @@ -232,7 +232,7 @@ class Network @curl_close($ch); - $a->saveTimestamp($stamp1, 'network'); + $a->getProfiler()->saveTimestamp($stamp1, 'network'); return $curlResponse; } @@ -334,7 +334,7 @@ class Network curl_close($ch); - $a->saveTimestamp($stamp1, 'network'); + $a->getProfiler()->saveTimestamp($stamp1, 'network'); Logger::log('post_url: end ' . $url, Logger::DATA); @@ -641,7 +641,7 @@ class Network $http_code = $curl_info['http_code']; curl_close($ch); - $a->saveTimestamp($stamp1, "network"); + $a->getProfiler()->saveTimestamp($stamp1, "network"); if ($http_code == 0) { return $url; @@ -683,7 +683,7 @@ class Network $body = curl_exec($ch); curl_close($ch); - $a->saveTimestamp($stamp1, "network"); + $a->getProfiler()->saveTimestamp($stamp1, "network"); if (trim($body) == "") { return $url; diff --git a/src/Util/Profiler.php b/src/Util/Profiler.php new file mode 100644 index 0000000000..7bf30a2775 --- /dev/null +++ b/src/Util/Profiler.php @@ -0,0 +1,252 @@ +enabled = $enabled; + $this->rendertime = $renderTime; + $this->logger = $logger; + $this->performance = []; + $this->callstack = []; + } + + /** + * 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 + */ + public function saveTimestamp($timestamp, $value) + { + if (!$this->enabled) { + return; + } + + $duration = (float) (microtime(true) - $timestamp); + + if (!isset($this->performance[$value])) { + // Prevent ugly E_NOTICE + $this->performance[$value] = 0; + } + + $this->performance[$value] += (float) $duration; + $this->performance['marktime'] += (float) $duration; + + $callstack = Core\System::callstack(); + + if (!isset($this->callstack[$value][$callstack])) { + // Prevent ugly E_NOTICE + $this->callstack[$value][$callstack] = 0; + } + + $this->callstack[$value][$callstack] += (float) $duration; + } + + /** + * Resets the performance and callstack profiling + * + * @param bool $performance If true, reset the performance (Default true) + * @param bool $callstack If true, reset the callstack (Default true) + */ + public function reset($performance = true, $callstack = true) + { + if ($performance) { + $this->performance = []; + $this->performance['start'] = microtime(true); + $this->performance['database'] = 0; + $this->performance['database_write'] = 0; + $this->performance['cache'] = 0; + $this->performance['cache_write'] = 0; + $this->performance['network'] = 0; + $this->performance['file'] = 0; + $this->performance['rendering'] = 0; + $this->performance['parser'] = 0; + $this->performance['marktime'] = 0; + $this->performance['markstart'] = microtime(true); + } + + if ($callstack) { + $this->callstack['database'] = []; + $this->callstack['database_write'] = []; + $this->callstack['cache'] = []; + $this->callstack['cache_write'] = []; + $this->callstack['network'] = []; + $this->callstack['file'] = []; + $this->callstack['rendering'] = []; + $this->callstack['parser'] = []; + } + } + + /** + * Save the current profiling data to a log entry + * + * @param string $message Additional message for the log + */ + public function saveLog($message) + { + // Write down the performance values into the log + if ($this->enabled) { + $duration = microtime(true)-$this->get('start'); + $this->logger->info( + $message, + [ + 'module' => 'api', + 'action' => 'call', + '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) + ] + ); + + $o = ''; + if ($this->rendertime) { + if (isset($this->callstack["database"])) { + $o .= "\nDatabase Read:\n"; + foreach ($this->callstack["database"] as $func => $time) { + $time = round($time, 3); + if ($time > 0) { + $o .= $func.": ".$time."\n"; + } + } + } + if (isset($this->callstack["database_write"])) { + $o .= "\nDatabase Write:\n"; + foreach ($this->callstack["database_write"] as $func => $time) { + $time = round($time, 3); + if ($time > 0) { + $o .= $func.": ".$time."\n"; + } + } + } + if (isset($this->callstack["dache"])) { + $o .= "\nCache Read:\n"; + foreach ($this->callstack["dache"] as $func => $time) { + $time = round($time, 3); + if ($time > 0) { + $o .= $func.": ".$time."\n"; + } + } + } + if (isset($this->callstack["dache_write"])) { + $o .= "\nCache Write:\n"; + foreach ($this->callstack["dache_write"] as $func => $time) { + $time = round($time, 3); + if ($time > 0) { + $o .= $func.": ".$time."\n"; + } + } + } + if (isset($this->callstack["network"])) { + $o .= "\nNetwork:\n"; + foreach ($this->callstack["network"] as $func => $time) { + $time = round($time, 3); + if ($time > 0) { + $o .= $func.": ".$time."\n"; + } + } + } + } + + $this->logger->info( + $message . ": " . sprintf( + "DB: %s/%s, Cache: %s/%s, Net: %s, I/O: %s, Other: %s, Total: %s".$o, + number_format($this->get('database') - $this->get('database_write'), 2), + number_format($this->get('database_write'), 2), + number_format($this->get('cache'), 2), + number_format($this->get('cache_write'), 2), + number_format($this->get('network'), 2), + number_format($this->get('file'), 2), + number_format($duration - ($this->get('database') + + $this->get('cache') + $this->get('cache_write') + + $this->get('network') + $this->get('file')), 2), + number_format($duration, 2) + ) + ); + } + } + + /** + * Finds an entry of the container by its identifier and returns it. + * + * @param string $id Identifier of the entry to look for. + * + * @throws NotFoundExceptionInterface No entry was found for **this** identifier. + * @throws ContainerExceptionInterface Error while retrieving the entry. + * + * @return int Entry. + */ + public function get($id) + { + if (!$this->has($id)) { + return 0; + } else { + return $this->performance[$id]; + } + } + + /** + * Returns true if the container can return an entry for the given identifier. + * Returns false otherwise. + * + * `has($id)` returning true does not mean that `get($id)` will not throw an exception. + * It does however mean that `get($id)` will not throw a `NotFoundExceptionInterface`. + * + * @param string $id Identifier of the entry to look for. + * + * @return bool + */ + public function has($id) + { + return isset($this->performance[$id]); + } +} diff --git a/tests/DatabaseTest.php b/tests/DatabaseTest.php index 79af5b5468..5c66711dcf 100644 --- a/tests/DatabaseTest.php +++ b/tests/DatabaseTest.php @@ -9,6 +9,7 @@ use Friendica\Core\Config; use Friendica\Database\DBA; use Friendica\Factory; use Friendica\Util\BasePath; +use Friendica\Util\Profiler; use PHPUnit\DbUnit\DataSet\YamlDataSet; use PHPUnit\DbUnit\TestCaseTrait; use PHPUnit_Extensions_Database_DB_IDatabaseConnection; @@ -43,8 +44,11 @@ abstract class DatabaseTest extends MockedTest $configLoader = new Config\ConfigCacheLoader($basedir); $config = Factory\ConfigFactory::createCache($configLoader); + $profiler = \Mockery::mock(Profiler::class); + DBA::connect( $config, + $profiler, getenv('MYSQL_HOST'), getenv('MYSQL_USERNAME'), getenv('MYSQL_PASSWORD'),