From 1437bc3092fbba8323e54d4d694df6476c778229 Mon Sep 17 00:00:00 2001 From: Ben Rog-Wilhelm Date: Thu, 10 Nov 2022 19:17:30 -0600 Subject: [PATCH] Rig up a query-frequency analyzer with the most commonly seen callstack, including Jinja demangling. --- Dockerfile | 5 ++- files/__main__.py | 36 +++++++++++++++++++ pyproject.toml | 5 +++ .../easy_profile/middleware.py | 8 +++-- .../easy_profile/profiler.py | 17 +++++++-- .../easy_profile/reporters.py | 5 ++- 6 files changed, 69 insertions(+), 7 deletions(-) diff --git a/Dockerfile b/Dockerfile index 7878d2263..c02b26cea 100644 --- a/Dockerfile +++ b/Dockerfile @@ -26,7 +26,10 @@ CMD [ "/usr/bin/supervisord", "-c", "/etc/supervisord.conf" ] ################################################################### # Dev container FROM release AS dev -# we don't actually do anything different yet + +# Install our tweaked sqlalchemy-easy-profile +COPY thirdparty/sqlalchemy-easy-profile sqlalchemy-easy-profile +RUN cd sqlalchemy-easy-profile && python3 setup.py install ################################################################### diff --git a/files/__main__.py b/files/__main__.py index e7675f6ee..253985805 100644 --- a/files/__main__.py +++ b/files/__main__.py @@ -48,6 +48,42 @@ if environ.get("FLASK_PROFILER_ENDPOINT"): profiler = flask_profiler.Profiler() profiler.init_app(app) +try: + from easy_profile import EasyProfileMiddleware + from jinja2.utils import internal_code + + import inspect as inspectlib + import linecache + + def jinja_unmangle_stacktrace(): + rewritten_frames = [] + + for record in inspectlib.stack(): + # Skip jinja internalcode frames + if record.frame.f_code in internal_code: + continue + + filename = record.frame.f_code.co_filename + lineno = record.frame.f_lineno + name = record.frame.f_code.co_name + + template = record.frame.f_globals.get("__jinja_template__") + if template is not None: + lineno = template.get_corresponding_lineno(lineno) + + line = linecache.getline(filename, lineno).strip() + + rewritten_frames.append(f' File "{filename}", line {lineno}, {name}\n {line}\n') + + return "".join(rewritten_frames) + + app.wsgi_app = EasyProfileMiddleware( + app.wsgi_app, + stack_callback = jinja_unmangle_stacktrace) +except ModuleNotFoundError: + # failed to import, just keep on going + pass + app.config["SITE_ID"]=environ.get("SITE_ID").strip() app.config["SITE_TITLE"]=environ.get("SITE_TITLE").strip() app.config['SQLALCHEMY_TRACK_MODIFICATIONS'] = False diff --git a/pyproject.toml b/pyproject.toml index 5beb25604..c34235db6 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -44,3 +44,8 @@ pytest = "*" [build-system] requires = ["poetry-core>=1.0.0"] build-backend = "poetry.core.masonry.api" + +[tool.pytest.ini_options] +norecursedirs = [ + "thirdparty/*", +] diff --git a/thirdparty/sqlalchemy-easy-profile/easy_profile/middleware.py b/thirdparty/sqlalchemy-easy-profile/easy_profile/middleware.py index 9d6d5af89..b94c4af5f 100644 --- a/thirdparty/sqlalchemy-easy-profile/easy_profile/middleware.py +++ b/thirdparty/sqlalchemy-easy-profile/easy_profile/middleware.py @@ -1,4 +1,5 @@ import re +import traceback from .profiler import SessionProfiler from .reporters import Reporter, StreamReporter @@ -23,7 +24,8 @@ class EasyProfileMiddleware(object): reporter=None, exclude_path=None, min_time=0, - min_query_count=1): + min_query_count=1, + stack_callback=None): if reporter: if not isinstance(reporter, Reporter): @@ -37,9 +39,10 @@ class EasyProfileMiddleware(object): self.exclude_path = exclude_path or [] self.min_time = min_time self.min_query_count = min_query_count + self.stack_callback = stack_callback def __call__(self, environ, start_response): - profiler = SessionProfiler(self.engine) + profiler = SessionProfiler(self.engine, stack_callback=self.stack_callback) path = environ.get("PATH_INFO", "") if not self._ignore_request(path): method = environ.get("REQUEST_METHOD") @@ -61,3 +64,4 @@ class EasyProfileMiddleware(object): if (stats["total"] >= self.min_query_count and stats["duration"] >= self.min_time): self.reporter.report(path, stats) + diff --git a/thirdparty/sqlalchemy-easy-profile/easy_profile/profiler.py b/thirdparty/sqlalchemy-easy-profile/easy_profile/profiler.py index ce5793a5c..a0d039493 100644 --- a/thirdparty/sqlalchemy-easy-profile/easy_profile/profiler.py +++ b/thirdparty/sqlalchemy-easy-profile/easy_profile/profiler.py @@ -5,6 +5,8 @@ from queue import Queue import re import sys import time +import traceback +import pprint from sqlalchemy import event from sqlalchemy.engine.base import Engine @@ -32,7 +34,7 @@ def _get_object_name(obj): _DebugQuery = namedtuple( - "_DebugQuery", "statement,parameters,start_time,end_time" + "_DebugQuery", "statement,parameters,start_time,end_time,callstack" ) @@ -57,7 +59,7 @@ class SessionProfiler: _before = "before_cursor_execute" _after = "after_cursor_execute" - def __init__(self, engine=None): + def __init__(self, engine=None, stack_callback=None): if engine is None: self.engine = Engine self.db_name = "default" @@ -70,6 +72,8 @@ class SessionProfiler: self._stats = None + self._stack_callback = stack_callback or self._stack_callback_default + def __enter__(self): self.begin() @@ -160,6 +164,9 @@ class SessionProfiler: self._stats["duration"] += query.duration duplicates = self._stats["duplicates"].get(query.statement, -1) self._stats["duplicates"][query.statement] = duplicates + 1 + if query.statement not in self._stats["callstacks"]: + self._stats["callstacks"][query.statement] = Counter() + self._stats["callstacks"][query.statement].update({query.callstack: 1}) return self._stats @@ -174,6 +181,7 @@ class SessionProfiler: self._stats["duration"] = 0 self._stats["call_stack"] = [] self._stats["duplicates"] = Counter() + self._stats["callstacks"] = {} def _before_cursor_execute(self, conn, cursor, statement, parameters, context, executemany): @@ -182,5 +190,8 @@ class SessionProfiler: def _after_cursor_execute(self, conn, cursor, statement, parameters, context, executemany): self.queries.put(DebugQuery( - statement, parameters, context._query_start_time, _timer() + statement, parameters, context._query_start_time, _timer(), self._stack_callback() )) + + def _stack_callback_default(self): + return ''.join(traceback.format_stack()) diff --git a/thirdparty/sqlalchemy-easy-profile/easy_profile/reporters.py b/thirdparty/sqlalchemy-easy-profile/easy_profile/reporters.py index d1c77a7bc..e13f984fa 100644 --- a/thirdparty/sqlalchemy-easy-profile/easy_profile/reporters.py +++ b/thirdparty/sqlalchemy-easy-profile/easy_profile/reporters.py @@ -86,6 +86,8 @@ class StreamReporter(Reporter): summary = "Total queries: {0} in {1:.3}s".format(total, duration) output += self._info_line("\n{0}\n".format(summary), total) + callstacks = stats["callstacks"] + # Display duplicated sql statements. # # Get top counters were value greater than 1 and write to @@ -95,11 +97,12 @@ class StreamReporter(Reporter): for statement, count in most_common: if count < 1: continue + callstack = callstacks[statement].most_common(1) # Wrap SQL statement and returning a list of wrapped lines statement = sqlparse.format( statement, reindent=True, keyword_case="upper" ) - text = "\nRepeated {0} times:\n{1}\n".format(count + 1, statement) + text = "\nRepeated {0} times:\n{1}\nMost common callstack {2} times:\n{3}\n".format(count + 1, statement, callstack[0][1], callstack[0][0]) output += self._info_line(text, count) self._file.write(output)