Merge pull request #36643 from nextcloud/fs-setup-instrimuntion

more filesystem setup performance instrumentation

5 files changed, 76 insertions, 28 deletions

diff --git a/lib/private/Files/Config/MountProviderCollection.php b/lib/private/Files/Config/MountProviderCollection.php
index 0e08d9d0e83..ae6481e45bb 100644
--- a/lib/private/Files/Config/MountProviderCollection.php
+++ b/lib/private/Files/Config/MountProviderCollection.php
@@ -26,6 +26,7 @@ namespace OC\Files\Config;
 
 use OC\Hooks\Emitter;
 use OC\Hooks\EmitterTrait;
+use OCP\Diagnostics\IEventLogger;
 use OCP\Files\Config\IHomeMountProvider;
 use OCP\Files\Config\IMountProvider;
 use OCP\Files\Config\IMountProviderCollection;
@@ -65,13 +66,29 @@ class MountProviderCollection implements IMountProviderCollection, Emitter {
 	/** @var callable[] */
 	private $mountFilters = [];
 
+	private IEventLogger $eventLogger;
+
 	/**
 	 * @param \OCP\Files\Storage\IStorageFactory $loader
 	 * @param IUserMountCache $mountCache
 	 */
-	public function __construct(IStorageFactory $loader, IUserMountCache $mountCache) {
+	public function __construct(
+		IStorageFactory $loader,
+		IUserMountCache $mountCache,
+		IEventLogger $eventLogger
+	) {
 		$this->loader = $loader;
 		$this->mountCache = $mountCache;
+		$this->eventLogger = $eventLogger;
+	}
+
+	private function getMountsFromProvider(IMountProvider $provider, IUser $user, IStorageFactory $loader): array {
+		$class = str_replace('\\', '_', get_class($provider));
+		$uid = $user->getUID();
+		$this->eventLogger->start('fs:setup:provider:' . $class, "Getting mounts from $class for $uid");
+		$mounts = $provider->getMountsForUser($user, $loader) ?? [];
+		$this->eventLogger->end('fs:setup:provider:' . $class);
+		return $mounts;
 	}
 
 	/**
@@ -82,11 +99,8 @@ class MountProviderCollection implements IMountProviderCollection, Emitter {
 	private function getUserMountsForProviders(IUser $user, array $providers): array {
 		$loader = $this->loader;
 		$mounts = array_map(function (IMountProvider $provider) use ($user, $loader) {
-			return $provider->getMountsForUser($user, $loader);
+			return $this->getMountsFromProvider($provider, $user, $loader);
 		}, $providers);
-		$mounts = array_filter($mounts, function ($result) {
-			return is_array($result);
-		});
 		$mounts = array_reduce($mounts, function (array $mounts, array $providerMounts) {
 			return array_merge($mounts, $providerMounts);
 		}, []);
@@ -121,24 +135,22 @@ class MountProviderCollection implements IMountProviderCollection, Emitter {
 			return (get_class($provider) === 'OCA\Files_Sharing\MountProvider');
 		});
 		foreach ($firstProviders as $provider) {
-			$mounts = $provider->getMountsForUser($user, $this->loader);
-			if (is_array($mounts)) {
-				$firstMounts = array_merge($firstMounts, $mounts);
-			}
+			$mounts = $this->getMountsFromProvider($provider, $user, $this->loader);
+			$firstMounts = array_merge($firstMounts, $mounts);
 		}
 		$firstMounts = $this->filterMounts($user, $firstMounts);
 		array_walk($firstMounts, [$mountManager, 'addMount']);
 
 		$lateMounts = [];
 		foreach ($lastProviders as $provider) {
-			$mounts = $provider->getMountsForUser($user, $this->loader);
-			if (is_array($mounts)) {
-				$lateMounts = array_merge($lateMounts, $mounts);
-			}
+			$mounts = $this->getMountsFromProvider($provider, $user, $this->loader);
+			$lateMounts = array_merge($lateMounts, $mounts);
 		}
 
 		$lateMounts = $this->filterMounts($user, $lateMounts);
+		$this->eventLogger->start("fs:setup:add-mounts", "Add mounts to the filesystem");
 		array_walk($lateMounts, [$mountManager, 'addMount']);
+		$this->eventLogger->end("fs:setup:add-mounts");
 
 		return array_merge($lateMounts, $firstMounts);
 	}
diff --git a/lib/private/Files/Config/UserMountCache.php b/lib/private/Files/Config/UserMountCache.php
index 3540b563742..fe677c5ea52 100644
--- a/lib/private/Files/Config/UserMountCache.php
+++ b/lib/private/Files/Config/UserMountCache.php
@@ -31,6 +31,7 @@ namespace OC\Files\Config;
 use OCP\Cache\CappedMemoryCache;
 use OCA\Files_Sharing\SharedMount;
 use OCP\DB\QueryBuilder\IQueryBuilder;
+use OCP\Diagnostics\IEventLogger;
 use OCP\Files\Config\ICachedMountFileInfo;
 use OCP\Files\Config\ICachedMountInfo;
 use OCP\Files\Config\IUserMountCache;
@@ -56,19 +57,27 @@ class UserMountCache implements IUserMountCache {
 	private LoggerInterface $logger;
 	/** @var CappedMemoryCache<array> */
 	private CappedMemoryCache $cacheInfoCache;
+	private IEventLogger $eventLogger;
 
 	/**
 	 * UserMountCache constructor.
 	 */
-	public function __construct(IDBConnection $connection, IUserManager $userManager, LoggerInterface $logger) {
+	public function __construct(
+		IDBConnection $connection,
+		IUserManager $userManager,
+		LoggerInterface $logger,
+		IEventLogger $eventLogger
+	) {
 		$this->connection = $connection;
 		$this->userManager = $userManager;
 		$this->logger = $logger;
+		$this->eventLogger = $eventLogger;
 		$this->cacheInfoCache = new CappedMemoryCache();
 		$this->mountsForUsers = new CappedMemoryCache();
 	}
 
 	public function registerMounts(IUser $user, array $mounts, array $mountProviderClasses = null) {
+		$this->eventLogger->start('fs:setup:user:register', 'Registering mounts for user');
 		// filter out non-proper storages coming from unit tests
 		$mounts = array_filter($mounts, function (IMountPoint $mount) {
 			return $mount instanceof SharedMount || ($mount->getStorage() && $mount->getStorage()->getCache());
@@ -134,6 +143,7 @@ class UserMountCache implements IUserMountCache {
 		foreach ($changedMounts as $mount) {
 			$this->updateCachedMount($mount);
 		}
+		$this->eventLogger->end('fs:setup:user:register');
 	}
 
 	/**
diff --git a/lib/private/Files/SetupManager.php b/lib/private/Files/SetupManager.php
index 979e4ce966a..4cbd0328d76 100644
--- a/lib/private/Files/SetupManager.php
+++ b/lib/private/Files/SetupManager.php
@@ -212,6 +212,8 @@ class SetupManager {
 		}
 		$this->setupUsersComplete[] = $user->getUID();
 
+		$this->eventLogger->start('fs:setup:user:full', 'Setup full filesystem for user');
+
 		if (!isset($this->setupUserMountProviders[$user->getUID()])) {
 			$this->setupUserMountProviders[$user->getUID()] = [];
 		}
@@ -226,6 +228,7 @@ class SetupManager {
 			});
 		});
 		$this->afterUserFullySetup($user, $previouslySetupProviders);
+		$this->eventLogger->end('fs:setup:user:full');
 	}
 
 	/**
@@ -237,6 +240,8 @@ class SetupManager {
 		}
 		$this->setupUsers[] = $user->getUID();
 
+		$this->eventLogger->start('fs:setup:user:onetime', 'Onetime filesystem for user');
+
 		$this->setupBuiltinWrappers();
 
 		$prevLogging = Filesystem::logWarningWhenAddingStorageWrapper(false);
@@ -250,14 +255,18 @@ class SetupManager {
 		Filesystem::initInternal($userDir);
 
 		if ($this->lockdownManager->canAccessFilesystem()) {
+			$this->eventLogger->start('fs:setup:user:home', 'Setup home filesystem for user');
 			// home mounts are handled separate since we need to ensure this is mounted before we call the other mount providers
 			$homeMount = $this->mountProviderCollection->getHomeMountForUser($user);
 			$this->mountManager->addMount($homeMount);
 
 			if ($homeMount->getStorageRootId() === -1) {
+				$this->eventLogger->start('fs:setup:user:home:scan', 'Scan home filesystem for user');
 				$homeMount->getStorage()->mkdir('');
 				$homeMount->getStorage()->getScanner()->scan('');
+				$this->eventLogger->end('fs:setup:user:home:scan');
 			}
+			$this->eventLogger->end('fs:setup:user:home');
 		} else {
 			$this->mountManager->addMount(new MountPoint(
 				new NullStorage([]),
@@ -271,12 +280,15 @@ class SetupManager {
 		}
 
 		$this->listenForNewMountProviders();
+
+		$this->eventLogger->end('fs:setup:user:onetime');
 	}
 
 	/**
 	 * Final housekeeping after a user has been fully setup
 	 */
 	private function afterUserFullySetup(IUser $user, array $previouslySetupProviders): void {
+		$this->eventLogger->start('fs:setup:user:full:post', 'Housekeeping after user is setup');
 		$userRoot = '/' . $user->getUID() . '/';
 		$mounts = $this->mountManager->getAll();
 		$mounts = array_filter($mounts, function (IMountPoint $mount) use ($userRoot) {
@@ -296,6 +308,7 @@ class SetupManager {
 			$this->cache->set($user->getUID(), true, $cacheDuration);
 			$this->fullSetupRequired[$user->getUID()] = false;
 		}
+		$this->eventLogger->end('fs:setup:user:full:post');
 	}
 
 	/**
@@ -312,17 +325,17 @@ class SetupManager {
 			$this->oneTimeUserSetup($user);
 		}
 
-		$this->eventLogger->start('setup_fs', 'Setup filesystem');
-
 		if ($this->lockdownManager->canAccessFilesystem()) {
 			$mountCallback();
 		}
+		$this->eventLogger->start('fs:setup:user:post-init-mountpoint', 'post_initMountPoints legacy hook');
 		\OC_Hook::emit('OC_Filesystem', 'post_initMountPoints', ['user' => $user->getUID()]);
+		$this->eventLogger->end('fs:setup:user:post-init-mountpoint');
 
 		$userDir = '/' . $user->getUID() . '/files';
+		$this->eventLogger->start('fs:setup:user:setup-hook', 'setup legacy hook');
 		OC_Hook::emit('OC_Filesystem', 'setup', ['user' => $user->getUID(), 'user_dir' => $userDir]);
-
-		$this->eventLogger->end('setup_fs');
+		$this->eventLogger->end('fs:setup:user:setup-hook');
 	}
 
 	/**
@@ -335,7 +348,7 @@ class SetupManager {
 		}
 		$this->rootSetup = true;
 
-		$this->eventLogger->start('setup_root_fs', 'Setup root filesystem');
+		$this->eventLogger->start('fs:setup:root', 'Setup root filesystem');
 
 		$this->setupBuiltinWrappers();
 
@@ -344,7 +357,7 @@ class SetupManager {
 			$this->mountManager->addMount($rootMountProvider);
 		}
 
-		$this->eventLogger->end('setup_root_fs');
+		$this->eventLogger->end('fs:setup:root');
 	}
 
 	/**
@@ -413,6 +426,9 @@ class SetupManager {
 			$this->oneTimeUserSetup($user);
 		}
 
+		$this->eventLogger->start('fs:setup:user:path', "Setup $path filesystem for user");
+		$this->eventLogger->start('fs:setup:user:path:find', "Find mountpoint for $path");
+
 		$mounts = [];
 		if (!in_array($cachedMount->getMountProvider(), $setupProviders)) {
 			$currentProviders[] = $cachedMount->getMountProvider();
@@ -421,13 +437,16 @@ class SetupManager {
 				$mounts = $this->mountProviderCollection->getUserMountsForProviderClasses($user, [$cachedMount->getMountProvider()]);
 			} else {
 				$this->logger->debug("mount at " . $cachedMount->getMountPoint() . " has no provider set, performing full setup");
+				$this->eventLogger->end('fs:setup:user:path:find');
 				$this->setupForUser($user);
+				$this->eventLogger->end('fs:setup:user:path');
 				return;
 			}
 		}
 
 		if ($includeChildren) {
 			$subCachedMounts = $this->userMountCache->getMountsInPath($user, $path);
+			$this->eventLogger->end('fs:setup:user:path:find');
 
 			$needsFullSetup = array_reduce($subCachedMounts, function (bool $needsFullSetup, ICachedMountInfo $cachedMountInfo) {
 				return $needsFullSetup || $cachedMountInfo->getMountProvider() === '';
@@ -436,6 +455,7 @@ class SetupManager {
 			if ($needsFullSetup) {
 				$this->logger->debug("mount has no provider set, performing full setup");
 				$this->setupForUser($user);
+				$this->eventLogger->end('fs:setup:user:path');
 				return;
 			} else {
 				foreach ($subCachedMounts as $cachedMount) {
@@ -446,6 +466,8 @@ class SetupManager {
 					}
 				}
 			}
+		} else {
+			$this->eventLogger->end('fs:setup:user:path:find');
 		}
 
 		if (count($mounts)) {
@@ -456,6 +478,7 @@ class SetupManager {
 		} elseif (!$this->isSetupStarted($user)) {
 			$this->oneTimeUserSetup($user);
 		}
+		$this->eventLogger->end('fs:setup:user:path');
 	}
 
 	private function fullSetupRequired(IUser $user): bool {
@@ -488,6 +511,8 @@ class SetupManager {
 			return;
 		}
 
+		$this->eventLogger->start('fs:setup:user:providers', "Setup filesystem for " . implode(', ', $providers));
+
 		// home providers are always used
 		$providers = array_filter($providers, function (string $provider) {
 			return !is_subclass_of($provider, IHomeMountProvider::class);
@@ -504,6 +529,7 @@ class SetupManager {
 			if (!$this->isSetupStarted($user)) {
 				$this->oneTimeUserSetup($user);
 			}
+			$this->eventLogger->end('fs:setup:user:providers');
 			return;
 		} else {
 			$this->setupUserMountProviders[$user->getUID()] = array_merge($setupProviders, $providers);
@@ -514,6 +540,7 @@ class SetupManager {
 		$this->setupForUserWith($user, function () use ($mounts) {
 			array_walk($mounts, [$this->mountManager, 'addMount']);
 		});
+		$this->eventLogger->end('fs:setup:user:providers');
 	}
 
 	public function tearDown() {
diff --git a/lib/private/Server.php b/lib/private/Server.php
index bd33cdf58bd..39947ebcabe 100644
--- a/lib/private/Server.php
+++ b/lib/private/Server.php
@@ -86,6 +86,7 @@ use OC\EventDispatcher\SymfonyAdapter;
 use OC\Federation\CloudFederationFactory;
 use OC\Federation\CloudFederationProviderManager;
 use OC\Federation\CloudIdManager;
+use OC\Files\Config\MountProviderCollection;
 use OC\Files\Config\UserMountCache;
 use OC\Files\Config\UserMountCacheListener;
 use OC\Files\Lock\LockManager;
@@ -946,11 +947,7 @@ class Server extends ServerContainer implements IServerContainer {
 		$this->registerDeprecatedAlias('DateTimeFormatter', IDateTimeFormatter::class);
 
 		$this->registerService(IUserMountCache::class, function (ContainerInterface $c) {
-			$mountCache = new UserMountCache(
-				$c->get(IDBConnection::class),
-				$c->get(IUserManager::class),
-				$c->get(LoggerInterface::class)
-			);
+			$mountCache = $c->get(UserMountCache::class);
 			$listener = new UserMountCacheListener($mountCache);
 			$listener->listen($c->get(IUserManager::class));
 			return $mountCache;
@@ -959,9 +956,10 @@ class Server extends ServerContainer implements IServerContainer {
 		$this->registerDeprecatedAlias('UserMountCache', IUserMountCache::class);
 
 		$this->registerService(IMountProviderCollection::class, function (ContainerInterface $c) {
-			$loader = \OC\Files\Filesystem::getLoader();
+			$loader = $c->get(IStorageFactory::class);
 			$mountCache = $c->get(IUserMountCache::class);
-			$manager = new \OC\Files\Config\MountProviderCollection($loader, $mountCache);
+			$eventLogger = $c->get(IEventLogger::class);
+			$manager = new MountProviderCollection($loader, $mountCache, $eventLogger);
 
 			// builtin providers
 
diff --git a/tests/lib/Files/Config/UserMountCacheTest.php b/tests/lib/Files/Config/UserMountCacheTest.php
index f1206781c5e..a9a88cb85c9 100644
--- a/tests/lib/Files/Config/UserMountCacheTest.php
+++ b/tests/lib/Files/Config/UserMountCacheTest.php
@@ -13,6 +13,7 @@ use OC\Files\Mount\MountPoint;
 use OC\Files\Storage\Storage;
 use OCP\Cache\CappedMemoryCache;
 use OC\User\Manager;
+use OCP\Diagnostics\IEventLogger;
 use OCP\EventDispatcher\IEventDispatcher;
 use OCP\Files\Config\ICachedMountInfo;
 use OCP\ICacheFactory;
@@ -67,7 +68,7 @@ class UserMountCacheTest extends TestCase {
 		$userBackend->createUser('u2', '');
 		$userBackend->createUser('u3', '');
 		$this->userManager->registerBackend($userBackend);
-		$this->cache = new \OC\Files\Config\UserMountCache($this->connection, $this->userManager, $this->createMock(LoggerInterface::class));
+		$this->cache = new \OC\Files\Config\UserMountCache($this->connection, $this->userManager, $this->createMock(LoggerInterface::class), $this->createMock(IEventLogger::class));
 	}
 
 	protected function tearDown(): void {