diff --git a/apps/dav/composer/composer/autoload_classmap.php b/apps/dav/composer/composer/autoload_classmap.php index 764f94ef665..b9708ea5589 100644 --- a/apps/dav/composer/composer/autoload_classmap.php +++ b/apps/dav/composer/composer/autoload_classmap.php @@ -216,6 +216,7 @@ return array( 'OCA\\DAV\\Connector\\Sabre\\Node' => $baseDir . '/../lib/Connector/Sabre/Node.php', 'OCA\\DAV\\Connector\\Sabre\\ObjectTree' => $baseDir . '/../lib/Connector/Sabre/ObjectTree.php', 'OCA\\DAV\\Connector\\Sabre\\Principal' => $baseDir . '/../lib/Connector/Sabre/Principal.php', + 'OCA\\DAV\\Connector\\Sabre\\PropFindMonitorPlugin' => $baseDir . '/../lib/Connector/Sabre/PropFindMonitorPlugin.php', 'OCA\\DAV\\Connector\\Sabre\\PropfindCompressionPlugin' => $baseDir . '/../lib/Connector/Sabre/PropfindCompressionPlugin.php', 'OCA\\DAV\\Connector\\Sabre\\PublicAuth' => $baseDir . '/../lib/Connector/Sabre/PublicAuth.php', 'OCA\\DAV\\Connector\\Sabre\\QuotaPlugin' => $baseDir . '/../lib/Connector/Sabre/QuotaPlugin.php', diff --git a/apps/dav/composer/composer/autoload_static.php b/apps/dav/composer/composer/autoload_static.php index f3d1eacfcd0..75ac3350160 100644 --- a/apps/dav/composer/composer/autoload_static.php +++ b/apps/dav/composer/composer/autoload_static.php @@ -231,6 +231,7 @@ class ComposerStaticInitDAV 'OCA\\DAV\\Connector\\Sabre\\Node' => __DIR__ . '/..' . '/../lib/Connector/Sabre/Node.php', 'OCA\\DAV\\Connector\\Sabre\\ObjectTree' => __DIR__ . '/..' . '/../lib/Connector/Sabre/ObjectTree.php', 'OCA\\DAV\\Connector\\Sabre\\Principal' => __DIR__ . '/..' . '/../lib/Connector/Sabre/Principal.php', + 'OCA\\DAV\\Connector\\Sabre\\PropFindMonitorPlugin' => __DIR__ . '/..' . '/../lib/Connector/Sabre/PropFindMonitorPlugin.php', 'OCA\\DAV\\Connector\\Sabre\\PropfindCompressionPlugin' => __DIR__ . '/..' . '/../lib/Connector/Sabre/PropfindCompressionPlugin.php', 'OCA\\DAV\\Connector\\Sabre\\PublicAuth' => __DIR__ . '/..' . '/../lib/Connector/Sabre/PublicAuth.php', 'OCA\\DAV\\Connector\\Sabre\\QuotaPlugin' => __DIR__ . '/..' . '/../lib/Connector/Sabre/QuotaPlugin.php', diff --git a/apps/dav/lib/Connector/Sabre/PropFindMonitorPlugin.php b/apps/dav/lib/Connector/Sabre/PropFindMonitorPlugin.php new file mode 100644 index 00000000000..130d4562146 --- /dev/null +++ b/apps/dav/lib/Connector/Sabre/PropFindMonitorPlugin.php @@ -0,0 +1,78 @@ +server = $server; + $this->server->on('afterResponse', [$this, 'afterResponse']); + } + + public function afterResponse( + RequestInterface $request, + ResponseInterface $response): void { + if (!$this->server instanceof Server) { + return; + } + + $pluginQueries = $this->server->getPluginQueries(); + if (empty($pluginQueries)) { + return; + } + $maxDepth = max(0, ...array_keys($pluginQueries)); + // entries at the top are usually not interesting + unset($pluginQueries[$maxDepth]); + + $logger = $this->server->getLogger(); + foreach ($pluginQueries as $depth => $propFinds) { + foreach ($propFinds as $pluginName => $propFind) { + [ + 'queries' => $queries, + 'nodes' => $nodes + ] = $propFind; + if ($queries === 0 || $nodes > $queries || $nodes < self::THRESHOLD_NODES + || $queries < $nodes * self::THRESHOLD_QUERY_FACTOR) { + continue; + } + $logger->error( + '{name} scanned {scans} nodes with {count} queries in depth {depth}/{maxDepth}. This is bad for performance, please report to the plugin developer!', [ + 'name' => $pluginName, + 'scans' => $nodes, + 'count' => $queries, + 'depth' => $depth, + 'maxDepth' => $maxDepth, + ] + ); + } + } + } +} diff --git a/apps/dav/lib/Connector/Sabre/Server.php b/apps/dav/lib/Connector/Sabre/Server.php index f3bfac1d6e0..dda9c29b763 100644 --- a/apps/dav/lib/Connector/Sabre/Server.php +++ b/apps/dav/lib/Connector/Sabre/Server.php @@ -7,7 +7,11 @@ */ namespace OCA\DAV\Connector\Sabre; +use OC\DB\Connection; +use Override; use Sabre\DAV\Exception; +use Sabre\DAV\INode; +use Sabre\DAV\PropFind; use Sabre\DAV\Version; use TypeError; @@ -21,6 +25,14 @@ use TypeError; class Server extends \Sabre\DAV\Server { /** @var CachingTree $tree */ + /** + * Tracks queries done by plugins. + * @var array> + */ + private array $pluginQueries = []; + + public bool $debugEnabled = false; + /** * @see \Sabre\DAV\Server */ @@ -30,6 +42,97 @@ class Server extends \Sabre\DAV\Server { $this->enablePropfindDepthInfinity = true; } + #[Override] + public function once( + string $eventName, + callable $callBack, + int $priority = 100, + ): void { + $this->debugEnabled ? $this->monitorPropfindQueries( + parent::once(...), + ...func_get_args(), + ) : parent::once(...func_get_args()); + } + + #[Override] + public function on( + string $eventName, + callable $callBack, + int $priority = 100, + ): void { + $this->debugEnabled ? $this->monitorPropfindQueries( + parent::on(...), + ...func_get_args(), + ) : parent::on(...func_get_args()); + } + + /** + * Wraps the handler $callBack into a query-monitoring function and calls + * $parentFn to register it. + */ + private function monitorPropfindQueries( + callable $parentFn, + string $eventName, + callable $callBack, + int $priority = 100, + ): void { + if ($eventName !== 'propFind') { + $parentFn($eventName, $callBack, $priority); + return; + } + + $pluginName = debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS, 3)[2]['class'] ?? 'unknown'; + $callback = $this->getMonitoredCallback($callBack, $pluginName); + + $parentFn($eventName, $callback, $priority); + } + + /** + * Returns a callable that wraps $callBack with code that monitors and + * records queries per plugin. + */ + private function getMonitoredCallback( + callable $callBack, + string $pluginName, + ): callable { + return function (PropFind $propFind, INode $node) use ( + $callBack, + $pluginName, + ) { + $connection = \OCP\Server::get(Connection::class); + $queriesBefore = $connection->getStats()['executed']; + $result = $callBack($propFind, $node); + $queriesAfter = $connection->getStats()['executed']; + $this->trackPluginQueries( + $pluginName, + $queriesAfter - $queriesBefore, + $propFind->getDepth() + ); + + return $result; + }; + } + + /** + * Tracks the queries executed by a specific plugin. + */ + private function trackPluginQueries( + string $pluginName, + int $queriesExecuted, + int $depth, + ): void { + // report only nodes which cause queries to the DB + if ($queriesExecuted === 0) { + return; + } + + $this->pluginQueries[$depth][$pluginName]['nodes'] + = ($this->pluginQueries[$depth][$pluginName]['nodes'] ?? 0) + 1; + + $this->pluginQueries[$depth][$pluginName]['queries'] + = ($this->pluginQueries[$depth][$pluginName]['queries'] ?? 0) + $queriesExecuted; + } + /** * * @return void @@ -115,4 +218,13 @@ class Server extends \Sabre\DAV\Server { $this->sapi->sendResponse($this->httpResponse); } } + + /** + * Returns queries executed by registered plugins. + * + * @return array> + */ + public function getPluginQueries(): array { + return $this->pluginQueries; + } } diff --git a/apps/dav/lib/Connector/Sabre/ServerFactory.php b/apps/dav/lib/Connector/Sabre/ServerFactory.php index 3749b506d16..a6a27057177 100644 --- a/apps/dav/lib/Connector/Sabre/ServerFactory.php +++ b/apps/dav/lib/Connector/Sabre/ServerFactory.php @@ -68,6 +68,7 @@ class ServerFactory { Plugin $authPlugin, callable $viewCallBack, ): Server { + $debugEnabled = $this->config->getSystemValue('debug', false); // Fire up server if ($isPublicShare) { $rootCollection = new SimpleCollection('root'); @@ -89,6 +90,10 @@ class ServerFactory { )); $server->addPlugin(new AnonymousOptionsPlugin()); $server->addPlugin($authPlugin); + if ($debugEnabled) { + $server->debugEnabled = $debugEnabled; + $server->addPlugin(new PropFindMonitorPlugin()); + } // FIXME: The following line is a workaround for legacy components relying on being able to send a GET to / $server->addPlugin(new DummyGetResponsePlugin()); $server->addPlugin(new ExceptionLoggerPlugin('webdav', $this->logger)); @@ -117,7 +122,8 @@ class ServerFactory { } // wait with registering these until auth is handled and the filesystem is setup - $server->on('beforeMethod:*', function () use ($server, $tree, $viewCallBack, $isPublicShare, $rootCollection): void { + $server->on('beforeMethod:*', function () use ($server, $tree, + $viewCallBack, $isPublicShare, $rootCollection, $debugEnabled): void { // ensure the skeleton is copied $userFolder = \OC::$server->getUserFolder(); @@ -181,7 +187,7 @@ class ServerFactory { \OCP\Server::get(IFilenameValidator::class), \OCP\Server::get(IAccountManager::class), false, - !$this->config->getSystemValue('debug', false) + !$debugEnabled ) ); $server->addPlugin(new QuotaPlugin($view)); diff --git a/apps/dav/lib/Server.php b/apps/dav/lib/Server.php index f81c7fa6f29..a92e162f1b0 100644 --- a/apps/dav/lib/Server.php +++ b/apps/dav/lib/Server.php @@ -45,6 +45,7 @@ use OCA\DAV\Connector\Sabre\FilesReportPlugin; use OCA\DAV\Connector\Sabre\LockPlugin; use OCA\DAV\Connector\Sabre\MaintenancePlugin; use OCA\DAV\Connector\Sabre\PropfindCompressionPlugin; +use OCA\DAV\Connector\Sabre\PropFindMonitorPlugin; use OCA\DAV\Connector\Sabre\QuotaPlugin; use OCA\DAV\Connector\Sabre\RequestIdHeaderPlugin; use OCA\DAV\Connector\Sabre\SharesPlugin; @@ -108,6 +109,7 @@ class Server { private IRequest $request, private string $baseUri, ) { + $debugEnabled = \OCP\Server::get(IConfig::class)->getSystemValue('debug', false); $this->profiler = \OCP\Server::get(IProfiler::class); if ($this->profiler->isEnabled()) { /** @var IEventLogger $eventLogger */ @@ -120,6 +122,7 @@ class Server { $root = new RootCollection(); $this->server = new \OCA\DAV\Connector\Sabre\Server(new CachingTree($root)); + $this->server->setLogger($logger); // Add maintenance plugin $this->server->addPlugin(new MaintenancePlugin(\OCP\Server::get(IConfig::class), \OC::$server->getL10N('dav'))); @@ -167,7 +170,9 @@ class Server { $authPlugin->addBackend($authBackend); // debugging - if (\OCP\Server::get(IConfig::class)->getSystemValue('debug', false)) { + if ($debugEnabled) { + $this->server->debugEnabled = true; + $this->server->addPlugin(new PropFindMonitorPlugin()); $this->server->addPlugin(new \Sabre\DAV\Browser\Plugin()); } else { $this->server->addPlugin(new DummyGetResponsePlugin()); diff --git a/apps/dav/tests/unit/Connector/Sabre/PropFindMonitorPluginTest.php b/apps/dav/tests/unit/Connector/Sabre/PropFindMonitorPluginTest.php new file mode 100644 index 00000000000..b528c3d731c --- /dev/null +++ b/apps/dav/tests/unit/Connector/Sabre/PropFindMonitorPluginTest.php @@ -0,0 +1,123 @@ + [[], 0], + 'Plugins with queries in less than threshold nodes should not be logged' => [ + [ + [ + 'PluginName' => ['queries' => 100, 'nodes' + => PropFindMonitorPlugin::THRESHOLD_NODES - 1] + ], + [], + ], + 0 + ], + 'Plugins with query-to-node ratio less than threshold should not be logged' => [ + [ + [ + 'PluginName' => [ + 'queries' => $minQueriesTrigger - 1, + 'nodes' => PropFindMonitorPlugin::THRESHOLD_NODES ], + ], + [], + ], + 0 + ], + 'Plugins with more nodes scanned than queries executed should not be logged' => [ + [ + [ + 'PluginName' => [ + 'queries' => $minQueriesTrigger, + 'nodes' => PropFindMonitorPlugin::THRESHOLD_NODES * 2], + ], + [], + ], + 0 + ], + 'Plugins with queries only in highest depth level should not be logged' => [ + [ + [ + 'PluginName' => [ + 'queries' => $minQueriesTrigger, + 'nodes' => PropFindMonitorPlugin::THRESHOLD_NODES - 1 + ] + ], + [ + 'PluginName' => [ + 'queries' => $minQueriesTrigger * 2, + 'nodes' => PropFindMonitorPlugin::THRESHOLD_NODES + ] + ] + ], + 0 + ], + 'Plugins with too many queries should be logged' => [ + [ + [ + 'FirstPlugin' => [ + 'queries' => $minQueriesTrigger, + 'nodes' => PropFindMonitorPlugin::THRESHOLD_NODES, + ], + 'SecondPlugin' => [ + 'queries' => $minQueriesTrigger, + 'nodes' => PropFindMonitorPlugin::THRESHOLD_NODES, + ] + ], + [] + ], + 2 + ] + ]; + } + + /** + * @dataProvider dataTest + */ + public function test(array $queries, $expectedLogCalls): void { + $this->plugin->initialize($this->server); + $this->server->expects($this->once())->method('getPluginQueries') + ->willReturn($queries); + + $this->server->expects(empty($queries) ? $this->never() : $this->once()) + ->method('getLogger') + ->willReturn($this->logger); + + $this->logger->expects($this->exactly($expectedLogCalls))->method('error'); + $this->plugin->afterResponse($this->request, $this->response); + } + + protected function setUp(): void { + parent::setUp(); + + $this->plugin = new PropFindMonitorPlugin(); + $this->server = $this->createMock(Server::class); + $this->logger = $this->createMock(LoggerInterface::class); + $this->request = $this->createMock(Request::class); + $this->response = $this->createMock(Response::class); + } +}