Poor performance after server running for a few days

[Terrance]

I'm seeing certain requests taking durations into the minutes to complete. For example, loading my calendars in InfCloud:

Method	Path	Duration	Note
PROPFIND	/	16 ms
REPORT	/user/	11 ms
PROPFIND	/user/	13 ms	Reading server settings
PROPFIND	/user/	4.64 min	Reading calendar / address book list
REPORT	/user/1a518a80-23b6-abd1-cef8-f0e25e6063ef/	2.43 min	Reading events
PUT	/user/1a518a80-23b6-abd1-cef8-f0e25e6063ef/cca...892.ics	1.22 min	Creating an event

I've bumped my nginx proxy timeout to keep the requests working, though it makes things difficult to use with the long delays.

Performance seems to vary somewhat (e.g. give or take a few minutes for a scan of all collections) from day to day despite no obvious difference in server load. Restarting Radicale helps (e.g. reducing the scan time to about 30 seconds initially) for a day or two, but the slowness creeps back in after that.

I'm not sure if I'm at the point where my calendars are just too hefty to work with as files, or if there's another bottleneck here.

Debug log snippet: radicale-2023-02-26.log (NB. different day to the table)

Collection stats

For context, as I'm not sure what constitutes a "large" collection, here's some stats on the collection root (I'm the only user):

Collection	Type	# items	Total size
1a518a80-23b6-abd1-cef8-f0e25e6063ef	VCALENDAR	12836	651M
1fc7a94b-a1b1-bb0a-5e9e-c3756f597434	VCALENDAR	921	14M
260ceee4-135a-69a8-d36c-8bfe3937ed2a	VADDRESSBOOK	155	6.0M
29917d2c-60e7-0a32-178b-079c5bb33fe8	VCALENDAR	3060	46M
31f4fd59-7748-b1de-426c-ee1bee515ef4	VCALENDAR	3052	47M
4c899125-a332-8e3d-ce5b-6aabb3db886a	VCALENDAR	25	348K
513bbed6-56f0-cd92-4188-5c3c076745a5	VCALENDAR	167	2.3M
53f15099-79b5-d366-a91f-462bbc0435f5	VCALENDAR	8393	108M
68643525-214e-bc87-dd32-773f40887307	VCALENDAR	2848	70M
6c9d17e5-7012-f6c9-29c3-2d93898f0c0d	VCALENDAR	706	11M
883076b9-7570-78be-a719-bdd417592df5	VCALENDAR	6480	171M
9d9d7ce5-54f0-eae2-ef0f-704b6493b8f4	VCALENDAR	2	56K
a5797b88-7d73-9751-c7e7-2227c5a55f07	VADDRESSBOOK	75	2.3M
b31241e3-f303-9ffa-aca2-03734debda04	VADDRESSBOOK	49	2.6M
c730a9ad-243f-5bf3-1c14-580fc1f623ca	VCALENDAR	1194	20M
cb17d5b1-5693-4d59-4fdf-b8a62e705465	VCALENDAR	2445	57M
eb6cc48b-f577-609f-f929-56b6ddd37792	VCALENDAR	1287	28M

Totals: 43695 items, 1.2GB

Server: Radicale 3.1.8 on Arch Linux

[pbiering]

can you check your system regarding

• consumed memory of the process, e.g.

ps -F -C radicale

• system swap state, e.g.

free

• current load on the system

cat /proc/loadavg

• check system behavoir during long running calls

vmstat 1

[Terrance]

Initial stats (after a service restart and leaving it for a bit, just DAVx5 doing mobile syncing):

$ cat /proc/loadavg
0.04 0.11 0.96 1/484 4124315

$ free
               total        used        free      shared  buff/cache   available
Mem:         8038544     2372640     3151612      160288     2514292     5199280
Swap:              0           0           0

$ ps -F -C radicale
UID          PID    PPID  C    SZ   RSS PSR STIME TTY          TIME CMD
radicale 4123175 2725173  0 82592 28652   1 14:21 pts/16   00:00:03 /usr/bin/python /usr/bin/radicale --debug

After 5 minutes whilst InfCloud is waiting for a scanning PROPFIND request:

$ cat /proc/loadavg
3.07 1.71 1.37 2/490 4124649

$ free
               total        used        free      shared  buff/cache   available
Mem:         8038544     2400064     2933564      160288     2704916     5171860
Swap:              0           0           0

$ ps -F -C radicale
UID          PID    PPID  C    SZ   RSS PSR STIME TTY          TIME CMD
radicale 4123175 2725173  1 83505 31808   1 14:21 pts/16   00:00:20 /usr/bin/python /usr/bin/radicale --debug

After 10 minutes with calendars loaded in InfCloud:

$ cat /proc/loadavg
1.18 1.46 1.36 2/485 4124885

$ free
               total        used        free      shared  buff/cache   available
Mem:         8038544     2430644     2498560      160288     3109340     5141324
Swap:              0           0           0

$ ps -F -C radicale
UID          PID    PPID  C    SZ   RSS PSR STIME TTY          TIME CMD
radicale 4123175 2725173  3 83709 62012   1 14:21 pts/16   00:00:51 /usr/bin/python /usr/bin/radicale --debug

Stats during those requests: radicale-2023-02-06-vmstat.log

[pbiering]

Looks like your system has an IO and/or CPU issue, the "idle" column turns from usually 99 down to 0 while the "wait" column turns up from 0 to nearly 99 -> the process/OS is waiting for IO response.

Potential reasons

• overloaded underlying virtual infrastructure (in case of a VM)
• bottleneck in underlying/connected IO
• too less CPU cores for parallel work

what is the output of

• virt-what
• cat /sys/block/*/device/{vendor,model}
• cat /proc/cpuinfo | grep processor | wc -l

Also monitor using top while the long running request is running

[Terrance]

$ cat /sys/block/*/device/{vendor,model}
ATA
WDC WD20EFRX-68E

$ cat /proc/cpuinfo | grep processor | wc -l
2

This is a bare-metal home server, so no virtualisation here. CPU is a 2-core Intel(R) Pentium(R) CPU G4560 @ 3.50GHz, HDD is a 2TB WD Red circa 2012. I should say Radicale's performance has likely been in a bit of a decline on my machine for a while, though I'm not sure when I first noticed.

Since the run above, I've rebooted after some other upgrades, and we're back to ~10 seconds for that scanning PROPFIND. It's possible it's just cleared some in-memory cruft, though I hadn't noticed any other software performing poorly before the reboot. I'll keep tabs on it and see how the performance goes as time goes on, but I'll welcome any other places to check.

[Terrance]

So we're a couple of reboots later, and it seems that after about 7-10 days of uptime I start seeing noticeably slow or timing-out requests with Radicale.

I've took down a couple of "heavy" services to try and rule out system performance issues, though the server as a whole still seems fine, and besides some automated backups there isn't really anything else here with any significant disk usage.

From the potential reasons listed before:

• too less CPU cores for parallel work

I noted it's a 2-core system before -- is there an expected / ballpark figure for number of cores required (be it fixed, linear in number of calendars etc.)? Would reducing max_connections in config help?

[Terrance]

Just wanted to check in again as the performance remains a problem, and is also now blocking my ability to sync on mobile: DAVx5 is consistently timing out during the sync (not sure if they've recently implemented a timeout, or the delays have crept up and passed its tolerance).

I'm at the point where I'm considering alternative servers that don't use plain .ics files on disk, as I assume that's ultimately the bottleneck here, though being able to interact with the storage is very useful and I suspect any database-backed servers will be harder to work with for ad-hoc tasks.

Any answers to the open questions above (re. CPU cores, max_connections, and whether this collection is just considered "too large") would still be appreciated, along with any suggestions for other data I can provide -- one other data point I have is from looking at system disk usage: Radicale achieved ~22.5GB of disk reads over the course of ~4 days, which seems excessive when the whole collection is a bit over 1GB (a fraction of which is within sync range of DAVx5).

[pbiering]

did this problem disappear since last report?

[Terrance]

No change, still seeing problematic disk usage. (I assume I'm not expecting to see any changes on Radicale's side? The latest release is still 3.1.8 and the Arch package hasn't changed since last year.)

I have switched from InfCloud to AgenDAV as my web client, which seems to handle the slowness a bit better in general, at the cost of some edits seemingly not going through if they time out.

[pbiering]

which seems excessive when the whole collection is a bit over 1GB

Your collection has a size of over 1 GByte on disk? That's huge and potentially an explanation for the high "wait" value caused by long running I/O.

For testing purposes, can you insert a SSD and move the collection?

Another way of speed check would be temporary copy the collection to /dev/shm/<subdirectory> and run speed test "memory-only".

[Terrance]

I suspected the collection was on the large size, which is why I put the collection stats in the original issue and queried it a few times. Unfortunately I don't have a spare SSD I can hook up, but I can try running it in-memory for a bit and see how that compares -- I just came across Profile-sync-daemon elsewhere which might work for this.

[pbiering]

What filesystem are you using? If "ext*" and there are a huge amount of files in one single directory this can also be a reason. In this case try to create an additional partition with "xfs" and copy over and check the behavior again.

[Terrance]

I've currently got the largest calendar symlinked into /dev/shm (with some manual rsyncs to keep it backed up) as an experiment, but so far it doesn't feel like much of a gain.

It is otherwise on ext4, so with the large calendar in the tens of thousands of items and others in the thousands, I'm not sure how much of a hit is taken listing the collection directories (naive ls -l doesn't seem to struggle though). I think repartitioning this server is a bit out of scope for now -- I'll leave it on the temporary partition for a bit and see how it goes.

Would tidying up the cache help? Or perhaps putting all the caches in /dev/shm? Stats for the large calendar:

Path	Size	Files
.Radicale.cache/history	74M	18325
.Radicale.cache/item	97M	18319
.Radicale.cache/sync-token	617M	294

[pbiering]

Hmm, the sync token directory has a large size. You can stop "radicale", remove directory ".Radicale.cache" complete, create it on /dev/shm/collection-root/$COLLECTION/.Radicale.cache and create a symlink towards in the original collection directory.

Beside that I would assume that without using Python's profiling capabilites it's not easy to detect what consumes the time.

But you can work with a copy of on a different system to dig further. I would start on this 180 seconds duration call from the log you've posted above - and potentially dig into radicale/app/propfind.py and add some debug log entries, especially before and after any for loop to narrow down where the time is consumed.

[mmuszkow]

I was evaluating Radicale few months ago (before the project became active again) for use as a CardDAV server for Contacts synchronisation on iOS/macOS. I had ~12k read-only contacts/users synchronised with ActiveDirectory via script over a course of few months, with ~100 changes per day on average. I spent some time profiling Radicale and the bottleneck was always the filesystem based storage (especially when it lists the files in directories).

To make it work in more or less reliable manner:

• If you want to import large amount of data (e.g. initially) - do it manually by creating the necessary files in collections folders. Doing it via API is bloating the .Radicale.cache and after 10k of inserts the response time you can count in 10s of seconds.
• Limit size of your data. 20k contacts was too much, the synchronisation with iOS/Mac sometimes worked, sometimes not, not sure if that was related to Apple implementation or Radicale slow response times/hanging.
• Using type = multifilesystem_nolock improves performance a bit.
• The rights file is read on every-single-request. Loading it on start and storing in memory increases the performance further.
• There is a max_sync_token_age parameter, it can limit the size of the cache file.

[pbiering]

bottleneck was always the filesystem

which filesystem type was in use?

especially when it lists the files in directories

This can be related to file system type and related caching settings (in the very past this was the reason why "squid" and also "postfix" implemented a multi-subdirectory structure for its file cache/queues)

The rights file is read on every-single-request.

Filed a separate issue: #1523 (potentially one want to contribute and send a PR)

There is a max_sync_token_age parameter, it can limit the size of the cache file.

Default is 30 days, are there any general recommendations around about min or max?

Using type = multifilesystem_nolock improves performance a bit.

Thank you for the hint.

Created a new Wiki page: https://github.com/Kozea/Radicale/wiki/Performance-tuning

Feel free to contribute

[pbiering]

can this be closed now?

[Terrance]

Unfortuately I haven't had the time to properly dig into this. Last time I checked (on the upgrade to 3.2.0 I think) it was still struggling, so I ended up switching efforts to reduce calendar usage more generally -- these large calendars likely just aren't suitable for Radicale's disk-backed storage, and I've yet to find a database-backed one I like and can successfully configure. 🫤

Feel free to close if supporting abnormally-sized calendars isn't a priority; I suspect I'm in the minority here by shoehorning data into calendars!

[pbiering]

please try to reproduce with an optional different caching method "use_mtime_and_size_for_item_cache=True" implemented into upcoming 3.3.2 by #1655

If it improves, all fine and issue was caused by the item file read to calc SHA256 hash and then lookup cache.

If not, please reopen

[Terrance]

Thanks for the heads up -- I've built a local Arch package for the 3.3.2 tag, restored my large calendars, left the cache migration running (took around 80 minutes on my collection, not sure what the expectation there is), and started the server back up.

For now it does seem to be running much more smoothly: InfCloud can load the month view from scratch in 15 seconds, which is a significant improvement over the times in the OP. I'll let it simmer and see how it holds up after a few days/weeks of uptime.

radicale --verify-storage log

[2024-12-15 12:34:48 +0000] [370073] [INFO] Logging of backtrace is disabled in this loglevel
[2024-12-15 12:34:48 +0000] [370073] [INFO] Logging of backtrace is disabled in this loglevel
[2024-12-15 12:34:48 +0000] [370073] [INFO] Loaded default config
[2024-12-15 12:34:48 +0000] [370073] [INFO] Loaded config file '/etc/radicale/config'
[2024-12-15 12:34:48 +0000] [370073] [INFO] Skipped missing/unreadable config file '/var/lib/radicale/.config/radicale/config'
[2024-12-15 12:34:48 +0000] [370073] [INFO] Verifying storage
[2024-12-15 12:34:48 +0000] [370073] [INFO] storage type is 'radicale.storage.multifilesystem_nolock'
[2024-12-15 12:34:48 +0000] [370073] [INFO] storage location: '/var/lib/radicale/collections'
[2024-12-15 12:34:48 +0000] [370073] [INFO] storage location subfolder: '/var/lib/radicale/collections/collection-root'
[2024-12-15 12:34:48 +0000] [370073] [INFO] storage cache subfolder usage for 'item': False
[2024-12-15 12:34:48 +0000] [370073] [INFO] storage cache subfolder usage for 'history': False
[2024-12-15 12:34:48 +0000] [370073] [INFO] storage cache subfolder usage for 'sync-token': False
[2024-12-15 12:34:48 +0000] [370073] [INFO] storage cache use mtime and size for 'item': True
[2024-12-15 12:34:48 +0000] [370073] [INFO] storage folder umask (from system): '0022'
[2024-12-15 12:34:48 +0000] [370073] [INFO] Verifying   path ''
[2024-12-15 12:34:48 +0000] [370073] [INFO] Skip !collection ''
[2024-12-15 12:34:48 +0000] [370073] [INFO] Verifying   path 'user'
[2024-12-15 12:34:48 +0000] [370073] [INFO] Skip !collection 'user'
[2024-12-15 12:34:48 +0000] [370073] [INFO] Verifying   path 'user/a5797b88-7d73-9751-c7e7-2227c5a55f07'
[2024-12-15 12:34:48 +0000] [370073] [INFO] Verified collect 'user/a5797b88-7d73-9751-c7e7-2227c5a55f07' (items: 106)
[2024-12-15 12:34:48 +0000] [370073] [INFO] Verifying   path 'user/4c899125-a332-8e3d-ce5b-6aabb3db886a'
[2024-12-15 12:34:48 +0000] [370073] [INFO] Verified collect 'user/4c899125-a332-8e3d-ce5b-6aabb3db886a' (items: 34)
[2024-12-15 12:34:48 +0000] [370073] [INFO] Verifying   path 'user/29917d2c-60e7-0a32-178b-079c5bb33fe8'
[2024-12-15 12:51:19 +0000] [370073] [INFO] Verified collect 'user/29917d2c-60e7-0a32-178b-079c5bb33fe8' (items: 3466)
[2024-12-15 12:51:19 +0000] [370073] [INFO] Verifying   path 'user/1a518a80-23b6-abd1-cef8-f0e25e6063ef'
[2024-12-15 13:07:27 +0000] [370073] [INFO] Verified collect 'user/1a518a80-23b6-abd1-cef8-f0e25e6063ef' (items: 2387)
[2024-12-15 13:07:27 +0000] [370073] [INFO] Verifying   path 'user/1fc7a94b-a1b1-bb0a-5e9e-c3756f597434'
[2024-12-15 13:09:38 +0000] [370073] [INFO] Verified collect 'user/1fc7a94b-a1b1-bb0a-5e9e-c3756f597434' (items: 1082)
[2024-12-15 13:09:38 +0000] [370073] [INFO] Verifying   path 'user/53f15099-79b5-d366-a91f-462bbc0435f5'
[2024-12-15 13:23:30 +0000] [370073] [INFO] Verified collect 'user/53f15099-79b5-d366-a91f-462bbc0435f5' (items: 4400)
[2024-12-15 13:23:30 +0000] [370073] [INFO] Verifying   path 'user/eb6cc48b-f577-609f-f929-56b6ddd37792'
[2024-12-15 13:32:19 +0000] [370073] [INFO] Verified collect 'user/eb6cc48b-f577-609f-f929-56b6ddd37792' (items: 5186)
[2024-12-15 13:32:19 +0000] [370073] [INFO] Verifying   path 'user/883076b9-7570-78be-a719-bdd417592df5'
[2024-12-15 13:55:43 +0000] [370073] [INFO] Verified collect 'user/883076b9-7570-78be-a719-bdd417592df5' (items: 13161)
[2024-12-15 13:55:43 +0000] [370073] [INFO] Verifying   path 'user/6c9d17e5-7012-f6c9-29c3-2d93898f0c0d'
[2024-12-15 13:55:44 +0000] [370073] [INFO] Verified collect 'user/6c9d17e5-7012-f6c9-29c3-2d93898f0c0d' (items: 1721)
[2024-12-15 13:55:44 +0000] [370073] [INFO] Verifying   path 'user/b31241e3-f303-9ffa-aca2-03734debda04'
[2024-12-15 13:55:44 +0000] [370073] [INFO] Verified collect 'user/b31241e3-f303-9ffa-aca2-03734debda04' (items: 59)
[2024-12-15 13:55:44 +0000] [370073] [INFO] Verifying   path 'user/cb17d5b1-5693-4d59-4fdf-b8a62e705465'
[2024-12-15 13:55:52 +0000] [370073] [INFO] Verified collect 'user/cb17d5b1-5693-4d59-4fdf-b8a62e705465' (items: 3789)
[2024-12-15 13:55:52 +0000] [370073] [INFO] Verifying   path 'user/68643525-214e-bc87-dd32-773f40887307'
[2024-12-15 13:55:58 +0000] [370073] [INFO] Verified collect 'user/68643525-214e-bc87-dd32-773f40887307' (items: 3534)
[2024-12-15 13:55:58 +0000] [370073] [INFO] Verifying   path 'user/31f4fd59-7748-b1de-426c-ee1bee515ef4'
[2024-12-15 13:56:02 +0000] [370073] [INFO] Verified collect 'user/31f4fd59-7748-b1de-426c-ee1bee515ef4' (items: 3104)
[2024-12-15 13:56:02 +0000] [370073] [INFO] Verifying   path 'user/9d9d7ce5-54f0-eae2-ef0f-704b6493b8f4'
[2024-12-15 13:56:02 +0000] [370073] [INFO] Verified collect 'user/9d9d7ce5-54f0-eae2-ef0f-704b6493b8f4' (items: 2)
[2024-12-15 13:56:02 +0000] [370073] [INFO] Verifying   path 'user/c730a9ad-243f-5bf3-1c14-580fc1f623ca'
[2024-12-15 13:56:04 +0000] [370073] [INFO] Verified collect 'user/c730a9ad-243f-5bf3-1c14-580fc1f623ca' (items: 1431)
[2024-12-15 13:56:04 +0000] [370073] [INFO] Verifying   path 'user/260ceee4-135a-69a8-d36c-8bfe3937ed2a'
[2024-12-15 13:56:04 +0000] [370073] [INFO] Verified collect 'user/260ceee4-135a-69a8-d36c-8bfe3937ed2a' (items: 166)
[2024-12-15 13:56:04 +0000] [370073] [INFO] Verifying   path 'user/513bbed6-56f0-cd92-4188-5c3c076745a5'
[2024-12-15 13:56:05 +0000] [370073] [INFO] Verified collect 'user/513bbed6-56f0-cd92-4188-5c3c076745a5' (items: 193)
[2024-12-15 13:56:05 +0000] [370073] [INFO] Verifying   path 'user/9658d9a8-70e5-d038-18f7-a2545d5f9af8'
[2024-12-15 13:56:07 +0000] [370073] [INFO] Verified collect 'user/9658d9a8-70e5-d038-18f7-a2545d5f9af8' (items: 102)

[pbiering]

left the cache migration running (took around 80 minutes on my collection, not sure what the expectation there is)

I assume, too many fsync calls during verfication and regeneration of the cache...will dig into how to postpone them.

[pbiering]

left the cache migration running (took around 80 minutes on my collection, not sure what the expectation there is)

I assume, too many fsync calls during verfication and regeneration of the cache...will dig into how to postpone them.

Should be fixed by 4b1183a