Introducing Profiler

This commit is contained in:
Philipp Holzer 2019-02-16 23:11:30 +01:00
parent 12ff467a9b
commit 5e6e1a8025
No known key found for this signature in database
GPG key ID: 517BE60E2CE5C8A5
24 changed files with 370 additions and 262 deletions

View file

@ -58,8 +58,9 @@ $basedir = BasePath::create(dirname(__DIR__), $_SERVER);
$configLoader = new Config\ConfigCacheLoader($basedir); $configLoader = new Config\ConfigCacheLoader($basedir);
$config = Factory\ConfigFactory::createCache($configLoader); $config = Factory\ConfigFactory::createCache($configLoader);
$logger = Factory\LoggerFactory::create('auth_ejabberd', $config); $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()) { if ($a->getMode()->isNormal()) {
$oAuth = new ExAuth(); $oAuth = new ExAuth();

View file

@ -11,8 +11,9 @@ $basedir = BasePath::create(dirname(__DIR__), $_SERVER);
$configLoader = new Config\ConfigCacheLoader($basedir); $configLoader = new Config\ConfigCacheLoader($basedir);
$config = Factory\ConfigFactory::createCache($configLoader); $config = Factory\ConfigFactory::createCache($configLoader);
$logger = Factory\LoggerFactory::create('console', $config); $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); \Friendica\BaseObject::setApp($a);
(new Friendica\Core\Console($argv))->execute(); (new Friendica\Core\Console($argv))->execute();

View file

@ -37,8 +37,9 @@ $basedir = BasePath::create(dirname(__DIR__), $_SERVER);
$configLoader = new Config\ConfigCacheLoader($basedir); $configLoader = new Config\ConfigCacheLoader($basedir);
$config = Factory\ConfigFactory::createCache($configLoader); $config = Factory\ConfigFactory::createCache($configLoader);
$logger = Factory\LoggerFactory::create('daemon', $config); $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()) { if ($a->getMode()->isInstall()) {
die("Friendica isn't properly installed yet.\n"); die("Friendica isn't properly installed yet.\n");

View file

@ -35,8 +35,9 @@ $basedir = BasePath::create(dirname(__DIR__), $_SERVER);
$configLoader = new Config\ConfigCacheLoader($basedir); $configLoader = new Config\ConfigCacheLoader($basedir);
$config = Factory\ConfigFactory::createCache($configLoader); $config = Factory\ConfigFactory::createCache($configLoader);
$logger = Factory\LoggerFactory::create('worker', $config); $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 // Check the database structure and possibly fixes it
Update::check($a->getBasePath(), true); Update::check($a->getBasePath(), true);

View file

@ -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)]); Logger::info(API_LOG_PREFIX . 'username {username}', ['module' => 'api', 'action' => 'call', 'username' => $a->user['username'], 'duration' => round($duration, 2)]);
if (Config::get("system", "profiler")) { $a->getProfiler()->saveLog(API_LOG_PREFIX . 'performance');
$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']);
}
}
if (false === $return) { if (false === $return) {
/* /*

View file

@ -19,9 +19,10 @@ $basedir = BasePath::create(__DIR__, $_SERVER);
$configLoader = new Config\ConfigCacheLoader($basedir); $configLoader = new Config\ConfigCacheLoader($basedir);
$config = Factory\ConfigFactory::createCache($configLoader); $config = Factory\ConfigFactory::createCache($configLoader);
$logger = Factory\LoggerFactory::create('index', $config); $logger = Factory\LoggerFactory::create('index', $config);
$profiler = Factory\ProfilerFactory::create($config);
// We assume that the index.php is called by a frontend process // We assume that the index.php is called by a frontend process
// The value is set to "true" by default in App // 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(); $a->runFrontend();

View file

@ -13,6 +13,7 @@ use Friendica\Core\Config\ConfigCacheLoader;
use Friendica\Database\DBA; use Friendica\Database\DBA;
use Friendica\Factory\ConfigFactory; use Friendica\Factory\ConfigFactory;
use Friendica\Network\HTTPException\InternalServerErrorException; use Friendica\Network\HTTPException\InternalServerErrorException;
use Friendica\Util\Profiler;
use Psr\Log\LoggerInterface; use Psr\Log\LoggerInterface;
/** /**
@ -53,8 +54,6 @@ class App
public $identities; public $identities;
public $is_mobile = false; public $is_mobile = false;
public $is_tablet = false; public $is_tablet = false;
public $performance = [];
public $callstack = [];
public $theme_info = []; public $theme_info = [];
public $category; public $category;
// Allow themes to control internal parameters // Allow themes to control internal parameters
@ -119,6 +118,11 @@ class App
*/ */
private $config; private $config;
/**
* @var Profiler The profiler of this app
*/
private $profiler;
/** /**
* Returns the current config cache of this node * Returns the current config cache of this node
* *
@ -139,6 +143,16 @@ class App
return $this->basePath; 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 <head> tag of every page. * Register a stylesheet file path to be included in the <head> tag of every page.
* Inclusion is done in App->initHead(). * Inclusion is done in App->initHead().
@ -183,14 +197,16 @@ class App
* *
* @param ConfigCache $config The Cached Config * @param ConfigCache $config The Cached Config
* @param LoggerInterface $logger Logger of this application * @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) * @param bool $isBackend Whether it is used for backend or frontend (Default true=backend)
* *
* @throws Exception if the Basepath is not usable * @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->config = $config;
$this->logger = $logger; $this->logger = $logger;
$this->profiler = $profiler;
$this->basePath = $this->config->get('system', 'basepath'); $this->basePath = $this->config->get('system', 'basepath');
if (!Core\System::isDirectoryUsable($this->basePath, false)) { if (!Core\System::isDirectoryUsable($this->basePath, false)) {
@ -203,26 +219,7 @@ class App
$this->checkBackend($isBackend); $this->checkBackend($isBackend);
$this->checkFriendicaApp(); $this->checkFriendicaApp();
$this->performance['start'] = microtime(true); $this->profiler->reset();
$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->mode = new App\Mode($this->basePath); $this->mode = new App\Mode($this->basePath);
@ -489,14 +486,14 @@ class App
$stamp1 = microtime(true); $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 // Loads DB_UPDATE_VERSION constant
Database\DBStructure::definition($this->basePath, false); Database\DBStructure::definition($this->basePath, false);
} }
unset($db_host, $db_user, $db_pass, $db_data, $charset); unset($db_host, $db_user, $db_pass, $db_data, $charset);
$this->saveTimestamp($stamp1, 'network'); $this->profiler->saveTimestamp($stamp1, 'network');
} }
public function getScheme() 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 * Returns the current UserAgent as a String
* *
@ -1227,7 +1189,7 @@ class App
if (!$this->isBackend()) { if (!$this->isBackend()) {
$stamp1 = microtime(true); $stamp1 = microtime(true);
session_start(); session_start();
$this->saveTimestamp($stamp1, 'parser'); $this->profiler->saveTimestamp($stamp1, 'parser');
Core\L10n::setSessionVariable(); Core\L10n::setSessionVariable();
Core\L10n::setLangFromSession(); Core\L10n::setLangFromSession();
} else { } else {

View file

@ -1027,7 +1027,7 @@ class BBCode extends BaseObject
@curl_exec($ch); @curl_exec($ch);
$curl_info = @curl_getinfo($ch); $curl_info = @curl_getinfo($ch);
$a->saveTimestamp($stamp1, "network"); $a->getProfiler()->saveTimestamp($stamp1, "network");
if (substr($curl_info["content_type"], 0, 6) == "image/") { if (substr($curl_info["content_type"], 0, 6) == "image/") {
$text = "[url=" . $match[1] . "]" . $match[1] . "[/url]"; $text = "[url=" . $match[1] . "]" . $match[1] . "[/url]";
@ -1086,7 +1086,7 @@ class BBCode extends BaseObject
@curl_exec($ch); @curl_exec($ch);
$curl_info = @curl_getinfo($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 its a link to a picture then embed this picture
if (substr($curl_info["content_type"], 0, 6) == "image/") { if (substr($curl_info["content_type"], 0, 6) == "image/") {
@ -1915,7 +1915,7 @@ class BBCode extends BaseObject
// unmask the special chars back to HTML // unmask the special chars back to HTML
$text = str_replace(['&\_lt\_;', '&\_gt\_;', '&\_amp\_;'], ['&lt;', '&gt;', '&amp;'], $text); $text = str_replace(['&\_lt\_;', '&\_gt\_;', '&\_amp\_;'], ['&lt;', '&gt;', '&amp;'], $text);
$a->saveTimestamp($stamp1, "parser"); $a->getProfiler()->saveTimestamp($stamp1, "parser");
// Libertree has a problem with escaped hashtags. // Libertree has a problem with escaped hashtags.
$text = str_replace(['\#'], ['#'], $text); $text = str_replace(['\#'], ['#'], $text);

View file

@ -36,7 +36,7 @@ class Markdown extends BaseObject
$html = $MarkdownParser->transform($text); $html = $MarkdownParser->transform($text);
$html = preg_replace('/<a(.*?)href="#/is', '<a$1href="' . ltrim($_SERVER['REQUEST_URI'], '/') . '#', $html); $html = preg_replace('/<a(.*?)href="#/is', '<a$1href="' . ltrim($_SERVER['REQUEST_URI'], '/') . '#', $html);
self::getApp()->saveTimestamp($stamp1, "parser"); self::getApp()->getProfiler()->saveTimestamp($stamp1, "parser");
return $html; return $html;
} }

View file

@ -219,7 +219,7 @@ class Addon extends BaseObject
$stamp1 = microtime(true); $stamp1 = microtime(true);
$f = file_get_contents("addon/$addon/$addon.php"); $f = file_get_contents("addon/$addon/$addon.php");
$a->saveTimestamp($stamp1, "file"); $a->getProfiler()->saveTimestamp($stamp1, "file");
$r = preg_match("|/\*.*\*/|msU", $f, $m); $r = preg_match("|/\*.*\*/|msU", $f, $m);

View file

@ -63,7 +63,7 @@ class Cache extends \Friendica\BaseObject
$return = self::getDriver()->getAllKeys($prefix); $return = self::getDriver()->getAllKeys($prefix);
self::getApp()->saveTimestamp($time, 'cache'); self::getApp()->getProfiler()->saveTimestamp($time, 'cache');
return $return; return $return;
} }
@ -82,7 +82,7 @@ class Cache extends \Friendica\BaseObject
$return = self::getDriver()->get($key); $return = self::getDriver()->get($key);
self::getApp()->saveTimestamp($time, 'cache'); self::getApp()->getProfiler()->saveTimestamp($time, 'cache');
return $return; return $return;
} }
@ -105,7 +105,7 @@ class Cache extends \Friendica\BaseObject
$return = self::getDriver()->set($key, $value, $duration); $return = self::getDriver()->set($key, $value, $duration);
self::getApp()->saveTimestamp($time, 'cache_write'); self::getApp()->getProfiler()->saveTimestamp($time, 'cache_write');
return $return; return $return;
} }
@ -124,7 +124,7 @@ class Cache extends \Friendica\BaseObject
$return = self::getDriver()->delete($key); $return = self::getDriver()->delete($key);
self::getApp()->saveTimestamp($time, 'cache_write'); self::getApp()->getProfiler()->saveTimestamp($time, 'cache_write');
return $return; return $return;
} }

View file

@ -146,7 +146,7 @@ HELP;
$installer->resetChecks(); $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()); $errorMessage = $this->extractErrors($installer->getChecks());
throw new RuntimeException($errorMessage); throw new RuntimeException($errorMessage);
} }

View file

@ -11,6 +11,7 @@ use Friendica\Database\DBA;
use Friendica\Database\DBStructure; use Friendica\Database\DBStructure;
use Friendica\Object\Image; use Friendica\Object\Image;
use Friendica\Util\Network; use Friendica\Util\Network;
use Friendica\Util\Profiler;
use Friendica\Util\Strings; use Friendica\Util\Strings;
/** /**
@ -583,6 +584,7 @@ class Installer
* Checking the Database connection and if it is available for the current installation * Checking the Database connection and if it is available for the current installation
* *
* @param ConfigCache $configCache The configuration cache * @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 $dbhost Hostname/IP of the Friendica Database
* @param string $dbuser Username of the Database connection credentials * @param string $dbuser Username of the Database connection credentials
* @param string $dbpass Password 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 * @return bool true if the check was successful, otherwise false
* @throws Exception * @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, ''); $this->addCheck(L10n::t('Could not connect to database.'), false, true, '');
return false; return false;

View file

@ -155,7 +155,7 @@ class Logger extends BaseObject
$stamp1 = microtime(true); $stamp1 = microtime(true);
self::$logger->emergency($message, $context); 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); $stamp1 = microtime(true);
self::$logger->alert($message, $context); 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); $stamp1 = microtime(true);
self::$logger->critical($message, $context); 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); $stamp1 = microtime(true);
self::$logger->error($message, $context); 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); $stamp1 = microtime(true);
self::$logger->warning($message, $context); 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); $stamp1 = microtime(true);
self::$logger->notice($message, $context); 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); $stamp1 = microtime(true);
self::$logger->info($message, $context); 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); $stamp1 = microtime(true);
self::$logger->debug($message, $context); 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); $stamp1 = microtime(true);
self::$logger->log($level, $msg); 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); $stamp1 = microtime(true);
self::$devLogger->log($level, $msg); self::$devLogger->log($level, $msg);
self::getApp()->saveTimestamp($stamp1, "file"); self::getApp()->getProfiler()->saveTimestamp($stamp1, "file");
} }
} }

View file

@ -74,7 +74,7 @@ class Renderer extends BaseObject
exit(); exit();
} }
$a->saveTimestamp($stamp1, "rendering"); $a->getProfiler()->saveTimestamp($stamp1, "rendering");
return $output; return $output;
} }
@ -101,7 +101,7 @@ class Renderer extends BaseObject
exit(); exit();
} }
$a->saveTimestamp($stamp1, "file"); $a->getProfiler()->saveTimestamp($stamp1, "file");
return $template; return $template;
} }

View file

@ -51,7 +51,7 @@ class Theme
$a = \get_app(); $a = \get_app();
$stamp1 = microtime(true); $stamp1 = microtime(true);
$theme_file = file_get_contents("view/theme/$theme/theme.php"); $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); $result = preg_match("|/\*.*\*/|msU", $theme_file, $matches);

View file

@ -380,20 +380,7 @@ class Worker
// We use the callstack here to analyze the performance of executed worker entries. // We use the callstack here to analyze the performance of executed worker entries.
// For this reason the variables have to be initialized. // For this reason the variables have to be initialized.
if (Config::get("system", "profiler")) { $a->getProfiler()->reset();
$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 = [];
}
// For better logging create a new process id for every worker call // For better logging create a new process id for every worker call
// But preserve the old one for the worker // 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); 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 $a->getProfiler()->saveLog("ID " . $queue["id"] . ": " . $funcname);
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
);
}
$cooldown = Config::get("system", "worker_cooldown", 0); $cooldown = Config::get("system", "worker_cooldown", 0);

View file

@ -6,6 +6,7 @@ use Friendica\Core\Config\IConfigCache;
use Friendica\Core\Logger; use Friendica\Core\Logger;
use Friendica\Core\System; use Friendica\Core\System;
use Friendica\Util\DateTimeFormat; use Friendica\Util\DateTimeFormat;
use Friendica\Util\Profiler;
use mysqli; use mysqli;
use mysqli_result; use mysqli_result;
use mysqli_stmt; use mysqli_stmt;
@ -35,6 +36,10 @@ class DBA
* @var IConfigCache * @var IConfigCache
*/ */
private static $configCache; private static $configCache;
/**
* @var Profiler
*/
private static $profiler;
private static $server_info = ''; private static $server_info = '';
private static $connection; private static $connection;
private static $driver; private static $driver;
@ -50,7 +55,7 @@ class DBA
private static $db_name = ''; private static $db_name = '';
private static $db_charset = ''; 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()) { if (!is_null(self::$connection) && self::connected()) {
return true; return true;
@ -58,6 +63,7 @@ class DBA
// We are storing these values for being able to perform a reconnect // We are storing these values for being able to perform a reconnect
self::$configCache = $configCache; self::$configCache = $configCache;
self::$profiler = $profiler;
self::$db_serveraddr = $serveraddr; self::$db_serveraddr = $serveraddr;
self::$db_user = $user; self::$db_user = $user;
self::$db_pass = $pass; self::$db_pass = $pass;
@ -158,7 +164,7 @@ class DBA
public static function reconnect() { public static function reconnect() {
self::disconnect(); 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; return $ret;
} }
@ -392,7 +398,6 @@ class DBA
* @throws \Exception * @throws \Exception
*/ */
public static function p($sql) { public static function p($sql) {
$a = \get_app();
$stamp1 = microtime(true); $stamp1 = microtime(true);
@ -582,7 +587,7 @@ class DBA
self::$errorno = $errorno; self::$errorno = $errorno;
} }
$a->saveTimestamp($stamp1, 'database'); self::$profiler->saveTimestamp($stamp1, 'database');
if (self::$configCache->get('system', 'db_log')) { if (self::$configCache->get('system', 'db_log')) {
$stamp2 = microtime(true); $stamp2 = microtime(true);
@ -611,7 +616,6 @@ class DBA
* @throws \Exception * @throws \Exception
*/ */
public static function e($sql) { public static function e($sql) {
$a = \get_app();
$stamp = microtime(true); $stamp = microtime(true);
@ -654,7 +658,7 @@ class DBA
self::$errorno = $errorno; self::$errorno = $errorno;
} }
$a->saveTimestamp($stamp, "database_write"); self::$profiler->saveTimestamp($stamp, "database_write");
return $retval; return $retval;
} }
@ -777,7 +781,6 @@ class DBA
* @return array current row * @return array current row
*/ */
public static function fetch($stmt) { public static function fetch($stmt) {
$a = \get_app();
$stamp1 = microtime(true); $stamp1 = microtime(true);
@ -824,7 +827,7 @@ class DBA
} }
} }
$a->saveTimestamp($stamp1, 'database'); self::$profiler->saveTimestamp($stamp1, 'database');
return $columns; return $columns;
} }
@ -1534,7 +1537,6 @@ class DBA
* @return boolean was the close successful? * @return boolean was the close successful?
*/ */
public static function close($stmt) { public static function close($stmt) {
$a = \get_app();
$stamp1 = microtime(true); $stamp1 = microtime(true);
@ -1562,7 +1564,7 @@ class DBA
break; break;
} }
$a->saveTimestamp($stamp1, 'database'); self::$profiler->saveTimestamp($stamp1, 'database');
return $ret; return $ret;
} }

View file

@ -0,0 +1,25 @@
<?php
namespace Friendica\Factory;
use Friendica\Core\Config\ConfigCache;
use Friendica\Util\Profiler;
use Psr\Log\LoggerInterface;
class ProfilerFactory
{
/**
* Creates a Profiler for the current execution
*
* @param LoggerInterface $logger The logger for saving the profiling data
* @param ConfigCache $configCache The configuration cache
*
* @return Profiler
*/
public static function create(LoggerInterface $logger, ConfigCache $configCache)
{
$enabled = $configCache->get('system', 'profiler', false);
$renderTime = $configCache->get('rendertime', 'callstack', false);
return new Profiler($logger, $enabled, $renderTime);
}
}

View file

@ -75,7 +75,7 @@ class Install extends BaseModule
$dbdata = Strings::escapeTags(trim(defaults($_POST, 'dbdata', ''))); $dbdata = Strings::escapeTags(trim(defaults($_POST, 'dbdata', '')));
// If we cannot connect to the database, return to the previous step // 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; self::$currentWizardStep = self::DATABASE_CONFIG;
} }
@ -92,7 +92,7 @@ class Install extends BaseModule
$adminmail = Strings::escapeTags(trim(defaults($_POST, 'adminmail', ''))); $adminmail = Strings::escapeTags(trim(defaults($_POST, 'adminmail', '')));
// If we cannot connect to the database, return to the Database config wizard // 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; self::$currentWizardStep = self::DATABASE_CONFIG;
return; return;
} }

View file

@ -5,6 +5,7 @@
*/ */
namespace Friendica\Object; namespace Friendica\Object;
use Exception;
use Friendica\App; use Friendica\App;
use Friendica\Core\Cache; use Friendica\Core\Cache;
use Friendica\Core\Config; use Friendica\Core\Config;
@ -14,7 +15,6 @@ use Friendica\Core\System;
use Friendica\Database\DBA; use Friendica\Database\DBA;
use Friendica\Model\Photo; use Friendica\Model\Photo;
use Friendica\Util\Network; use Friendica\Util\Network;
use Exception;
use Imagick; use Imagick;
use ImagickPixel; use ImagickPixel;
@ -656,7 +656,7 @@ class Image
$stamp1 = microtime(true); $stamp1 = microtime(true);
file_put_contents($path, $string); file_put_contents($path, $string);
$a->saveTimestamp($stamp1, "file"); $a->getProfiler()->saveTimestamp($stamp1, "file");
} }
/** /**
@ -802,7 +802,7 @@ class Image
$a = \get_app(); $a = \get_app();
$stamp1 = microtime(true); $stamp1 = microtime(true);
file_put_contents($tempfile, $img_str); file_put_contents($tempfile, $img_str);
$a->saveTimestamp($stamp1, "file"); $a->getProfiler()->saveTimestamp($stamp1, "file");
$data = getimagesize($tempfile); $data = getimagesize($tempfile);
unlink($tempfile); unlink($tempfile);
@ -910,7 +910,7 @@ class Image
$stamp1 = microtime(true); $stamp1 = microtime(true);
$imagedata = @file_get_contents($url); $imagedata = @file_get_contents($url);
$a->saveTimestamp($stamp1, "file"); $a->getProfiler()->saveTimestamp($stamp1, "file");
} }
$maximagesize = Config::get('system', 'maximagesize'); $maximagesize = Config::get('system', 'maximagesize');
@ -924,7 +924,7 @@ class Image
$stamp1 = microtime(true); $stamp1 = microtime(true);
file_put_contents($tempfile, $imagedata); file_put_contents($tempfile, $imagedata);
$a->saveTimestamp($stamp1, "file"); $a->getProfiler()->saveTimestamp($stamp1, "file");
$data = getimagesize($tempfile); $data = getimagesize($tempfile);

View file

@ -4,13 +4,13 @@
*/ */
namespace Friendica\Util; namespace Friendica\Util;
use DOMDocument;
use DomXPath;
use Friendica\Core\Config;
use Friendica\Core\Hook; use Friendica\Core\Hook;
use Friendica\Core\Logger; use Friendica\Core\Logger;
use Friendica\Core\System; use Friendica\Core\System;
use Friendica\Core\Config;
use Friendica\Network\CurlResult; use Friendica\Network\CurlResult;
use DOMDocument;
use DomXPath;
class Network class Network
{ {
@ -232,7 +232,7 @@ class Network
@curl_close($ch); @curl_close($ch);
$a->saveTimestamp($stamp1, 'network'); $a->getProfiler()->saveTimestamp($stamp1, 'network');
return $curlResponse; return $curlResponse;
} }
@ -334,7 +334,7 @@ class Network
curl_close($ch); curl_close($ch);
$a->saveTimestamp($stamp1, 'network'); $a->getProfiler()->saveTimestamp($stamp1, 'network');
Logger::log('post_url: end ' . $url, Logger::DATA); Logger::log('post_url: end ' . $url, Logger::DATA);
@ -641,7 +641,7 @@ class Network
$http_code = $curl_info['http_code']; $http_code = $curl_info['http_code'];
curl_close($ch); curl_close($ch);
$a->saveTimestamp($stamp1, "network"); $a->getProfiler()->saveTimestamp($stamp1, "network");
if ($http_code == 0) { if ($http_code == 0) {
return $url; return $url;
@ -683,7 +683,7 @@ class Network
$body = curl_exec($ch); $body = curl_exec($ch);
curl_close($ch); curl_close($ch);
$a->saveTimestamp($stamp1, "network"); $a->getProfiler()->saveTimestamp($stamp1, "network");
if (trim($body) == "") { if (trim($body) == "") {
return $url; return $url;

252
src/Util/Profiler.php Normal file
View file

@ -0,0 +1,252 @@
<?php
namespace Friendica\Util;
use Friendica\Core;
use Psr\Container\ContainerExceptionInterface;
use Psr\Container\ContainerInterface;
use Psr\Container\NotFoundExceptionInterface;
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 )
*/
class Profiler implements ContainerInterface
{
/**
* @var array The global performance array
*/
private $performance;
/**
* @var array The function specific callstack
*/
private $callstack;
/**
* @var bool True, if the Profiler is enabled
*/
private $enabled;
/**
* @var bool True, if the Profiler should measure the whole rendertime including functions
*/
private $rendertime;
/**
* @var LoggerInterface The profiler logger
*/
private $logger;
/**
* @param LoggerInterface $logger The profiler logger
* @param bool $enabled True, if the Profiler is enabled
* @param bool $renderTime True, if the Profiler should measure the whole rendertime including functions
*/
public function __construct(LoggerInterface $logger, $enabled = false, $renderTime = false)
{
$this->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]);
}
}

View file

@ -9,6 +9,7 @@ use Friendica\Core\Config;
use Friendica\Database\DBA; use Friendica\Database\DBA;
use Friendica\Factory; use Friendica\Factory;
use Friendica\Util\BasePath; use Friendica\Util\BasePath;
use Friendica\Util\Profiler;
use PHPUnit\DbUnit\DataSet\YamlDataSet; use PHPUnit\DbUnit\DataSet\YamlDataSet;
use PHPUnit\DbUnit\TestCaseTrait; use PHPUnit\DbUnit\TestCaseTrait;
use PHPUnit_Extensions_Database_DB_IDatabaseConnection; use PHPUnit_Extensions_Database_DB_IDatabaseConnection;
@ -43,8 +44,11 @@ abstract class DatabaseTest extends MockedTest
$configLoader = new Config\ConfigCacheLoader($basedir); $configLoader = new Config\ConfigCacheLoader($basedir);
$config = Factory\ConfigFactory::createCache($configLoader); $config = Factory\ConfigFactory::createCache($configLoader);
$profiler = \Mockery::mock(Profiler::class);
DBA::connect( DBA::connect(
$config, $config,
$profiler,
getenv('MYSQL_HOST'), getenv('MYSQL_HOST'),
getenv('MYSQL_USERNAME'), getenv('MYSQL_USERNAME'),
getenv('MYSQL_PASSWORD'), getenv('MYSQL_PASSWORD'),