From 3e6d2dc794ce15d2fa2bb1b0fdcaf587170dc293 Mon Sep 17 00:00:00 2001 From: "Simon L." Date: Mon, 16 Mar 2026 11:34:08 +0100 Subject: [PATCH 1/2] fix(CapabilitiesManager): only check execution time if debug mode is enabled Signed-off-by: Simon L. Co-Authored-By: Anna --- lib/private/CapabilitiesManager.php | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/lib/private/CapabilitiesManager.php b/lib/private/CapabilitiesManager.php index 884b957dbdd8d..94cff85a41596 100644 --- a/lib/private/CapabilitiesManager.php +++ b/lib/private/CapabilitiesManager.php @@ -13,6 +13,7 @@ use OCP\Capabilities\ICapability; use OCP\Capabilities\IInitialStateExcludedCapability; use OCP\Capabilities\IPublicCapability; +use OCP\IConfig; use OCP\ILogger; use Psr\Log\LoggerInterface; @@ -57,11 +58,15 @@ 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); + + // Only check execution time if debug mode is enabled + $debugMode = \OCP\Server::get(IConfig::class)->getSystemValueBool('debug', false); $timeSpent = $endTime - $startTime; - if ($timeSpent > self::ACCEPTABLE_LOADING_TIME) { + if ($debugMode && $timeSpent > self::ACCEPTABLE_LOADING_TIME) { $logLevel = match (true) { $timeSpent > self::ACCEPTABLE_LOADING_TIME * 16 => ILogger::FATAL, $timeSpent > self::ACCEPTABLE_LOADING_TIME * 8 => ILogger::ERROR, From 3881d9b1fa221f56937a9b332280d19a20d4793e Mon Sep 17 00:00:00 2001 From: "Simon L." Date: Mon, 15 Jun 2026 18:42:47 +0200 Subject: [PATCH 2/2] refactor(CapabilitiesManager): log slow capabilities in a single message Instead of logging one message per slow capability (and only in debug mode), collect all slow capabilities and emit a single log entry with all timings, using the highest applicable log level. Signed-off-by: Simon L. Co-Authored-By: Claude Opus 4.8 (1M context) Signed-off-by: Simon L. --- lib/private/CapabilitiesManager.php | 62 +++++++++++++++++++---------- 1 file changed, 40 insertions(+), 22 deletions(-) diff --git a/lib/private/CapabilitiesManager.php b/lib/private/CapabilitiesManager.php index 94cff85a41596..9e9db13a89bed 100644 --- a/lib/private/CapabilitiesManager.php +++ b/lib/private/CapabilitiesManager.php @@ -13,7 +13,6 @@ use OCP\Capabilities\ICapability; use OCP\Capabilities\IInitialStateExcludedCapability; use OCP\Capabilities\IPublicCapability; -use OCP\IConfig; use OCP\ILogger; use Psr\Log\LoggerInterface; @@ -41,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(); @@ -61,27 +61,10 @@ public function getCapabilities(bool $public = false, bool $initialState = false $startTime = microtime(true); $capabilities = array_replace_recursive($capabilities, $c->getCapabilities()); - $endTime = microtime(true); - - // Only check execution time if debug mode is enabled - $debugMode = \OCP\Server::get(IConfig::class)->getSystemValueBool('debug', false); - $timeSpent = $endTime - $startTime; - if ($debugMode && $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), - ] - ); + $timeSpent = microtime(true) - $startTime; + + if ($timeSpent > self::ACCEPTABLE_LOADING_TIME) { + $slowCapabilities[get_class($c)] = $timeSpent; } } } else { @@ -89,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