Extremely slow to count files and folders in vault

Phlip · January 9, 2023, 9:31pm

Hi all,

starting point: I created a vault and added several thousand files and folders. To ensure all unsecured files have been added to the vault, I wanted to count the filed and folders contained in the vault (right click on main directory > properties). I wanted to compare that to the result when doing the same on the local, unsecured main directory.

issue: It does count, but so slow it is likely going to take several days to finish, i.e., this is not feasible. Without that comparison, I cannot trust the copy to be complete which renders it useless.

questions: Am I doing anything wrong? Is there a faster way to count files/folders in a vault?

Michael · January 10, 2023, 6:48pm

Hi. Which volume type?
Which OS?
Anything suspicious in the log file?

Tried to reproduce this on Windows 11 with FUSE (WinFSP) but can’t.

Created 10.000 text files, each round about 1 MB.
Copied them into a directory in vault on another HDD (no SSD): ~3 minutes to copy
Counted them via directory properties: ~5 seconds until count was complete

Phlip · January 10, 2023, 10:18pm

Hi Michael,

Thanks for taking the time to look into this.

Which volume type?

SSD
(I hope this is what you were asking for. If not, please give an example of what you are looking for.)

Which OS?

Windows 11, 64-Bit

Anything suspicious in the log file?

As I am not sure which one is the relevant log file as a few days have passed since I experienced the issue, I will reproduce the issue tomorrow, check the log file, and revert here.

On a separate note: I saw several posts in English and posted mine accordingly. However, if posting in German is preferred, do let me know.

Thanks.

Michael · January 10, 2023, 10:31pm

Nope, I meant the volume type you have configured in your app settings. Means the type of your virtual drive/filesystem. It’s either WebDAV or Dokany or FUSE. I recommend to use FUSE (WinFSP)
See here: Volume Types — Cryptomator 1.7.0 documentation
(Please ignore the information that FUSE is only for Mac/Linux. It’s outdated. FUSE is available for windows too via WinFSP)

Phlip · January 11, 2023, 6:53am

Just checked. I went with the default. It is configured as FUSE.

Michael · January 11, 2023, 7:14am

Ok then it’s something else. Some user reported issues with their used antivirus program. Which one do you use and does a temporary deactivation have any influence on the speed?

Phlip · January 11, 2023, 10:29am

I use Windows Defender. The issue occurred before and after the latest Windows update (last run this morning).

Following your message, I have rebooted the system, deactivated Windows Defender, started Cryptomator and tried counting files in the vault (selecting all files via Ctrl + A > right click on marked folders > properties).

The process starts but is still extremely slow. I stopped after 1 minute with only around 70 files/folders counted.

In the following, I share the part of the debug log which covers the time from enabling the debug mode to the first few folders counted.

10:56:18.392 [JavaFX Application Thread] DEBUG org.cryptomator.logging.DebugMode - Debug mode enabled
10:56:19.393 [App Scheduled Executor 02] DEBUG o.c.common.settings.SettingsProvider - Attempting to save settings to C:\Users\AA\AppData\Roaming\Cryptomator\settings.json
10:56:19.395 [App Scheduled Executor 02] INFO  o.c.common.settings.SettingsProvider - Settings saved to C:\Users\AA\AppData\Roaming\Cryptomator\settings.json
10:56:19.591 [JavaFX Application Thread] INFO  o.cryptomator.ui.fxapp.UpdateChecker - Current version: 1.6.17, lastest version: 1.6.17
10:56:20.434 [JavaFX Application Thread] DEBUG o.c.w.k.WindowsProtectedKeychainAccess - Attempting to load keychain from C:\Users\AA\AppData\Roaming\Cryptomator\keychain.json
10:56:20.435 [JavaFX Application Thread] INFO  o.c.w.k.WindowsProtectedKeychainAccess - Unable to load existing keychain file, creating new keychain.
10:56:21.454 [JavaFX Application Thread] DEBUG o.c.common.vaults.VaultStats - stop recording stats
10:56:21.455 [JavaFX Application Thread] DEBUG o.c.ui.fxapp.FxApplicationTerminator - Disabling sudden termination
10:56:21.456 [JavaFX Application Thread] DEBUG o.c.ui.fxapp.FxApplicationWindows - Start unlock workflow for CM_online
10:56:21.467 [JavaFX Application Thread] DEBUG o.cryptomator.common.CommonsModule - Starting App Background Thread 003
10:56:22.727 [JavaFX Application Thread] TRACE o.c.u.k.m.PassphraseEntryController - UnlockController.unlock()
10:56:22.954 [App Background Thread 003] DEBUG o.c.cryptofs.common.BackupHelper - Verified backup file: G:\My Drive\CM_online\masterkey.cryptomator.B4784045.bkup
10:56:22.960 [App Background Thread 003] DEBUG o.c.cryptofs.common.BackupHelper - Verified backup file: G:\My Drive\CM_online\vault.cryptomator.65192CC9.bkup
10:56:23.002 [App Background Thread 003] DEBUG o.cryptomator.cryptofs.ReadonlyFlag - Vault opened for read and write.
10:56:23.290 [JavaFX Application Thread] INFO  o.c.ui.unlock.UnlockWorkflow - Unlock of 'CM_online' succeeded.
10:56:23.291 [JavaFX Application Thread] DEBUG o.c.common.vaults.VaultStats - start recording stats
10:56:23.292 [fuseMount-0-main] TRACE o.c.frontend.fuse.ReadOnlyAdapter - statfs / (331989073920 / 490744049664)
10:56:23.295 [fuseMount-0-main] TRACE o.c.frontend.fuse.locks.LockManager - Creating ReadWriteLock for []
10:56:23.296 [fuseMount-0-main] TRACE o.c.f.fuse.locks.PathRLockImpl - Acquired read path lock for '[]'
10:56:23.297 [fuseMount-0-main] TRACE o.c.frontend.fuse.locks.LockManager - Creating ReadWriteLock for []
10:56:23.297 [fuseMount-0-main] TRACE o.c.f.fuse.locks.DataRLockImpl - Acquired read data lock for '[]'
10:56:23.302 [fuseMount-0-main] TRACE o.c.frontend.fuse.ReadOnlyAdapter - getattr / (lastModifiedTime: 2023-01-11T09:51:42.274Z, lastAccessTime: 2023-01-06T00:40:23.199Z, creationTime: 2023-01-06T00:01:09.374Z, isRegularFile: false, isDirectory: true, isSymbolicLink: false, isOther: false, size: 0, fileKey: null)
10:56:23.302 [fuseMount-0-main] TRACE o.c.f.fuse.locks.DataRLockImpl - Released read data lock for '[]'
10:56:23.302 [fuseMount-0-main] TRACE o.c.f.fuse.locks.PathRLockImpl - Released read path lock for '[]'
10:56:23.315 [JavaFX Application Thread] DEBUG o.cryptomator.common.CommonsModule - Starting App Background Thread 004
10:56:24.040 [JavaFX Application Thread] TRACE o.c.u.unlock.UnlockSuccessController - UnlockSuccessController.revealAndClose()
10:56:24.041 [JavaFX Application Thread] DEBUG o.cryptomator.common.CommonsModule - Starting App Background Thread 005
10:56:24.136 [Thread-14] TRACE o.c.f.fuse.locks.PathRLockImpl - Acquired read path lock for '[]'
10:56:24.136 [Thread-14] TRACE o.c.f.fuse.locks.DataRLockImpl - Acquired read data lock for '[]'
10:56:24.137 [Thread-14] TRACE o.c.frontend.fuse.ReadOnlyAdapter - getattr / (lastModifiedTime: 2023-01-11T09:51:42.274Z, lastAccessTime: 2023-01-06T00:40:23.199Z, creationTime: 2023-01-06T00:01:09.374Z, isRegularFile: false, isDirectory: true, isSymbolicLink: false, isOther: false, size: 0, fileKey: null)
10:56:24.137 [Thread-14] TRACE o.c.f.fuse.locks.DataRLockImpl - Released read data lock for '[]'
10:56:24.138 [Thread-14] TRACE o.c.f.fuse.locks.PathRLockImpl - Released read path lock for '[]'
10:56:24.138 [Thread-15] TRACE o.c.f.fuse.locks.PathRLockImpl - Acquired read path lock for '[]'
10:56:24.138 [Thread-15] TRACE o.c.f.fuse.locks.DataRLockImpl - Acquired read data lock for '[]'
10:56:24.139 [Thread-15] TRACE o.c.frontend.fuse.ReadOnlyAdapter - getattr / (lastModifiedTime: 2023-01-11T09:51:42.274Z, lastAccessTime: 2023-01-06T00:40:23.199Z, creationTime: 2023-01-06T00:01:09.374Z, isRegularFile: false, isDirectory: true, isSymbolicLink: false, isOther: false, size: 0, fileKey: null)
10:56:24.140 [Thread-15] TRACE o.c.f.fuse.locks.DataRLockImpl - Released read data lock for '[]'
10:56:24.140 [Thread-15] TRACE o.c.f.fuse.locks.PathRLockImpl - Released read path lock for '[]'
10:56:24.146 [Thread-16] TRACE o.c.frontend.fuse.ReadOnlyAdapter - statfs / (331988951040 / 490744049664)
10:56:24.263 [Thread-17] TRACE o.c.frontend.fuse.locks.LockManager - Deleting ReadWriteLock for []
10:56:24.264 [Thread-17] TRACE o.c.frontend.fuse.locks.LockManager - Creating ReadWriteLock for []
10:56:24.264 [Thread-17] TRACE o.c.f.fuse.locks.PathRLockImpl - Acquired read path lock for '[]'
10:56:24.264 [Thread-18] TRACE o.c.frontend.fuse.locks.LockManager - Creating ReadWriteLock for [, desktop.ini]
10:56:24.264 [Thread-17] TRACE o.c.frontend.fuse.locks.LockManager - Deleting ReadWriteLock for []
10:56:24.264 [Thread-17] TRACE o.c.frontend.fuse.locks.LockManager - Creating ReadWriteLock for []
10:56:24.264 [Thread-18] TRACE o.c.f.fuse.locks.PathRLockImpl - Acquired read path lock for '[]'
10:56:24.264 [Thread-17] TRACE o.c.f.fuse.locks.DataRLockImpl - Acquired read data lock for '[]'
10:56:24.264 [Thread-18] TRACE o.c.f.fuse.locks.PathRLockImpl - Acquired read path lock for '[, desktop.ini]'
10:56:24.264 [Thread-18] TRACE o.c.frontend.fuse.locks.LockManager - Creating ReadWriteLock for [, desktop.ini]
10:56:24.264 [Thread-18] TRACE o.c.f.fuse.locks.DataRLockImpl - Acquired read data lock for '[, desktop.ini]'
10:56:24.265 [Thread-17] TRACE o.c.frontend.fuse.ReadOnlyAdapter - getattr / (lastModifiedTime: 2023-01-11T09:51:42.274Z, lastAccessTime: 2023-01-06T00:40:23.199Z, creationTime: 2023-01-06T00:01:09.374Z, isRegularFile: false, isDirectory: true, isSymbolicLink: false, isOther: false, size: 0, fileKey: null)
10:56:24.265 [Thread-17] TRACE o.c.f.fuse.locks.DataRLockImpl - Released read data lock for '[]'
10:56:24.265 [Thread-17] TRACE o.c.f.fuse.locks.PathRLockImpl - Released read path lock for '[]'
10:56:24.266 [Thread-19] TRACE o.c.f.fuse.locks.PathRLockImpl - Acquired read path lock for '[]'
10:56:24.266 [Thread-19] TRACE o.c.f.fuse.locks.DataRLockImpl - Acquired read data lock for '[]'
10:56:24.267 [Thread-19] TRACE o.c.frontend.fuse.ReadOnlyAdapter - getattr / (lastModifiedTime: 2023-01-11T09:51:42.274Z, lastAccessTime: 2023-01-06T00:40:23.199Z, creationTime: 2023-01-06T00:01:09.374Z, isRegularFile: false, isDirectory: true, isSymbolicLink: false, isOther: false, size: 0, fileKey: null)
10:56:24.267 [Thread-19] TRACE o.c.f.fuse.locks.DataRLockImpl - Released read data lock for '[]'
10:56:24.267 [Thread-19] TRACE o.c.f.fuse.locks.PathRLockImpl - Released read path lock for '[]'
10:56:24.268 [Thread-18] TRACE o.c.f.fuse.locks.DataRLockImpl - Released read data lock for '[, desktop.ini]'
10:56:24.268 [Thread-18] TRACE o.c.f.fuse.locks.PathRLockImpl - Released read path lock for '[, desktop.ini]'
10:56:24.268 [Thread-18] TRACE o.c.f.fuse.locks.PathRLockImpl - Released read path lock for '[]'
10:56:24.268 [Thread-20] TRACE o.c.f.fuse.locks.PathRLockImpl - Acquired read path lock for '[]'
10:56:24.268 [Thread-18] TRACE o.c.frontend.fuse.ReadOnlyAdapter - getattr /desktop.ini failed, node not found
10:56:24.268 [Thread-20] TRACE o.c.f.fuse.locks.DataRLockImpl - Acquired read data lock for '[]'
10:56:24.269 [Thread-20] TRACE o.c.frontend.fuse.ReadOnlyAdapter - getattr / (lastModifiedTime: 2023-01-11T09:51:42.274Z, lastAccessTime: 2023-01-06T00:40:23.199Z, creationTime: 2023-01-06T00:01:09.374Z, isRegularFile: false, isDirectory: true, isSymbolicLink: false, isOther: false, size: 0, fileKey: null)
10:56:24.269 [Thread-20] TRACE o.c.f.fuse.locks.DataRLockImpl - Released read data lock for '[]'
10:56:24.269 [Thread-20] TRACE o.c.f.fuse.locks.PathRLockImpl - Released read path lock for '[]'
10:56:24.270 [Thread-21] TRACE o.c.f.fuse.locks.PathRLockImpl - Acquired read path lock for '[]'
10:56:24.270 [Thread-21] TRACE o.c.f.fuse.locks.DataRLockImpl - Acquired read data lock for '[]'
10:56:24.270 [Thread-21] TRACE o.c.frontend.fuse.ReadOnlyAdapter - getattr / (lastModifiedTime: 2023-01-11T09:51:42.274Z, lastAccessTime: 2023-01-06T00:40:23.199Z, creationTime: 2023-01-06T00:01:09.374Z, isRegularFile: false, isDirectory: true, isSymbolicLink: false, isOther: false, size: 0, fileKey: null)
10:56:24.270 [Thread-21] TRACE o.c.f.fuse.locks.DataRLockImpl - Released read data lock for '[]'
10:56:24.271 [Thread-21] TRACE o.c.f.fuse.locks.PathRLockImpl - Released read path lock for '[]'
10:56:24.271 [Thread-22] TRACE o.c.f.fuse.locks.PathRLockImpl - Acquired read path lock for '[]'
10:56:24.271 [Thread-22] TRACE o.c.f.fuse.locks.DataRLockImpl - Acquired read data lock for '[]'
10:56:24.272 [Thread-22] TRACE o.c.frontend.fuse.ReadOnlyAdapter - getattr / (lastModifiedTime: 2023-01-11T09:51:42.274Z, lastAccessTime: 2023-01-06T00:40:23.199Z, creationTime: 2023-01-06T00:01:09.374Z, isRegularFile: false, isDirectory: true, isSymbolicLink: false, isOther: false, size: 0, fileKey: null)
10:56:24.272 [Thread-22] TRACE o.c.f.fuse.locks.DataRLockImpl - Released read data lock for '[]'
10:56:24.272 [Thread-22] TRACE o.c.f.fuse.locks.PathRLockImpl - Released read path lock for '[]'
10:56:24.272 [Thread-23] TRACE o.c.f.fuse.locks.PathRLockImpl - Acquired read path lock for '[]'
10:56:24.272 [Thread-23] TRACE o.c.f.fuse.locks.DataRLockImpl - Acquired read data lock for '[]'
10:56:24.273 [Thread-23] TRACE o.c.frontend.fuse.ReadOnlyAdapter - getattr / (lastModifiedTime: 2023-01-11T09:51:42.274Z, lastAccessTime: 2023-01-06T00:40:23.199Z, creationTime: 2023-01-06T00:01:09.374Z, isRegularFile: false, isDirectory: true, isSymbolicLink: false, isOther: false, size: 0, fileKey: null)
10:56:24.273 [Thread-23] TRACE o.c.f.fuse.locks.DataRLockImpl - Released read data lock for '[]'
10:56:24.273 [Thread-23] TRACE o.c.f.fuse.locks.PathRLockImpl - Released read path lock for '[]'
10:56:24.279 [Thread-24] TRACE o.c.f.fuse.locks.PathRLockImpl - Acquired read path lock for '[]'
10:56:24.279 [Thread-24] TRACE o.c.f.fuse.locks.DataRLockImpl - Acquired read data lock for '[]'
10:56:24.280 [Thread-24] TRACE o.c.frontend.fuse.ReadOnlyAdapter - getattr / (lastModifiedTime: 2023-01-11T09:51:42.274Z, lastAccessTime: 2023-01-06T00:40:23.199Z, creationTime: 2023-01-06T00:01:09.374Z, isRegularFile: false, isDirectory: true, isSymbolicLink: false, isOther: false, size: 0, fileKey: null)
10:56:24.280 [Thread-24] TRACE o.c.f.fuse.locks.DataRLockImpl - Released read data lock for '[]'
10:56:24.280 [Thread-24] TRACE o.c.f.fuse.locks.PathRLockImpl - Released read path lock for '[]'
10:56:24.280 [Thread-25] TRACE o.c.f.fuse.locks.PathRLockImpl - Acquired read path lock for '[]'
10:56:24.281 [Thread-25] TRACE o.c.f.fuse.locks.DataRLockImpl - Acquired read data lock for '[]'
10:56:24.281 [Thread-25] TRACE o.c.frontend.fuse.ReadOnlyAdapter - getattr / (lastModifiedTime: 2023-01-11T09:51:42.274Z, lastAccessTime: 2023-01-06T00:40:23.199Z, creationTime: 2023-01-06T00:01:09.374Z, isRegularFile: false, isDirectory: true, isSymbolicLink: false, isOther: false, size: 0, fileKey: null)
10:56:24.281 [Thread-25] TRACE o.c.f.fuse.locks.DataRLockImpl - Released read data lock for '[]'
10:56:24.281 [Thread-25] TRACE o.c.f.fuse.locks.PathRLockImpl - Released read path lock for '[]'
10:56:24.285 [Thread-26] TRACE o.c.f.fuse.locks.PathRLockImpl - Acquired read path lock for '[]'
10:56:24.285 [Thread-26] TRACE o.c.f.fuse.locks.DataRLockImpl - Acquired read data lock for '[]'
10:56:24.285 [Thread-26] TRACE o.c.frontend.fuse.ReadOnlyAdapter - readdir /
10:56:24.289 [Thread-26] TRACE o.c.c.dir.CryptoDirectoryStream - OPEN 
10:56:24.316 [JavaFX Application Thread] DEBUG o.cryptomator.common.CommonsModule - Starting App Background Thread 006
10:56:24.350 [Thread-26] TRACE o.c.c.dir.CryptoDirectoryStream - CLOSE 
10:56:24.351 [Thread-26] TRACE o.c.f.fuse.locks.DataRLockImpl - Released read data lock for '[]'
10:56:24.351 [Thread-26] TRACE o.c.f.fuse.locks.PathRLockImpl - Released read path lock for '[]'
10:56:24.351 [Thread-28] TRACE o.c.frontend.fuse.locks.LockManager - Creating ReadWriteLock for [, Folder_A]
10:56:24.351 [Thread-28] TRACE o.c.f.fuse.locks.PathRLockImpl - Acquired read path lock for '[]'
10:56:24.351 [Thread-28] TRACE o.c.f.fuse.locks.PathRLockImpl - Acquired read path lock for '[, Folder_A]'
10:56:24.351 [Thread-28] TRACE o.c.frontend.fuse.locks.LockManager - Creating ReadWriteLock for [, Folder_A]
10:56:24.351 [Thread-28] TRACE o.c.f.fuse.locks.DataRLockImpl - Acquired read data lock for '[, Folder_A]'
10:56:24.355 [Thread-28] TRACE o.c.frontend.fuse.ReadOnlyAdapter - getattr /Folder_A (lastModifiedTime: 2023-01-09T21:47:56.601Z, lastAccessTime: 2023-01-09T21:47:01.313Z, creationTime: 2023-01-09T21:47:01.313Z, isRegularFile: false, isDirectory: true, isSymbolicLink: false, isOther: false, size: 0, fileKey: null)
10:56:24.355 [Thread-28] TRACE o.c.f.fuse.locks.DataRLockImpl - Released read data lock for '[, Folder_A]'
10:56:24.355 [Thread-28] TRACE o.c.f.fuse.locks.PathRLockImpl - Released read path lock for '[, Folder_A]'
10:56:24.355 [Thread-28] TRACE o.c.f.fuse.locks.PathRLockImpl - Released read path lock for '[]'

I’m not familiar with analyzing such log files and did not find anything unusual except for this node not found item:

10:56:24.268 [Thread-18] TRACE o.c.frontend.fuse.ReadOnlyAdapter - getattr /desktop.ini failed, node not found

tobihagemann · January 11, 2023, 10:50am

Regarding performance problems with WinFsp, we’re still evaluating if it’s useful to add a mount flag.

What you can try is marking the volume as a network drive by going into “Vault Options” and adding a custom mount flag saying -oVolumePrefix=/Cryptomator/YourVaultName. Does that have any effect?

Michael · January 11, 2023, 11:27am

Mhm, me too. So this isn’t a hint also.
Let’s see if @tobihagemann suggestion is solving this.

Phlip · January 11, 2023, 12:02pm

@tobihagemann I see the custom mount flag taking effect as the volume name looks different MyFoldersName followed by (\\Cryptomator) (D:) but the problem persists, i.e., counting of files/folders remains slow.