Merge pull request #1934 from pbiering/add-profiling

Add profiling support

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

DOCUMENTATION.md

@@ -1690,6 +1690,44 @@ Log storage cache actions on `level = debug`
 
 Default: `False`
 
+##### profiling_per_request
+
+_(>= 3.5.10)_
+
+Log profiling data on level=info
+
+Default: `none`
+
+One of
+* `none` (disabled)
+* `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.

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 | none
+#profiling = none
+
+# Log profiling data per request minium duration (seconds)
+#profiling_per_request_min_duration = 3
+
+# Log profiling data per request method interval (seconds)
+#profiling_per_request_method_interval = 600
+
+# Log profiling top X functions (limit)
+#profiling_top_x_functions = 10
+
+
 [headers]
 
 # Additional HTTP headers

contrib/logwatch/radicale

@@ -126,11 +126,35 @@ while (defined($ThisLine = <STDIN>)) {
    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}++;

radicale/app/__init__.py

@@ -27,8 +27,11 @@ 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
@@ -55,6 +58,8 @@ 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"]
+
 
 class Application(ApplicationPartDelete, ApplicationPartHead,
                   ApplicationPartGet, ApplicationPartMkcalendar,
@@ -73,6 +78,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 +127,51 @@ 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 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)
+        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 %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 %s after %d seconds: (no request seen so far)", method, profiler_timedelta_start)
+                else:
+                    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."""
@@ -156,6 +212,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 +251,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 +261,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 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 per request %s for %r%s: %s", request_method, unsafe_path, depthinfo, s.getvalue())
+                else:
+                    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
+                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 +450,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")

radicale/config.py

@@ -45,6 +45,8 @@ 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)
@@ -70,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 ""
@@ -581,6 +589,22 @@ This is an automated message. Please do not reply.""",
             "value": "False",
             "help": "log storage cache action on level=debug",
             "type": bool}),
+        ("profiling", {
+            "value": "none",
+            "help": "log profiling data level=info",
+            "type": 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",