diff --git a/lib/private/CapabilitiesManager.php b/lib/private/CapabilitiesManager.php index 884b957dbdd8d..9e9db13a89bed 100644 --- a/lib/private/CapabilitiesManager.php +++ b/lib/private/CapabilitiesManager.php @@ -40,6 +40,7 @@ public function __construct( */ public function getCapabilities(bool $public = false, bool $initialState = false) : array { $capabilities = []; + $slowCapabilities = []; foreach ($this->capabilities as $capability) { try { $c = $capability(); @@ -57,26 +58,13 @@ public function getCapabilities(bool $public = false, bool $initialState = false // that we would otherwise inject to every page load continue; } + $startTime = microtime(true); $capabilities = array_replace_recursive($capabilities, $c->getCapabilities()); - $endTime = microtime(true); - $timeSpent = $endTime - $startTime; + $timeSpent = microtime(true) - $startTime; + if ($timeSpent > self::ACCEPTABLE_LOADING_TIME) { - $logLevel = match (true) { - $timeSpent > self::ACCEPTABLE_LOADING_TIME * 16 => ILogger::FATAL, - $timeSpent > self::ACCEPTABLE_LOADING_TIME * 8 => ILogger::ERROR, - $timeSpent > self::ACCEPTABLE_LOADING_TIME * 4 => ILogger::WARN, - $timeSpent > self::ACCEPTABLE_LOADING_TIME * 2 => ILogger::INFO, - default => ILogger::DEBUG, - }; - $this->logger->log( - $logLevel, - 'Capabilities of {className} took {duration} seconds to generate.', - [ - 'className' => get_class($c), - 'duration' => round($timeSpent, 2), - ] - ); + $slowCapabilities[get_class($c)] = $timeSpent; } } } else { @@ -84,9 +72,44 @@ public function getCapabilities(bool $public = false, bool $initialState = false } } + if ($slowCapabilities !== []) { + $this->logSlowCapabilities($slowCapabilities); + } + return $capabilities; } + /** + * Log a single message for all capabilities that took too long to generate, + * using the highest log level applicable to the slowest one. + * + * @param array $slowCapabilities Map of class name to time spent in seconds + */ + private function logSlowCapabilities(array $slowCapabilities): void { + $slowestTime = max($slowCapabilities); + $logLevel = match (true) { + $slowestTime > self::ACCEPTABLE_LOADING_TIME * 16 => ILogger::FATAL, + $slowestTime > self::ACCEPTABLE_LOADING_TIME * 8 => ILogger::ERROR, + $slowestTime > self::ACCEPTABLE_LOADING_TIME * 4 => ILogger::WARN, + $slowestTime > self::ACCEPTABLE_LOADING_TIME * 2 => ILogger::INFO, + default => ILogger::DEBUG, + }; + + $durations = []; + foreach ($slowCapabilities as $className => $timeSpent) { + $durations[] = $className . ' (' . round($timeSpent, 2) . 's)'; + } + + $this->logger->log( + $logLevel, + 'Generating the capabilities of the following apps took longer than {acceptable} seconds: {capabilities}', + [ + 'acceptable' => self::ACCEPTABLE_LOADING_TIME, + 'capabilities' => implode(', ', $durations), + ] + ); + } + /** * In order to improve lazy loading a closure can be registered which will be called in case * capabilities are actually requested