WebDAV unbearably slow with NC 24

ℹ️ Support
1

Nextcloud version (eg, 20.0.5): 24.0.0.12
Operating system and version (eg, Ubuntu 20.04): Alpine linux (in LXC container)
Apache or nginx version (eg, Apache 2.4.25): nginx 1.20.2-r2
PHP version (eg, 7.4): php8 8.0.19-r0

The issue you are facing:

WebDAV mounts are so slow it’s practically impossible to use them. Even changing into a mounted directory once mounted takes tens of seconds.

Is this the first time you’ve seen this error? (Y/N): N, but I haven’t had a real need for WebDAV access until now

Steps to replicate it:

  1. mount share via webdav
mount -t davfs https://HOST/remote.php/dav/files/jose/ mount_point
  1. cd mount_point
  2. list contents
time ls
  1. get output:
..
Executed in   51.49 secs      fish           external
   usr time    4.66 millis    1.58 millis    3.08 millis
   sys time    0.46 millis    0.46 millis    0.00 millis

No relevant information in the logs. Also a request run via CURL runs several times shower when compared to a similarly sized system.

time curl  -u user:pass -X PROPFIND http://HOST/remote.php/dav/files/jose/
..
Executed in    2.88 secs      fish           external
   usr time    0.41 millis  412.00 micros    0.00 millis
   sys time    3.28 millis    0.00 micros    3.28 millis

While the query is running I can see PHP-FPM process CPU usage goes up to 100 % for a few seconds. After enabling slow-log:

[20-May-2022 11:44:08]  [pool nextcloud] pid 4852
script_filename = /usr/share/webapps/nextcloud/remote.php
[0xb6816c30] password_verify() /usr/share/webapps/nextcloud/lib/private/Security/Hasher.php:153
[0xb6816bc0] verifyHash() /usr/share/webapps/nextcloud/lib/private/Security/Hasher.php:177
[0xb6816b30] verify() /usr/share/webapps/nextcloud/lib/private/User/Database.php:343
[0xb6816a90] checkPassword() /usr/share/webapps/nextcloud/lib/private/User/Manager.php:258
[0xb68169e0] checkPasswordNoLogging() /usr/share/webapps/nextcloud/lib/private/User/Session.php:607
[0xb6816970] loginWithPassword() /usr/share/webapps/nextcloud/lib/private/User/Session.php:355
[0xb6816910] login() /usr/share/webapps/nextcloud/lib/private/User/Session.php:450
[0xb6816830] logClientIn() /usr/share/webapps/nextcloud/apps/dav/lib/Connector/Sabre/Auth.php:129
[0xb68167c0] validateUserPass() /usr/share/webapps/nextcloud/3rdparty/sabre/dav/lib/DAV/Auth/Backend/AbstractBasic.php:103
[0xb6816710] check() /usr/share/webapps/nextcloud/apps/dav/lib/Connector/Sabre/Auth.php:251
[0xb6816650] auth() /usr/share/webapps/nextcloud/apps/dav/lib/Connector/Sabre/Auth.php:154
[0xb68165a0] check() /usr/share/webapps/nextcloud/3rdparty/sabre/dav/lib/DAV/Auth/Plugin.php:180
[0xb68164f0] check() /usr/share/webapps/nextcloud/3rdparty/sabre/dav/lib/DAV/Auth/Plugin.php:135
[0xb6816450] beforeMethod() /usr/share/webapps/nextcloud/3rdparty/sabre/event/lib/WildcardEmitterTrait.php:89
[0xb6816390] emit() /usr/share/webapps/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php:456
[0xb68162f0] invokeMethod() /usr/share/webapps/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php:253
[0xb6816210] start() /usr/share/webapps/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php:321
[0xb68161e0] exec() /usr/share/webapps/nextcloud/apps/dav/lib/Server.php:352
[0xb6816180] exec() /usr/share/webapps/nextcloud/apps/dav/appinfo/v2/remote.php:35
[0xb6816110] [INCLUDE_OR_EVAL]() /usr/share/webapps/nextcloud/remote.php:166

I’d say it has to do something with the user password validation but I have no idea how to dig in further. Any help is greatly appreciated.

Edit: added KCachegrind output (xdebug) - not sure if it’ll serve any purpose though

[Album] imgur.com
2

I was checking with strace on php-fpm processes and this bit seems a bit suspicious:

[pid 18069] 07:53:57.966895 fcntl64(6, F_SETFD, FD_CLOEXEC) = 0
[pid 18069] 07:53:57.966992 statx(6, "", AT_STATX_SYNC_AS_STAT|AT_EMPTY_PATH, STATX_BASIC_STATS, {stx_mask=STATX_ALL, stx_attributes=0, stx_mode=S_IFREG|0600, stx_size=0, ...}) = 0
[pid 18069] 07:53:57.967507 statx(AT_FDCWD, "/usr/share/webapps/nextcloud/lib/private/User/Backend.php", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, {stx_mask=STATX_ALL, stx_attributes=0, stx_mode=S_IFREG|0644, stx_size=4298, ...}) = 0
[pid 18069] 07:53:57.967931 mmap2(NULL, 67108884, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xa89ff000
[pid 18069] 07:54:00.632156 munmap(0xa89ff000, 67112960) = 0
[pid 18069] 07:54:00.647694 sendto(5, "Y\0\0\0\3SELECT `appid`, `configkey`"..., 93, MSG_DONTWAIT, NULL, 0) = 93
[pid 18069] 07:54:00.648401 poll([{fd=5, events=POLLIN|POLLERR|POLLHUP}], 1, 86400000) = 1 ([{fd=5, revents=POLLIN}])

There is a 2.5-second pause between mmap2 and munmap syscall which seems to be a lot.