Log template rendering time to statsd

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

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:

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: