Add support for Python profiling of Server requests (#3502)

PBENCH-1228

Author: webbnh

lib/pbench/cli/server/shell.py

@@ -169,6 +169,17 @@ def run_gunicorn(server_config: PbenchServerConfig, logger: Logger) -> int:
         "pbench-server",
     ]
 
+    # If PB_PROFILE_DUMP_FILE is defined, enable profiling of the server's
+    # execution of requests.  If defined to an empty string, profiling
+    # results are dumped to the log; otherwise, the value is treated as the
+    # name of a file to receive the data.  (An excellent choice is
+    # "/srv/pbench/public_html/pbench_server.prof", because this is writable
+    # by the server and easily accessed by the user via the browser by hitting
+    # "https://<server>/pbench_server.prof".)  Note that the file is
+    # overwritten for each request.
+    if os.environ.get("PB_PROFILE_DUMP_FILE") is not None:
+        cmd_line += ["--config", "/opt/pbench-server/lib/pbench/profiling.conf.py"]
+
     # When installed via RPM, the shebang in the gunicorn script includes a -s
     # which prevents Python from implicitly including the user site packages in
     # the sys.path configuration.  (Note that, when installed via Pip, the

lib/pbench/profiling.conf.py

@@ -0,0 +1,70 @@
+"""Optional Gunicorn configuration file to enable profiling
+
+This module provides definitions for the pre-request and post-request Gunicorn
+hooks, which allow us to get control before a request begins executing and
+after it completes.  We use these to enable and disable profiling (so that the
+profile reflects only the single method call, with a minimum of extraneous
+execution), and, when the request is complete, we dump the profiling report to
+a file or to the log.
+
+This file is specified via a command line switch on the Gunicorn invocation
+when profiling is requested, and it is read by Gunicorn to set the
+`pre_request` and `post_request` Gunicorn settings to the hook routines
+defined below.
+"""
+
+import cProfile
+from io import StringIO
+import os
+import pstats
+import time
+
+from gunicorn.http import Request
+from gunicorn.workers import base
+
+
+def pre_request(worker: base.Worker, req: Request):
+    """Gunicorn hook function called before a request is executed
+
+    We create a profile context, notify the log that we're profiling (so that
+    no one is surprised), note the current time, and enable Python profiling.
+    (We hang the profile context and time stamp off the existing Gunicorn
+    worker object (ain't Python grand!?), and we use the worker's log.)
+    """
+    worker.profile = cProfile.Profile()
+    worker.log.info(f"PROFILING: {req.method} {req.uri}")
+    worker.start_time = time.time()
+    worker.profile.enable()
+
+
+def post_request(worker: base.Worker, req: Request, *_args):
+    """Gunicorn hook function called after a request is executed
+
+    Disable Python profiling; calculate the elapsed time for the request
+    execution and log it; dump the statistics to a file, or create a pstats
+    object which prints its output to a string-stream, sort the stats and print
+    them to the stream, and dump the contents of the stream to the log.  (We
+    pull the profile context and start time from where we hung them off the
+    Gunicorn worker object (ain't Python grand!?), and we use the worker's log.)
+    """
+    worker.profile.disable()
+
+    total_time = time.time() - worker.start_time
+    worker.log.info(f"Load Time: {total_time:.3}s {req.method} {req.uri}")
+
+    # If PB_PROFILE_DUMP_FILE is defined to a true-y value, assume that it is a
+    # file into which to dump the profile data.  (An excellent choice is
+    # "/srv/pbench/public_html/pbench_server.prof", because this is writable
+    # by the server and easily accessed by the user via the browser by hitting
+    # "https://<server>/pbench_server.prof".)  Otherwise, dump the top functions
+    # in the profile to the log.  (Note that, if PB_PROFILE_DUMP_FILE is
+    # undefined, profiling will not have been enabled, and we'll never get here.)
+    dump_file = os.environ.get("PB_PROFILE_DUMP_FILE")
+    if dump_file:
+        # Note that this will overwrite the previous request's data, if any.
+        worker.profile.dump_stats(dump_file)
+    else:
+        s = StringIO()
+        ps = pstats.Stats(worker.profile, stream=s).sort_stats("cumulative")
+        ps.print_stats(30)  # Limit the number of lines output
+        worker.log.info(s.getvalue())