Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Radicale quite slow after fresh installation with just one item in the calendar #1466

Closed
Skaronator opened this issue Apr 6, 2024 · 7 comments

Comments

@Skaronator
Copy link

Hi,

I just deployed Radicale 3.9.1 using the tomsquest/docker-radicale Container Image.

I noticed right from the beginning that Radicale is really slow. Looking at the logs confirms it. Every data request takes over 2 seconds.

I don't think it's a hardware issue for me. The machine has 128 GB RAM, 16 Core CPU, Idles at 0.63 (less than one core) and the storage is blazing fast NVMe in a ZFS Mirror.

Log

[2024-04-06 13:21:00 +0200] [1/Thread-200 (process_request_thread)] [INFO] Successful login: 'niklas'
[2024-04-06 13:21:00 +0200] [1/Thread-200 (process_request_thread)] [INFO] PROPFIND response status for '/niklas/' with depth '0' in 2.756 seconds: 207 Multi-Status
[2024-04-06 13:21:00 +0200] [1/Thread-207 (process_request_thread)] [INFO] PROPFIND request for '/niklas/' with depth '1' received from 10.244.1.1 using 'Mozilla/5.0'
[2024-04-06 13:21:00 +0200] [1/Thread-199 (process_request_thread)] [INFO] Successful login: 'niklas'
[2024-04-06 13:21:00 +0200] [1/Thread-199 (process_request_thread)] [INFO] PROPFIND response status for '/niklas/' with depth '0' in 2.766 seconds: 207 Multi-Status
[2024-04-06 13:21:00 +0200] [1/Thread-208 (process_request_thread)] [INFO] PROPFIND request for '/niklas/' with depth '1' received from 10.244.1.1 using 'Mozilla/5.0'
[2024-04-06 13:21:03 +0200] [1/Thread-207 (process_request_thread)] [INFO] Successful login: 'niklas'
[2024-04-06 13:21:03 +0200] [1/Thread-207 (process_request_thread)] [INFO] PROPFIND response status for '/niklas/' with depth '1' in 2.781 seconds: 207 Multi-Status
[2024-04-06 13:21:03 +0200] [1/Thread-209 (process_request_thread)] [INFO] PROPFIND request for '/niklas/3deae9b3-eabb-42d8-9811-3b4342e10395/' with depth '0' received from 10.244.1.1 using 'Mozilla/5.0'
[2024-04-06 13:21:03 +0200] [1/Thread-208 (process_request_thread)] [INFO] Successful login: 'niklas'
[2024-04-06 13:21:03 +0200] [1/Thread-208 (process_request_thread)] [INFO] PROPFIND response status for '/niklas/' with depth '1' in 2.782 seconds: 207 Multi-Status
[2024-04-06 13:21:03 +0200] [1/Thread-210 (process_request_thread)] [INFO] PROPFIND request for '/niklas/3deae9b3-eabb-42d8-9811-3b4342e10395/' with depth '0' received from 10.244.1.1 using 'Mozilla/5.0'
[2024-04-06 13:21:06 +0200] [1/Thread-209 (process_request_thread)] [INFO] Successful login: 'niklas'
[2024-04-06 13:21:06 +0200] [1/Thread-209 (process_request_thread)] [INFO] PROPFIND response status for '/niklas/3deae9b3-eabb-42d8-9811-3b4342e10395/' with depth '0' in 2.750 seconds: 207 Multi-Status
[2024-04-06 13:21:06 +0200] [1/Thread-211 (process_request_thread)] [INFO] REPORT request for '/niklas/3deae9b3-eabb-42d8-9811-3b4342e10395/' with depth '1' received from 10.244.1.1 using 'Mozilla/5.0'
[2024-04-06 13:21:06 +0200] [1/Thread-210 (process_request_thread)] [INFO] Successful login: 'niklas'
[2024-04-06 13:21:06 +0200] [1/Thread-210 (process_request_thread)] [INFO] PROPFIND response status for '/niklas/3deae9b3-eabb-42d8-9811-3b4342e10395/' with depth '0' in 2.747 seconds: 207 Multi-Status
[2024-04-06 13:21:06 +0200] [1/Thread-212 (process_request_thread)] [INFO] REPORT request for '/niklas/3deae9b3-eabb-42d8-9811-3b4342e10395/' with depth '1' received from 10.244.1.1 using 'Mozilla/5.0'
[2024-04-06 13:21:09 +0200] [1/Thread-211 (process_request_thread)] [INFO] Successful login: 'niklas'
[2024-04-06 13:21:09 +0200] [1/Thread-211 (process_request_thread)] [INFO] REPORT response status for '/niklas/3deae9b3-eabb-42d8-9811-3b4342e10395/' with depth '1' in 2.772 seconds: 207 Multi-Status
[2024-04-06 13:21:09 +0200] [1/Thread-212 (process_request_thread)] [INFO] Successful login: 'niklas'
[2024-04-06 13:21:09 +0200] [1/Thread-212 (process_request_thread)] [INFO] REPORT response status for '/niklas/3deae9b3-eabb-42d8-9811-3b4342e10395/' with depth '1' in 2.782 seconds: 207 Multi-Status

Config

[server]
hosts = 0.0.0.0:5232

[auth]
type = htpasswd
htpasswd_encryption = bcrypt
htpasswd_filename = /config/htpasswd
delay = 5

[storage]
type = multifilesystem
filesystem_folder = /data

[rights]
type = owner_only

[web]
type = internal

[logging]
level = info
mask_passwords = True
Skaronator added a commit to Skaronator/homelab that referenced this issue Apr 6, 2024
@pbiering
Copy link
Collaborator

pbiering commented Apr 6, 2024

Probably same issue reported in #1282
I will try to add some optional profiling messages to trail down what part of code consumes so much time.

@pbiering pbiering self-assigned this Apr 7, 2024
@pbiering
Copy link
Collaborator

pbiering commented Apr 7, 2024

could you please use following branch for testing, I've added some profiling output here...will extend on demand:'https://github.com/pbiering/Radicale/tree/add-profiling

Enable it using

[logging]
profiling = True

Example output:

[2024-04-07 09:27:23 +0200] [2228/Thread-1] [INFO] PROPFIND request for '/user/user.ics' with depth '1' received from 169.254.1.2 using 'curl/8.2.1'
[2024-04-07 09:27:23 +0200] [2228/Thread-1] [INFO] Successful login: 'user'
[2024-04-07 09:27:23 +0200] [2228/Thread-1] [INFO] profiling/PROPFIND/_xml_propfind: begin
[2024-04-07 09:27:23 +0200] [2228/Thread-1] [INFO] profiling/PROPFIND/_collect_allowed_items: begin
[2024-04-07 09:27:23 +0200] [2228/Thread-1] [INFO] profiling/PROPFIND/_collect_allowed_items: end 70 items in 0.129 seconds
[2024-04-07 09:27:23 +0200] [2228/Thread-1] [INFO] profiling/PROPFIND/_xml_propfind: end after 0.129 seconds
[2024-04-07 09:27:23 +0200] [2228/Thread-1] [INFO] PROPFIND response status for '/user/user.ics' with depth '1' in 0.186 seconds: 207 Multi-Status

Please post your's.

@pbiering pbiering added the medium label Apr 7, 2024
@Skaronator
Copy link
Author

Thanks for the swift response! Sadly, I'm unable to build the container image. I tried building the Dockerfile.dev image, but it seems not to include the latest changes.

When searching for the code within the image I cannot find anything relevant. I'm not that familiar with the python/pip install stage. From the container image it should be somewhere in /app/ but I can don't see anything:

/app $ ls -lsah /app/*
      0 lrwxrwxrwx    1 radicale radicale       3 Apr  7 08:28 /app/lib64 -> lib
   4.0K -rw-r--r--    1 radicale radicale     165 Apr  7 08:28 /app/pyvenv.cfg

/app/bin:
total 56K
   4.0K drwxr-xr-x    2 radicale radicale    4.0K Apr  7 08:28 .
   4.0K drwxr-xr-x    1 root     root        4.0K Apr  7 08:28 ..
  12.0K -rw-r--r--    1 radicale radicale    8.8K Apr  7 08:28 Activate.ps1
   4.0K -rw-r--r--    1 radicale radicale    2.0K Apr  7 08:28 activate
   4.0K -rw-r--r--    1 radicale radicale     903 Apr  7 08:28 activate.csh
   4.0K -rw-r--r--    1 radicale radicale    2.1K Apr  7 08:28 activate.fish
   4.0K -rwxr-xr-x    1 radicale radicale     220 Apr  7 08:28 change_tz
   4.0K -rwxr-xr-x    1 radicale radicale     219 Apr  7 08:28 ics_diff
   4.0K -rwxr-xr-x    1 radicale radicale     225 Apr  7 08:28 pip
   4.0K -rwxr-xr-x    1 radicale radicale     225 Apr  7 08:28 pip3
   4.0K -rwxr-xr-x    1 radicale radicale     225 Apr  7 08:28 pip3.12
      0 lrwxrwxrwx    1 radicale radicale      21 Apr  7 08:28 python -> /usr/local/bin/python
      0 lrwxrwxrwx    1 radicale radicale       6 Apr  7 08:28 python3 -> python
      0 lrwxrwxrwx    1 radicale radicale       6 Apr  7 08:28 python3.12 -> python
   4.0K -rwxr-xr-x    1 radicale radicale     218 Apr  7 08:28 radicale

/app/include:
total 12K
   4.0K drwxr-xr-x    3 radicale radicale    4.0K Apr  7 08:28 .
   4.0K drwxr-xr-x    1 root     root        4.0K Apr  7 08:28 ..
   4.0K drwxr-xr-x    2 radicale radicale    4.0K Apr  7 08:28 python3.12

/app/lib:
total 12K
   4.0K drwxr-xr-x    3 radicale radicale    4.0K Apr  7 08:28 .
   4.0K drwxr-xr-x    1 root     root        4.0K Apr  7 08:28 ..
   4.0K drwxr-xr-x    3 radicale radicale    4.0K Apr  7 08:28 python3.12

The only file that is called radicale contains only these few lines:

/app $ cat /app/bin/radicale
#!/app/venv/bin/python
# -*- coding: utf-8 -*-
import re
import sys
from radicale.__main__ import run
if __name__ == '__main__':
    sys.argv[0] = re.sub(r'(-script\.pyw|\.exe)?$', '', sys.argv[0])
    sys.exit(run())

My image is available here:

https://hub.docker.com/layers/skaronator/radicale/profiling-2/images/sha256-6117bdb15f5d378846a189fd49489233338d55b057465023713885dca086c2f3?context=repo

@pbiering
Copy link
Collaborator

pbiering commented Apr 7, 2024

Sorry, can't support such deployments for troubleshooting at the moment, try to apply the changes manually to the related files:
master...pbiering:Radicale:add-profiling

@Skaronator
Copy link
Author

I'll try to build a working image on the weekend.

@Skaronator
Copy link
Author

Hi, I was able to get the image working. It looks like the issue fixed itself?! I guess it's due to the newer release.

Here is the log with profiling and the newer version:

radicale [2024-05-19 17:24:29 +0200] [1/Thread-56 (process_request_thread)] [INFO] Successful login: 'niklas'
radicale [2024-05-19 17:24:29 +0200] [1/Thread-56 (process_request_thread)] [INFO] profiling/PROPFIND/_xml_propfind: begin
radicale [2024-05-19 17:24:29 +0200] [1/Thread-56 (process_request_thread)] [INFO] profiling/PROPFIND/_collect_allowed_items: begin
radicale [2024-05-19 17:24:29 +0200] [1/Thread-56 (process_request_thread)] [INFO] profiling/PROPFIND/_collect_allowed_items: end 1 items in 0.000 seconds
radicale [2024-05-19 17:24:29 +0200] [1/Thread-56 (process_request_thread)] [INFO] profiling/PROPFIND/_xml_propfind: end after 0.000 seconds
radicale [2024-05-19 17:24:29 +0200] [1/Thread-56 (process_request_thread)] [INFO] PROPFIND response status for '/niklas' with depth '0' in 0.096 seconds: 207 Multi-Status
radicale [2024-05-19 17:24:35 +0200] [1/Thread-58 (process_request_thread)] [INFO] GET request for '/' received from 10.244.1.1 using 'kube-probe/1.30'
radicale [2024-05-19 17:24:35 +0200] [1/Thread-58 (process_request_thread)] [INFO] GET response status for '/' in 0.000 seconds: 302 Found
radicale [2024-05-19 17:24:35 +0200] [1/Thread-59 (process_request_thread)] [INFO] GET request for '/' received from 10.244.1.1 using 'kube-probe/1.30'
radicale [2024-05-19 17:24:35 +0200] [1/Thread-59 (process_request_thread)] [INFO] GET response status for '/' in 0.000 seconds: 302 Found
radicale [2024-05-19 17:24:35 +0200] [1/Thread-60 (process_request_thread)] [INFO] GET request for '/.web' received from 10.244.1.1 using 'kube-probe/1.30'
radicale [2024-05-19 17:24:35 +0200] [1/Thread-60 (process_request_thread)] [INFO] GET response status for '/.web' in 0.000 seconds: 302 Found
radicale [2024-05-19 17:24:35 +0200] [1/Thread-61 (process_request_thread)] [INFO] GET request for '/.web' received from 10.244.1.1 using 'kube-probe/1.30'
radicale [2024-05-19 17:24:35 +0200] [1/Thread-61 (process_request_thread)] [INFO] GET response status for '/.web' in 0.000 seconds: 302 Found
radicale [2024-05-19 17:24:35 +0200] [1/Thread-62 (process_request_thread)] [INFO] GET request for '/.web/' received from 10.244.1.1 using 'kube-probe/1.30'
radicale [2024-05-19 17:24:35 +0200] [1/Thread-63 (process_request_thread)] [INFO] GET request for '/.web/' received from 10.244.1.1 using 'kube-probe/1.30'
radicale [2024-05-19 17:24:35 +0200] [1/Thread-62 (process_request_thread)] [INFO] GET response status for '/.web/' in 0.001 seconds: 200 OK
radicale [2024-05-19 17:24:35 +0200] [1/Thread-63 (process_request_thread)] [INFO] GET response status for '/.web/' in 0.000 seconds: 200 OK
radicale [2024-05-19 17:24:45 +0200] [1/Thread-64 (process_request_thread)] [INFO] GET request for '/' received from 10.244.1.1 using 'kube-probe/1.30'
radicale [2024-05-19 17:24:45 +0200] [1/Thread-64 (process_request_thread)] [INFO] GET response status for '/' in 0.000 seconds: 302 Found
radicale [2024-05-19 17:24:45 +0200] [1/Thread-65 (process_request_thread)] [INFO] GET request for '/' received from 10.244.1.1 using 'kube-probe/1.30'
radicale [2024-05-19 17:24:45 +0200] [1/Thread-65 (process_request_thread)] [INFO] GET response status for '/' in 0.000 seconds: 302 Found
radicale [2024-05-19 17:24:45 +0200] [1/Thread-66 (process_request_thread)] [INFO] GET request for '/.web' received from 10.244.1.1 using 'kube-probe/1.30'
radicale [2024-05-19 17:24:45 +0200] [1/Thread-66 (process_request_thread)] [INFO] GET response status for '/.web' in 0.000 seconds: 302 Found
radicale [2024-05-19 17:24:45 +0200] [1/Thread-67 (process_request_thread)] [INFO] GET request for '/.web' received from 10.244.1.1 using 'kube-probe/1.30'
radicale [2024-05-19 17:24:45 +0200] [1/Thread-67 (process_request_thread)] [INFO] GET response status for '/.web' in 0.000 seconds: 302 Found
radicale [2024-05-19 17:24:45 +0200] [1/Thread-68 (process_request_thread)] [INFO] GET request for '/.web/' received from 10.244.1.1 using 'kube-probe/1.30'
radicale [2024-05-19 17:24:45 +0200] [1/Thread-69 (process_request_thread)] [INFO] GET request for '/.web/' received from 10.244.1.1 using 'kube-probe/1.30'
radicale [2024-05-19 17:24:45 +0200] [1/Thread-68 (process_request_thread)] [INFO] GET response status for '/.web/' in 0.001 seconds: 200 OK
radicale [2024-05-19 17:24:45 +0200] [1/Thread-69 (process_request_thread)] [INFO] GET response status for '/.web/' in 0.000 seconds: 200 OK

My Dockerfile was pretty straightforward in the end:

FROM tomsquest/docker-radicale

RUN /venv/bin/pip install --no-cache-dir git+https://github.com/pbiering/Radicale.git@add-profiling

@Skaronator
Copy link
Author

I just retested using the older version and the issue is gone as well?! Really weird.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

2 participants