more routing performance instrumentation

Signed-off-by: Robin Appelman <robin@icewind.nl>

Author: icewind1991

lib/private/AppFramework/App.php

@@ -34,7 +34,6 @@
 use OC\AppFramework\DependencyInjection\DIContainer;
 use OC\AppFramework\Http\Dispatcher;
 use OC\AppFramework\Http\Request;
-use OC\Diagnostics\EventLogger;
 use OCP\Profiler\IProfiler;
 use OC\Profiler\RoutingDataCollector;
 use OCP\AppFramework\QueryException;
@@ -43,7 +42,6 @@
 use OCP\AppFramework\Http\IOutput;
 use OCP\Diagnostics\IEventLogger;
 use OCP\HintException;
-use OCP\IConfig;
 use OCP\IRequest;
 
 /**
@@ -120,14 +118,16 @@ public static function getAppIdForClass(string $className, string $topNamespace
 	public static function main(string $controllerName, string $methodName, DIContainer $container, array $urlParams = null) {
 		/** @var IProfiler $profiler */
 		$profiler = $container->get(IProfiler::class);
-		$config = $container->get(IConfig::class);
+		$eventLogger = $container->get(IEventLogger::class);
 		// Disable profiler on the profiler UI
 		$profiler->setEnabled($profiler->isEnabled() && !is_null($urlParams) && isset($urlParams['_route']) && !str_starts_with($urlParams['_route'], 'profiler.'));
 		if ($profiler->isEnabled()) {
 			\OC::$server->get(IEventLogger::class)->activate();
 			$profiler->add(new RoutingDataCollector($container['AppName'], $controllerName, $methodName));
 		}
 
+		$eventLogger->start('app:controller:params', 'Gather controller parameters');
+
 		if (!is_null($urlParams)) {
 			/** @var Request $request */
 			$request = $container->get(IRequest::class);
@@ -139,6 +139,10 @@ public static function main(string $controllerName, string $methodName, DIContai
 		}
 		$appName = $container['AppName'];
 
+		$eventLogger->end('app:controller:params');
+
+		$eventLogger->start('app:controller:load', 'Load app controller');
+
 		// first try $controllerName then go for \OCA\AppName\Controller\$controllerName
 		try {
 			$controller = $container->get($controllerName);
@@ -158,10 +162,18 @@ public static function main(string $controllerName, string $methodName, DIContai
 			$controller = $container->query($controllerName);
 		}
 
+		$eventLogger->end('app:controller:load');
+
+		$eventLogger->start('app:controller:dispatcher', 'Initialize dispatcher and pre-middleware');
+
 		// initialize the dispatcher and run all the middleware before the controller
 		/** @var Dispatcher $dispatcher */
 		$dispatcher = $container['Dispatcher'];
 
+		$eventLogger->end('app:controller:dispatcher');
+
+		$eventLogger->start('app:controller:run', 'Run app controller');
+
 		[
 			$httpHeaders,
 			$responseHeaders,
@@ -170,11 +182,11 @@ public static function main(string $controllerName, string $methodName, DIContai
 			$response
 		] = $dispatcher->dispatch($controller, $methodName);
 
+		$eventLogger->end('app:controller:run');
+
 		$io = $container[IOutput::class];
 
 		if ($profiler->isEnabled()) {
-			/** @var EventLogger $eventLogger */
-			$eventLogger = $container->get(IEventLogger::class);
 			$eventLogger->end('runtime');
 			$profile = $profiler->collect($container->get(IRequest::class), $response);
 			$profiler->saveProfile($profile);

lib/private/Route/Router.php

@@ -34,6 +34,7 @@
 
 use OC\AppFramework\Routing\RouteParser;
 use OCP\AppFramework\App;
+use OCP\Diagnostics\IEventLogger;
 use OCP\Route\IRouter;
 use OCP\Util;
 use Psr\Log\LoggerInterface;
@@ -64,6 +65,7 @@ class Router implements IRouter {
 	protected LoggerInterface $logger;
 	/** @var RequestContext */
 	protected $context;
+	private IEventLogger $eventLogger;
 
 	public function __construct(LoggerInterface $logger) {
 		$this->logger = $logger;
@@ -82,6 +84,7 @@ public function __construct(LoggerInterface $logger) {
 		$this->context = new RequestContext($baseUrl, $method, $host, $schema);
 		// TODO cache
 		$this->root = $this->getCollection('root');
+		$this->eventLogger = \OC::$server->get(IEventLogger::class);
 	}
 
 	/**
@@ -134,7 +137,7 @@ public function loadRoutes($app = null) {
 				$routingFiles = [];
 			}
 		}
-		\OC::$server->getEventLogger()->start('loadroutes' . $requestedApp, 'Loading Routes');
+		$this->eventLogger->start('route:load:' . $requestedApp, 'Loading Routes for ' . $requestedApp);
 		foreach ($routingFiles as $app => $file) {
 			if (!isset($this->loadedApps[$app])) {
 				if (!\OC_App::isAppLoaded($app)) {
@@ -170,7 +173,7 @@ public function loadRoutes($app = null) {
 			$collection->addPrefix('/ocs');
 			$this->root->addCollection($collection);
 		}
-		\OC::$server->getEventLogger()->end('loadroutes' . $requestedApp);
+		$this->eventLogger->end('route:load:' . $requestedApp);
 	}
 
 	/**
@@ -231,6 +234,7 @@ public function create($name,
 	 * @return array
 	 */
 	public function findMatchingRoute(string $url): array {
+		$this->eventLogger->start('route:match', 'Match route');
 		if (substr($url, 0, 6) === '/apps/') {
 			// empty string / 'apps' / $app / rest of the route
 			[, , $app,] = explode('/', $url, 4);
@@ -276,6 +280,7 @@ public function findMatchingRoute(string $url): array {
 			}
 		}
 
+		$this->eventLogger->end('route:match');
 		return $parameters;
 	}
 
@@ -289,7 +294,7 @@ public function findMatchingRoute(string $url): array {
 	public function match($url) {
 		$parameters = $this->findMatchingRoute($url);
 
-		\OC::$server->getEventLogger()->start('run_route', 'Run route');
+		$this->eventLogger->start('route:run', 'Run route');
 		if (isset($parameters['caller'])) {
 			$caller = $parameters['caller'];
 			unset($parameters['caller']);
@@ -303,13 +308,15 @@ public function match($url) {
 			}
 			unset($parameters['action']);
 			unset($parameters['caller']);
+			$this->eventLogger->start('route:run:call', 'Run callable route');
 			call_user_func($action, $parameters);
+			$this->eventLogger->end('route:run:call');
 		} elseif (isset($parameters['file'])) {
 			include $parameters['file'];
 		} else {
 			throw new \Exception('no action available');
 		}
-		\OC::$server->getEventLogger()->end('run_route');
+		$this->eventLogger->end('route:run');
 	}
 
 	/**