From 3212c074b95b7526767c33138dfa580790765aef Mon Sep 17 00:00:00 2001 From: Joas Schilling Date: Fri, 25 Sep 2020 14:47:14 +0200 Subject: [PATCH 1/2] Log the number of queries built and executed Signed-off-by: Joas Schilling --- .../DependencyInjection/DIContainer.php | 6 ++- lib/private/AppFramework/Http/Dispatcher.php | 53 ++++++++++++++++++- lib/private/DB/Connection.php | 18 +++++++ 3 files changed, 75 insertions(+), 2 deletions(-) diff --git a/lib/private/AppFramework/DependencyInjection/DIContainer.php b/lib/private/AppFramework/DependencyInjection/DIContainer.php index 875597a1fb..3ef816f503 100644 --- a/lib/private/AppFramework/DependencyInjection/DIContainer.php +++ b/lib/private/AppFramework/DependencyInjection/DIContainer.php @@ -61,6 +61,7 @@ use OCP\Files\Folder; use OCP\Files\IAppData; use OCP\Group\ISubAdmin; use OCP\IConfig; +use OCP\IDBConnection; use OCP\IInitialStateService; use OCP\IL10N; use OCP\ILogger; @@ -180,7 +181,10 @@ class DIContainer extends SimpleContainer implements IAppContainer { $c->get('Protocol'), $c->get(MiddlewareDispatcher::class), $c->get(IControllerMethodReflector::class), - $c->get(IRequest::class) + $c->get(IRequest::class), + $c->get(IConfig::class), + $c->get(IDBConnection::class), + $c->get(LoggerInterface::class) ); }); diff --git a/lib/private/AppFramework/Http/Dispatcher.php b/lib/private/AppFramework/Http/Dispatcher.php index 3892bb667f..930e18b032 100644 --- a/lib/private/AppFramework/Http/Dispatcher.php +++ b/lib/private/AppFramework/Http/Dispatcher.php @@ -36,10 +36,15 @@ use OC\AppFramework\Http; use OC\AppFramework\Middleware\MiddlewareDispatcher; use OC\AppFramework\Utility\ControllerMethodReflector; +use OC\DB\Connection; use OCP\AppFramework\Controller; use OCP\AppFramework\Http\DataResponse; use OCP\AppFramework\Http\Response; +use OCP\Diagnostics\IQueryLogger; +use OCP\IConfig; +use OCP\IDBConnection; use OCP\IRequest; +use Psr\Log\LoggerInterface; /** * Class to dispatch the request to the middleware dispatcher @@ -58,6 +63,15 @@ class Dispatcher { /** @var IRequest */ private $request; + /** @var IConfig */ + private $config; + + /** @var IDBConnection|Connection */ + private $connection; + + /** @var LoggerInterface */ + private $logger; + /** * @param Http $protocol the http protocol with contains all status headers * @param MiddlewareDispatcher $middlewareDispatcher the dispatcher which @@ -65,15 +79,24 @@ class Dispatcher { * @param ControllerMethodReflector $reflector the reflector that is used to inject * the arguments for the controller * @param IRequest $request the incoming request + * @param IConfig $config + * @param IDBConnection $connection + * @param LoggerInterface $logger */ public function __construct(Http $protocol, MiddlewareDispatcher $middlewareDispatcher, ControllerMethodReflector $reflector, - IRequest $request) { + IRequest $request, + IConfig $config, + IDBConnection $connection, + LoggerInterface $logger) { $this->protocol = $protocol; $this->middlewareDispatcher = $middlewareDispatcher; $this->reflector = $reflector; $this->request = $request; + $this->config = $config; + $this->connection = $connection; + $this->logger = $logger; } @@ -97,8 +120,36 @@ class Dispatcher { $this->middlewareDispatcher->beforeController($controller, $methodName); + + $databaseStatsBefore = []; + if ($this->config->getSystemValueBool('debug', false)) { + $databaseStatsBefore = $this->connection->getStats(); + } + $response = $this->executeController($controller, $methodName); + if (!empty($databaseStatsBefore)) { + $databaseStatsAfter = $this->connection->getStats(); + $numBuilt = $databaseStatsAfter['built'] - $databaseStatsBefore['built']; + $numExecuted = $databaseStatsAfter['executed'] - $databaseStatsBefore['executed']; + + if ($numBuilt > 50) { + $this->logger->debug('Controller {class}::{method} created {count} QueryBuilder objects, please check if they are created inside a loop by accident.' , [ + 'class' => (string) get_class($controller), + 'method' => $methodName, + 'count' => $numBuilt, + ]); + } + + if ($numExecuted > 100) { + $this->logger->warning('Controller {class}::{method} executed {count} queries.' , [ + 'class' => (string) get_class($controller), + 'method' => $methodName, + 'count' => $numExecuted, + ]); + } + } + // if an exception appears, the middleware checks if it can handle the // exception and creates a response. If no response is created, it is // assumed that theres no middleware who can handle it and the error is diff --git a/lib/private/DB/Connection.php b/lib/private/DB/Connection.php index c5766dcd7e..ba3e6aae5b 100644 --- a/lib/private/DB/Connection.php +++ b/lib/private/DB/Connection.php @@ -59,6 +59,12 @@ class Connection extends ReconnectWrapper implements IDBConnection { protected $lockedTable = null; + /** @var int */ + protected $queriesBuilt = 0; + + /** @var int */ + protected $queriesExecuted = 0; + public function connect() { try { return parent::connect(); @@ -68,12 +74,20 @@ class Connection extends ReconnectWrapper implements IDBConnection { } } + public function getStats(): array { + return [ + 'built' => $this->queriesBuilt, + 'executed' => $this->queriesExecuted, + ]; + } + /** * Returns a QueryBuilder for the connection. * * @return \OCP\DB\QueryBuilder\IQueryBuilder */ public function getQueryBuilder() { + $this->queriesBuilt++; return new QueryBuilder( $this, \OC::$server->getSystemConfig(), @@ -90,6 +104,7 @@ class Connection extends ReconnectWrapper implements IDBConnection { public function createQueryBuilder() { $backtrace = $this->getCallerBacktrace(); \OC::$server->getLogger()->debug('Doctrine QueryBuilder retrieved in {backtrace}', ['app' => 'core', 'backtrace' => $backtrace]); + $this->queriesBuilt++; return parent::createQueryBuilder(); } @@ -102,6 +117,7 @@ class Connection extends ReconnectWrapper implements IDBConnection { public function getExpressionBuilder() { $backtrace = $this->getCallerBacktrace(); \OC::$server->getLogger()->debug('Doctrine ExpressionBuilder retrieved in {backtrace}', ['app' => 'core', 'backtrace' => $backtrace]); + $this->queriesBuilt++; return parent::getExpressionBuilder(); } @@ -191,6 +207,7 @@ class Connection extends ReconnectWrapper implements IDBConnection { public function executeQuery($query, array $params = [], $types = [], QueryCacheProfile $qcp = null) { $query = $this->replaceTablePrefix($query); $query = $this->adapter->fixupStatement($query); + $this->queriesExecuted++; return parent::executeQuery($query, $params, $types, $qcp); } @@ -211,6 +228,7 @@ class Connection extends ReconnectWrapper implements IDBConnection { public function executeUpdate($query, array $params = [], array $types = []) { $query = $this->replaceTablePrefix($query); $query = $this->adapter->fixupStatement($query); + $this->queriesExecuted++; return parent::executeUpdate($query, $params, $types); } From 95a301ea570bfc724877530975297aad1e7536c8 Mon Sep 17 00:00:00 2001 From: Joas Schilling Date: Fri, 2 Oct 2020 10:37:18 +0200 Subject: [PATCH 2/2] Fix tests Signed-off-by: Joas Schilling --- lib/private/AppFramework/Http/Dispatcher.php | 2 - .../lib/AppFramework/Http/DispatcherTest.php | 55 ++++++++++++++++--- 2 files changed, 46 insertions(+), 11 deletions(-) diff --git a/lib/private/AppFramework/Http/Dispatcher.php b/lib/private/AppFramework/Http/Dispatcher.php index 930e18b032..4a05ecaead 100644 --- a/lib/private/AppFramework/Http/Dispatcher.php +++ b/lib/private/AppFramework/Http/Dispatcher.php @@ -35,12 +35,10 @@ namespace OC\AppFramework\Http; use OC\AppFramework\Http; use OC\AppFramework\Middleware\MiddlewareDispatcher; use OC\AppFramework\Utility\ControllerMethodReflector; - use OC\DB\Connection; use OCP\AppFramework\Controller; use OCP\AppFramework\Http\DataResponse; use OCP\AppFramework\Http\Response; -use OCP\Diagnostics\IQueryLogger; use OCP\IConfig; use OCP\IDBConnection; use OCP\IRequest; diff --git a/tests/lib/AppFramework/Http/DispatcherTest.php b/tests/lib/AppFramework/Http/DispatcherTest.php index c4c973aec9..e308e5f2b3 100644 --- a/tests/lib/AppFramework/Http/DispatcherTest.php +++ b/tests/lib/AppFramework/Http/DispatcherTest.php @@ -33,6 +33,9 @@ use OCP\AppFramework\Http\DataResponse; use OCP\AppFramework\Http\JSONResponse; use OCP\AppFramework\Http\Response; use OCP\IConfig; +use OCP\IRequest; +use PHPUnit\Framework\MockObject\MockObject; +use Psr\Log\LoggerInterface; class TestController extends Controller { /** @@ -72,7 +75,12 @@ class TestController extends Controller { } } - +/** + * Class DispatcherTest + * + * @package Test\AppFramework\Http + * @group DB + */ class DispatcherTest extends \Test\TestCase { /** @var MiddlewareDispatcher */ private $middlewareDispatcher; @@ -80,16 +88,24 @@ class DispatcherTest extends \Test\TestCase { private $dispatcher; private $controllerMethod; private $response; + /** @var IRequest|MockObject */ private $request; private $lastModified; private $etag; + /** @var Http|MockObject */ private $http; private $reflector; + /** @var IConfig|MockObject */ + private $config; + /** @var LoggerInterface|MockObject */ + private $logger; protected function setUp(): void { parent::setUp(); $this->controllerMethod = 'test'; + $this->config = $this->createMock(IConfig::class); + $this->logger = $this->createMock(LoggerInterface::class); $app = $this->getMockBuilder( 'OC\AppFramework\DependencyInjection\DIContainer') ->disableOriginalConstructor() @@ -99,7 +115,7 @@ class DispatcherTest extends \Test\TestCase { ->disableOriginalConstructor() ->getMock(); $this->http = $this->getMockBuilder( - '\OC\AppFramework\Http') + \OC\AppFramework\Http::class) ->disableOriginalConstructor() ->getMock(); @@ -124,7 +140,10 @@ class DispatcherTest extends \Test\TestCase { $this->http, $this->middlewareDispatcher, $this->reflector, - $this->request + $this->request, + $this->config, + \OC::$server->getDatabaseConnection(), + $this->logger ); $this->response = $this->createMock(Response::class); @@ -299,7 +318,10 @@ class DispatcherTest extends \Test\TestCase { ); $this->dispatcher = new Dispatcher( $this->http, $this->middlewareDispatcher, $this->reflector, - $this->request + $this->request, + $this->config, + \OC::$server->getDatabaseConnection(), + $this->logger ); $controller = new TestController('app', $this->request); @@ -330,7 +352,10 @@ class DispatcherTest extends \Test\TestCase { ); $this->dispatcher = new Dispatcher( $this->http, $this->middlewareDispatcher, $this->reflector, - $this->request + $this->request, + $this->config, + \OC::$server->getDatabaseConnection(), + $this->logger ); $controller = new TestController('app', $this->request); @@ -364,7 +389,10 @@ class DispatcherTest extends \Test\TestCase { ); $this->dispatcher = new Dispatcher( $this->http, $this->middlewareDispatcher, $this->reflector, - $this->request + $this->request, + $this->config, + \OC::$server->getDatabaseConnection(), + $this->logger ); $controller = new TestController('app', $this->request); @@ -397,7 +425,10 @@ class DispatcherTest extends \Test\TestCase { ); $this->dispatcher = new Dispatcher( $this->http, $this->middlewareDispatcher, $this->reflector, - $this->request + $this->request, + $this->config, + \OC::$server->getDatabaseConnection(), + $this->logger ); $controller = new TestController('app', $this->request); @@ -431,7 +462,10 @@ class DispatcherTest extends \Test\TestCase { ); $this->dispatcher = new Dispatcher( $this->http, $this->middlewareDispatcher, $this->reflector, - $this->request + $this->request, + $this->config, + \OC::$server->getDatabaseConnection(), + $this->logger ); $controller = new TestController('app', $this->request); @@ -467,7 +501,10 @@ class DispatcherTest extends \Test\TestCase { ); $this->dispatcher = new Dispatcher( $this->http, $this->middlewareDispatcher, $this->reflector, - $this->request + $this->request, + $this->config, + \OC::$server->getDatabaseConnection(), + $this->logger ); $controller = new TestController('app', $this->request);