From 3c0267c98a21175f4fc8edea0ff8be391e3a1c2b Mon Sep 17 00:00:00 2001 From: Peter Bieringer Date: Mon, 8 Dec 2025 12:29:43 +0100 Subject: [PATCH 01/10] profiling: add options --- radicale/config.py | 19 +++++++++++++++++++ 1 file changed, 19 insertions(+) diff --git a/radicale/config.py b/radicale/config.py index a4ba6610..5ec5908f 100644 --- a/radicale/config.py +++ b/radicale/config.py @@ -41,6 +41,8 @@ from radicale import auth, hook, rights, storage, types, web from radicale.hook import email from radicale.item import check_and_sanitize_props +from radicale import app # isort:skip (circular import issue) + DEFAULT_CONFIG_PATH: str = os.pathsep.join([ "?/etc/radicale/config", "?~/.config/radicale/config"]) @@ -581,6 +583,23 @@ This is an automated message. Please do not reply.""", "value": "False", "help": "log storage cache action on level=debug", "type": bool}), + ("profiling", { + "value": "per_request_method", + "help": "log profiling data level=info", + "type": str, + "internal": app.PROFILING}), + ("profiling_per_request_min_duration", { + "value": "3", + "help": "log profiling data per request minimum duration (seconds)", + "type": int}), + ("profiling_per_request_method_interval", { + "value": "600", + "help": "log profiling data per request method interval (seconds)", + "type": int}), + ("profiling_top_x_functions", { + "value": "10", + "help": "log profiling top X functions (limit)", + "type": int}), ("mask_passwords", { "value": "True", "help": "mask passwords in logs", From edc88fbed8463eae87d8a2a6e45b08326dc86ffc Mon Sep 17 00:00:00 2001 From: Peter Bieringer Date: Mon, 8 Dec 2025 12:31:09 +0100 Subject: [PATCH 02/10] profiling: add option default --- config | 14 ++++++++++++++ 1 file changed, 14 insertions(+) diff --git a/config b/config index 93291650..46b2f689 100644 --- a/config +++ b/config @@ -321,6 +321,20 @@ # Log storage cache actions on level=debug #storage_cache_actions_on_debug = False +# Log profiling data on level=info +# Value: per_request | per_request_method +#profiling = per_request_method + +# Log profiling data per request minium duration (seconds) +#profiling_per_request_min_duration = 3 + +# Log profiling data per request method interval +#profiling_per_request_method_interval = 600 + +# Log profiling top X functions (limit) +#profiling_top_x_functions = 10 + + [headers] # Additional HTTP headers From 462fa931846fa4bbda36935ab406fc37e95a4faf Mon Sep 17 00:00:00 2001 From: Peter Bieringer Date: Mon, 8 Dec 2025 12:31:49 +0100 Subject: [PATCH 03/10] profiling: document new options --- DOCUMENTATION.md | 37 +++++++++++++++++++++++++++++++++++++ 1 file changed, 37 insertions(+) diff --git a/DOCUMENTATION.md b/DOCUMENTATION.md index 855c671a..420345b6 100644 --- a/DOCUMENTATION.md +++ b/DOCUMENTATION.md @@ -1690,6 +1690,43 @@ Log storage cache actions on `level = debug` Default: `False` +##### profiling_per_request + +_(>= 3.5.10)_ + +Log profiling data on level=info + +Default: `per_request` + +One of +* `per_request` (above minimum duration) +* `per_request_method` (regular interval) + +##### profiling_per_request_min_duration + +_(>= 3.5.10)_ + +Log profiling data per request minimum duration (seconds) before logging, otherwise skip + +Default: `3` + +##### profiling_per_request_method_interval + +_(>= 3.5.10)_ + +Log profiling data per method interval (seconds) +Triggered by request, not active on idle systems + +Default: `600` + +##### profiling_top_x_functions + +_(>= 3.5.10)_ + +Log profiling top X functions (limit) + +Default: `10` + #### [headers] This section can be used to specify additional HTTP headers that will be sent to clients. From 3f4d43443927794499f3301f443df6142fa45e1d Mon Sep 17 00:00:00 2001 From: Peter Bieringer Date: Mon, 8 Dec 2025 12:33:17 +0100 Subject: [PATCH 04/10] profiling: add support --- radicale/app/__init__.py | 102 ++++++++++++++++++++++++++++++++++++++- 1 file changed, 100 insertions(+), 2 deletions(-) diff --git a/radicale/app/__init__.py b/radicale/app/__init__.py index 940d15b5..882787ec 100644 --- a/radicale/app/__init__.py +++ b/radicale/app/__init__.py @@ -27,13 +27,16 @@ the built-in server (see ``radicale.server`` module). """ import base64 +import cProfile import datetime +import io import pprint +import pstats import random import time import zlib from http import client -from typing import Iterable, List, Mapping, Tuple, Union +from typing import Iterable, List, Mapping, Sequence, Tuple, Union from radicale import config, httputils, log, pathutils, types from radicale.app.base import ApplicationBase @@ -55,6 +58,10 @@ from radicale.log import logger # Combination of types.WSGIStartResponse and WSGI application return value _IntermediateResponse = Tuple[str, List[Tuple[str, str]], Iterable[bytes]] +REQUEST_METHODS = ["DELETE", "GET", "HEAD", "MKCALENDAR", "MKCOL", "MOVE", "OPTIONS", "POST", "PROPFIND", "PROPPATCH", "PUT", "REPORT"] + +PROFILING: Sequence[str] = ("per_request", "per_request_method") + class Application(ApplicationPartDelete, ApplicationPartHead, ApplicationPartGet, ApplicationPartMkcalendar, @@ -73,6 +80,12 @@ class Application(ApplicationPartDelete, ApplicationPartHead, _web_type: str _script_name: str _extra_headers: Mapping[str, str] + _profiling_per_request: bool = False + _profiling_per_request_method: bool = False + profiler_per_request_method: dict[str, cProfile.Profile] = {} + profiler_per_request_method_counter: dict[str, int] = {} + profiler_per_request_method_starttime: datetime.datetime + profiler_per_request_method_logtime: datetime.datetime def __init__(self, configuration: config.Configuration) -> None: """Initialize Application. @@ -116,6 +129,52 @@ class Application(ApplicationPartDelete, ApplicationPartHead, self._extra_headers[key] = configuration.get("headers", key) self._strict_preconditions = configuration.get("storage", "strict_preconditions") logger.info("strict preconditions check: %s", self._strict_preconditions) + # Profiling options + self._profiling = configuration.get("logging", "profiling") + self._profiling_per_request_min_duration = configuration.get("logging", "profiling_per_request_min_duration") + self._profiling_per_request_method_interval = configuration.get("logging", "profiling_per_request_method_interval") + self._profiling_top_x_functions = configuration.get("logging", "profiling_top_x_functions") + if self._profiling == "per_request": + self._profiling_per_request = True + elif self._profiling == "per_request_method": + self._profiling_per_request_method = True + else: + logger.warning("profiling: %s (not supported, disabled)", self._profiling) + if self._profiling_per_request or self._profiling_per_request_method: + logger.info("profiling: %s", self._profiling) + logger.info("profiling top X functions: %d", self._profiling_top_x_functions) + if self._profiling_per_request: + logger.info("profiling per request minimum duration: %d (below are skipped)", self._profiling_per_request_min_duration) + if self._profiling_per_request_method: + logger.info("profiling per request method interval: %d seconds", self._profiling_per_request_method_interval) + # Profiling per request method initialization + if self._profiling_per_request_method: + for method in REQUEST_METHODS: + self.profiler_per_request_method[method] = cProfile.Profile() + self.profiler_per_request_method_counter[method] = False + self.profiler_per_request_method_starttime = datetime.datetime.now() + self.profiler_per_request_method_logtime = self.profiler_per_request_method_starttime + + def __del__(self) -> None: + """Shutdown application.""" + if self._profiling_per_request_method: + # Profiling since startup + self._profiler_per_request_method(True) + + def _profiler_per_request_method(self, shutdown: bool = False) -> None: + """Display profiler data per method.""" + profiler_timedelta_start = (datetime.datetime.now() - self.profiler_per_request_method_starttime).total_seconds() + for method in REQUEST_METHODS: + if self.profiler_per_request_method_counter[method] > 0: + s = io.StringIO() + stats = pstats.Stats(self.profiler_per_request_method[method], stream=s).sort_stats('cumulative') + stats.print_stats(self._profiling_top_x_functions) # Print top X functions + logger.info("Profiling data per request method after %d seconds and %d requests: %s: %s", profiler_timedelta_start, self.profiler_per_request_method_counter[method], method, s.getvalue()) + else: + if shutdown: + logger.info("Profiling data per request method after %d seconds: %s: (no requests seen so far)", profiler_timedelta_start, method) + else: + logger.debug("Profiling data per request method after %d seconds: %s: (no requests seen so far)", profiler_timedelta_start, method) def _scrub_headers(self, environ: types.WSGIEnviron) -> types.WSGIEnviron: """Mask passwords and cookies.""" @@ -156,6 +215,7 @@ class Application(ApplicationPartDelete, ApplicationPartHead, request_method = environ["REQUEST_METHOD"].upper() unsafe_path = environ.get("PATH_INFO", "") https = environ.get("HTTPS", "") + profiler = None context = AuthContext() @@ -194,6 +254,7 @@ class Application(ApplicationPartDelete, ApplicationPartHead, # Start response time_end = datetime.datetime.now() + time_delta_seconds = (time_end - time_begin).total_seconds() status_text = "%d %s" % ( status, client.responses.get(status, "Unknown")) if answer is not None: @@ -203,7 +264,29 @@ class Application(ApplicationPartDelete, ApplicationPartHead, else: logger.info("%s response status for %r%s in %.3f seconds: %s", request_method, unsafe_path, depthinfo, - (time_end - time_begin).total_seconds(), status_text) + time_delta_seconds, status_text) + + # Profiling end + if self._profiling_per_request: + if profiler is not None: + # Profiling per request + if time_delta_seconds < self._profiling_per_request_min_duration: + logger.debug("Profiling data %s response for %r%s: (supressed because duration below minimum %.3f < %.3f)", request_method, unsafe_path, depthinfo, time_delta_seconds, self._profiling_per_request_min_duration) + else: + s = io.StringIO() + stats = pstats.Stats(profiler, stream=s).sort_stats('cumulative') + stats.print_stats(self._profiling_top_x_functions) # Print top X functions + logger.info("Profiling data %s response for %r%s: %s", request_method, unsafe_path, depthinfo, s.getvalue()) + else: + logger.debug("Profiling data %s response for %r%s: (supressed because of no data)", request_method, unsafe_path, depthinfo) + elif self._profiling_per_request_method: + self.profiler_per_request_method[request_method].disable() + self.profiler_per_request_method_counter[request_method] += 1 + profiler_timedelta = (datetime.datetime.now() - self.profiler_per_request_method_logtime).total_seconds() + if profiler_timedelta > self._profiling_per_request_method_interval: + self._profiler_per_request_method() + self.profiler_per_request_method_logtime = datetime.datetime.now() + # Return response content return status_text, list(headers.items()), answers @@ -370,8 +453,23 @@ class Application(ApplicationPartDelete, ApplicationPartHead, return response(*httputils.REQUEST_ENTITY_TOO_LARGE) if not login or user: + # Profiling + if self._profiling_per_request: + profiler = cProfile.Profile() + profiler.enable() + elif self._profiling_per_request_method: + self.profiler_per_request_method[request_method].enable() + status, headers, answer = function( environ, base_prefix, path, user, remote_host, remote_useragent) + + # Profiling + if self._profiling_per_request: + if profiler is not None: + profiler.disable() + elif self._profiling_per_request_method: + self.profiler_per_request_method[request_method].disable() + if (status, headers, answer) == httputils.NOT_ALLOWED: logger.info("Access to %r denied for %s", path, repr(user) if user else "anonymous user") From 0776b1bdd0daf2649cc433635a9b4c76a80ec465 Mon Sep 17 00:00:00 2001 From: Peter Bieringer Date: Mon, 8 Dec 2025 12:33:30 +0100 Subject: [PATCH 05/10] profiling: extend changelog --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 920df43b..599a108e 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,7 @@ * Add: logging of broken contact items during PUT * Extend: [auth] imap: add fallback support for LOGIN towards remote IMAP server (replaced in 3.5.0) * Fix: improper detection of HTTP_X_FORWARDED_PORT on MOVE +* Extend: [logging] with profiling log per reqest or regular per request method ## 3.5.9 * Extend: [auth] add support for type http_remote_user From 15ebb1e647deaea2e8a0d637d3aefceb2b095266 Mon Sep 17 00:00:00 2001 From: Peter Bieringer Date: Mon, 8 Dec 2025 17:54:18 +0100 Subject: [PATCH 06/10] profiling: default is now 'none' and config option will be checked instantly --- DOCUMENTATION.md | 3 ++- config | 4 ++-- radicale/config.py | 15 ++++++++++----- 3 files changed, 14 insertions(+), 8 deletions(-) diff --git a/DOCUMENTATION.md b/DOCUMENTATION.md index 420345b6..71670c68 100644 --- a/DOCUMENTATION.md +++ b/DOCUMENTATION.md @@ -1696,9 +1696,10 @@ _(>= 3.5.10)_ Log profiling data on level=info -Default: `per_request` +Default: `none` One of +* `none` (disabled) * `per_request` (above minimum duration) * `per_request_method` (regular interval) diff --git a/config b/config index 46b2f689..290fa368 100644 --- a/config +++ b/config @@ -322,8 +322,8 @@ #storage_cache_actions_on_debug = False # Log profiling data on level=info -# Value: per_request | per_request_method -#profiling = per_request_method +# Value: per_request | per_request_method | none +#profiling = none # Log profiling data per request minium duration (seconds) #profiling_per_request_min_duration = 3 diff --git a/radicale/config.py b/radicale/config.py index 5ec5908f..cf59bcd1 100644 --- a/radicale/config.py +++ b/radicale/config.py @@ -41,12 +41,12 @@ from radicale import auth, hook, rights, storage, types, web from radicale.hook import email from radicale.item import check_and_sanitize_props -from radicale import app # isort:skip (circular import issue) - DEFAULT_CONFIG_PATH: str = os.pathsep.join([ "?/etc/radicale/config", "?~/.config/radicale/config"]) +PROFILING: Sequence[str] = ("per_request", "per_request_method", "none") + def positive_int(value: Any) -> int: value = int(value) @@ -72,6 +72,12 @@ def logging_level(value: Any) -> str: return value +def profiling(value: Any) -> str: + if value not in PROFILING: + raise ValueError("unsupported profiling: %r" % value) + return value + + def filepath(value: Any) -> str: if not value: return "" @@ -584,10 +590,9 @@ This is an automated message. Please do not reply.""", "help": "log storage cache action on level=debug", "type": bool}), ("profiling", { - "value": "per_request_method", + "value": "none", "help": "log profiling data level=info", - "type": str, - "internal": app.PROFILING}), + "type": profiling}), ("profiling_per_request_min_duration", { "value": "3", "help": "log profiling data per request minimum duration (seconds)", From 2df265617b2cdab1f40d316d7e887cef61b34e42 Mon Sep 17 00:00:00 2001 From: Peter Bieringer Date: Mon, 8 Dec 2025 17:55:11 +0100 Subject: [PATCH 07/10] profiling: fix for 'none' --- radicale/app/__init__.py | 17 +++++++---------- 1 file changed, 7 insertions(+), 10 deletions(-) diff --git a/radicale/app/__init__.py b/radicale/app/__init__.py index 882787ec..d5d480e2 100644 --- a/radicale/app/__init__.py +++ b/radicale/app/__init__.py @@ -36,7 +36,7 @@ import random import time import zlib from http import client -from typing import Iterable, List, Mapping, Sequence, Tuple, Union +from typing import Iterable, List, Mapping, Tuple, Union from radicale import config, httputils, log, pathutils, types from radicale.app.base import ApplicationBase @@ -60,8 +60,6 @@ _IntermediateResponse = Tuple[str, List[Tuple[str, str]], Iterable[bytes]] REQUEST_METHODS = ["DELETE", "GET", "HEAD", "MKCALENDAR", "MKCOL", "MOVE", "OPTIONS", "POST", "PROPFIND", "PROPPATCH", "PUT", "REPORT"] -PROFILING: Sequence[str] = ("per_request", "per_request_method") - class Application(ApplicationPartDelete, ApplicationPartHead, ApplicationPartGet, ApplicationPartMkcalendar, @@ -134,14 +132,13 @@ class Application(ApplicationPartDelete, ApplicationPartHead, self._profiling_per_request_min_duration = configuration.get("logging", "profiling_per_request_min_duration") self._profiling_per_request_method_interval = configuration.get("logging", "profiling_per_request_method_interval") self._profiling_top_x_functions = configuration.get("logging", "profiling_top_x_functions") - if self._profiling == "per_request": - self._profiling_per_request = True - elif self._profiling == "per_request_method": - self._profiling_per_request_method = True - else: - logger.warning("profiling: %s (not supported, disabled)", self._profiling) - if self._profiling_per_request or self._profiling_per_request_method: + if self._profiling in config.PROFILING: logger.info("profiling: %s", self._profiling) + if self._profiling == "per_request": + self._profiling_per_request = True + elif self._profiling == "per_request_method": + self._profiling_per_request_method = True + if self._profiling_per_request or self._profiling_per_request_method: logger.info("profiling top X functions: %d", self._profiling_top_x_functions) if self._profiling_per_request: logger.info("profiling per request minimum duration: %d (below are skipped)", self._profiling_per_request_min_duration) From 5fbd838eab0e762867d29f29307738d4dfc7e300 Mon Sep 17 00:00:00 2001 From: Peter Bieringer Date: Mon, 8 Dec 2025 18:41:43 +0100 Subject: [PATCH 08/10] profiling: cosmetics/alignment --- radicale/app/__init__.py | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/radicale/app/__init__.py b/radicale/app/__init__.py index d5d480e2..9b3c9ba3 100644 --- a/radicale/app/__init__.py +++ b/radicale/app/__init__.py @@ -166,12 +166,12 @@ class Application(ApplicationPartDelete, ApplicationPartHead, s = io.StringIO() stats = pstats.Stats(self.profiler_per_request_method[method], stream=s).sort_stats('cumulative') stats.print_stats(self._profiling_top_x_functions) # Print top X functions - logger.info("Profiling data per request method after %d seconds and %d requests: %s: %s", profiler_timedelta_start, self.profiler_per_request_method_counter[method], method, s.getvalue()) + logger.info("Profiling data per request method %s after %d seconds and %d requests: %s", method, profiler_timedelta_start, self.profiler_per_request_method_counter[method], s.getvalue()) else: if shutdown: - logger.info("Profiling data per request method after %d seconds: %s: (no requests seen so far)", profiler_timedelta_start, method) + logger.info("Profiling data per request method %s after %d seconds: (no request seen so far)", method, profiler_timedelta_start) else: - logger.debug("Profiling data per request method after %d seconds: %s: (no requests seen so far)", profiler_timedelta_start, method) + logger.debug("Profiling data per request method %s after %d seconds: (no request seen so far)", method, profiler_timedelta_start) def _scrub_headers(self, environ: types.WSGIEnviron) -> types.WSGIEnviron: """Mask passwords and cookies.""" @@ -268,14 +268,14 @@ class Application(ApplicationPartDelete, ApplicationPartHead, if profiler is not None: # Profiling per request if time_delta_seconds < self._profiling_per_request_min_duration: - logger.debug("Profiling data %s response for %r%s: (supressed because duration below minimum %.3f < %.3f)", request_method, unsafe_path, depthinfo, time_delta_seconds, self._profiling_per_request_min_duration) + logger.debug("Profiling data per request %s for %r%s: (suppressed because duration below minimum %.3f < %.3f)", request_method, unsafe_path, depthinfo, time_delta_seconds, self._profiling_per_request_min_duration) else: s = io.StringIO() stats = pstats.Stats(profiler, stream=s).sort_stats('cumulative') stats.print_stats(self._profiling_top_x_functions) # Print top X functions - logger.info("Profiling data %s response for %r%s: %s", request_method, unsafe_path, depthinfo, s.getvalue()) + logger.info("Profiling data per request %s for %r%s: %s", request_method, unsafe_path, depthinfo, s.getvalue()) else: - logger.debug("Profiling data %s response for %r%s: (supressed because of no data)", request_method, unsafe_path, depthinfo) + logger.debug("Profiling data per request %s for %r%s: (suppressed because of no data)", request_method, unsafe_path, depthinfo) elif self._profiling_per_request_method: self.profiler_per_request_method[request_method].disable() self.profiler_per_request_method_counter[request_method] += 1 From 2ff6f188176bacaa281e5dcfaf0ebf85c4edaaef Mon Sep 17 00:00:00 2001 From: Peter Bieringer Date: Mon, 8 Dec 2025 18:42:02 +0100 Subject: [PATCH 09/10] profiling: logwatch extension (incl. skip not interesting lines) --- contrib/logwatch/radicale | 24 ++++++++++++++++++++++++ 1 file changed, 24 insertions(+) diff --git a/contrib/logwatch/radicale b/contrib/logwatch/radicale index 7cc1b1b8..1cdddc30 100644 --- a/contrib/logwatch/radicale +++ b/contrib/logwatch/radicale @@ -126,11 +126,35 @@ while (defined($ThisLine = )) { elsif ( $ThisLine =~ / (Failed login attempt) /o ) { $OtherEvents{$1}++; } + elsif ( $ThisLine =~ / (Profiling data per request method \S+) /o ) { + my $info = $1; + if ( $ThisLine =~ /(no request seen so far)/o ) { + $OtherEvents{$info . " - " . $1}++; + } else { + $OtherEvents{$info}++; + }; + } + elsif ( $ThisLine =~ / (Profiling data per request \S+) /o ) { + my $info = $1; + if ( $ThisLine =~ /(suppressed because duration below minimum|suppressed because of no data)/o ) { + $OtherEvents{$info . " - " . $1}++; + } else { + $OtherEvents{$info}++; + }; + } elsif ( $ThisLine =~ /\[(DEBUG|INFO)\] /o ) { # skip if DEBUG+INFO } else { # Report any unmatched entries... + if ($ThisLine =~ /^({\'| )/o) { + # skip profiling or raw header data + next; + }; + if ($ThisLine =~ /^$/o) { + # skip empty line + next; + }; $ThisLine =~ s/^\[\d+(\/Thread-\d+)?\] //; # remove process/Thread ID chomp($ThisLine); $OtherList{$ThisLine}++; From 5fb844b924e0ed44f939bd10d1cdfdb6c8469afd Mon Sep 17 00:00:00 2001 From: Peter Bieringer Date: Mon, 8 Dec 2025 18:54:46 +0100 Subject: [PATCH 10/10] profiling: add config hint --- config | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/config b/config index 290fa368..781c4edf 100644 --- a/config +++ b/config @@ -328,7 +328,7 @@ # Log profiling data per request minium duration (seconds) #profiling_per_request_min_duration = 3 -# Log profiling data per request method interval +# Log profiling data per request method interval (seconds) #profiling_per_request_method_interval = 600 # Log profiling top X functions (limit)