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: https://github.com/Kozea/Radicale/issues/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