From f266b207df48d0c46c32b99f4ea7532219ad4b13 Mon Sep 17 00:00:00 2001 From: Kiran Jonnalagadda Date: Fri, 28 Jul 2023 15:58:55 +0530 Subject: [PATCH] Log template rendering time to statsd --- pyproject.toml | 1 - src/baseframe/statsd.py | 74 ++++++++++++++++++++++++---- tests/baseframe_tests/statsd_test.py | 54 +++++++++++++++++++- 3 files changed, 117 insertions(+), 12 deletions(-) diff --git a/pyproject.toml b/pyproject.toml index 5665b583..40a54299 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -123,7 +123,6 @@ sections = [ [tool.mypy] files = '**/*.py' exclude = 'node_modules' -plugins = ['sqlalchemy.ext.mypy.plugin'] ignore_missing_imports = true show_error_codes = true warn_unreachable = true diff --git a/src/baseframe/statsd.py b/src/baseframe/statsd.py index ed31d797..b1fd9e72 100644 --- a/src/baseframe/statsd.py +++ b/src/baseframe/statsd.py @@ -4,8 +4,18 @@ import typing as t from datetime import timedelta -from flask import Flask, current_app, request, request_finished, request_started +from flask import ( + Flask, + before_render_template, + current_app, + g, + request, + request_finished, + request_started, + template_rendered, +) from flask_wtf import FlaskForm +from jinja2 import Template from statsd import StatsClient from statsd.client.timer import Timer from statsd.client.udp import Pipeline @@ -15,7 +25,8 @@ __all__ = ['Statsd'] -START_TIME_ATTR = 'statsd_start_time' +REQUEST_START_TIME_ATTR = 'statsd_request_start_time' +TEMPLATE_START_TIME_ATTR = 'statsd_template_start_time' TagsType = t.Dict[str, t.Union[int, str, None]] @@ -41,6 +52,7 @@ class Statsd: STATSD_RATE = 1 STATSD_TAGS = False STATSD_REQUEST_LOG = True + STATSD_RENDERTEMPLATE_LOG = True STATSD_FORM_LOG = True If the statsd server supports tags, the ``STATSD_TAGS`` parameter may be set to a @@ -92,6 +104,11 @@ def init_app(self, app: Flask) -> None: request_started.connect(self._request_started, app) request_finished.connect(self._request_finished, app) + if app.config.setdefault('STATSD_RENDERTEMPLATE_LOG', True): + # Flask's render_template also sends before and after signals + before_render_template.connect(self._before_render_template, app) + template_rendered.connect(self._template_rendered, app) + def _metric_name(self, name: str, tags: t.Optional[TagsType] = None) -> str: if tags is None: tags = {} @@ -209,10 +226,11 @@ def pipeline(self) -> Pipeline: def _request_started(self, app: Flask) -> None: if app.config['STATSD_RATE'] != 0: - setattr(request, START_TIME_ATTR, time.time()) + setattr(g, REQUEST_START_TIME_ATTR, time.time()) def _request_finished(self, app: Flask, response: Response) -> None: - if hasattr(request, START_TIME_ATTR): + if hasattr(g, REQUEST_START_TIME_ATTR): + start_time = getattr(g, REQUEST_START_TIME_ATTR) metrics = [ ( 'request_handlers', @@ -226,20 +244,56 @@ def _request_finished(self, app: Flask, response: Response) -> None: {'endpoint': '_overall', 'status_code': response.status_code}, ) ) - + duration = int((time.time() - start_time) * 1000) for metric_name, tags in metrics: # Use `timing` instead of `timer` because we record it as two metrics. # Convert time from seconds:float to milliseconds:int - self.timing( - metric_name, - int((time.time() - getattr(request, START_TIME_ATTR)) * 1000), - tags=tags, - ) + self.timing(metric_name, duration, tags=tags) # The timer metric also registers a count, making the counter metric # seemingly redundant, but the counter metric also includes a rate, so # we use both: timer (via `timing`) and counter (via `incr`). self.incr(metric_name, tags=tags) + def _before_render_template(self, app: Flask, template: Template, **kwargs) -> None: + if app.config['STATSD_RATE'] != 0: + if not hasattr(g, TEMPLATE_START_TIME_ATTR): + setattr(g, TEMPLATE_START_TIME_ATTR, {}) + getattr(g, TEMPLATE_START_TIME_ATTR)[template] = time.time() + + def _template_rendered(self, app: Flask, template: Template, **kwargs) -> None: + start_time = getattr(g, TEMPLATE_START_TIME_ATTR, {}).get(template) + if not start_time: + current_app.logger.warning( + "flask.template_rendered signal was called with template %s but" + " flask.before_render_template was not called first", + template, + ) + return + + metrics: t.List[t.Tuple[str, t.Dict[str, t.Optional[t.Union[int, str]]]]] = [ + ( + 'render_template', + {'template': template.name or '_str'}, + ) + ] + if not app.config['STATSD_TAGS']: + metrics.append( + ( + 'render_template', + {'template': '_overall'}, + ) + ) + + duration = int((time.time() - start_time) * 1000) + for metric_name, tags in metrics: + # Use `timing` instead of `timer` because we record it as two metrics. + # Convert time from seconds:float to milliseconds:int + self.timing(metric_name, duration, tags=tags) + # The timer metric also registers a count, making the counter metric + # seemingly redundant, but the counter metric also includes a rate, so + # we use both: timer (via `timing`) and counter (via `incr`). + self.incr(metric_name, tags=tags) + @form_validation_success.connect def _statsd_form_validation_success(form: FlaskForm) -> None: diff --git a/tests/baseframe_tests/statsd_test.py b/tests/baseframe_tests/statsd_test.py index dc148ae6..6060204a 100644 --- a/tests/baseframe_tests/statsd_test.py +++ b/tests/baseframe_tests/statsd_test.py @@ -7,7 +7,7 @@ from unittest.mock import patch import pytest -from flask import Flask +from flask import Flask, render_template_string from flask_babel import Babel from statsd.client.timer import Timer from statsd.client.udp import Pipeline @@ -285,6 +285,58 @@ def test_request_handler_disabled(app, view) -> None: mock_timing.assert_not_called() +def test_render_template_notags(app, statsd) -> None: + with patch('statsd.StatsClient.incr') as mock_incr: + with patch('statsd.StatsClient.timing') as mock_timing: + with app.app_context(): + render_template_string("Test template") + assert mock_incr.call_count == 2 + assert mock_timing.call_count == 2 + assert [c.args[0] for c in mock_incr.call_args_list] == [ + 'flask_app.baseframe_tests.statsd_test.render_template' + '.template__str', + 'flask_app.baseframe_tests.statsd_test.render_template' + '.template__overall', + ] + assert [c.args[0] for c in mock_incr.call_args_list] == [ + 'flask_app.baseframe_tests.statsd_test.render_template' + '.template__str', + 'flask_app.baseframe_tests.statsd_test.render_template' + '.template__overall', + ] + + +def test_render_template_tags(app, statsd) -> None: + app.config['STATSD_TAGS'] = ',' + with patch('statsd.StatsClient.incr') as mock_incr: + with patch('statsd.StatsClient.timing') as mock_timing: + with app.app_context(): + render_template_string("Test template") + assert mock_incr.call_count == 1 + assert mock_timing.call_count == 1 + assert ( + mock_incr.call_args.args[0] + == 'flask_app.render_template,template=_str,' + 'app=baseframe_tests.statsd_test' + ) + assert ( + mock_incr.call_args.args[0] + == 'flask_app.render_template,template=_str,' + 'app=baseframe_tests.statsd_test' + ) + + +def test_render_template_disabled(app, view) -> None: + app.config['STATSD_RENDERTEMPLATE_LOG'] = False + Statsd(app) + with patch('statsd.StatsClient.incr') as mock_incr: + with patch('statsd.StatsClient.timing') as mock_timing: + with app.app_context(): + render_template_string("Test template") + mock_incr.assert_not_called() + mock_timing.assert_not_called() + + def test_form_success(ctx, app, statsd, form) -> None: app.config['STATSD_TAGS'] = ',' with patch('statsd.StatsClient.incr') as mock_incr: