Log template rendering time to statsd (#431)

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 = {}
@@ -207,12 +224,16 @@ def set(  # noqa: A003
     def pipeline(self) -> Pipeline:
         return current_app.extensions['statsd_core'].pipeline()
 
-    def _request_started(self, app: Flask) -> None:
+    @staticmethod
+    def _request_started(app: Flask) -> None:
+        """Record start time when serving a request."""
         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):
+        """Calculate time to render a response and log to statsd."""
+        if hasattr(g, REQUEST_START_TIME_ATTR):
+            start_time = getattr(g, REQUEST_START_TIME_ATTR)
             metrics = [
                 (
                     'request_handlers',
@@ -226,20 +247,59 @@ 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)
 
+    @staticmethod
+    def _before_render_template(app: Flask, template: Template, **kwargs) -> None:
+        """Record start time when rendering a template."""
+        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:
+        """Calculate time to render a template and log to statsd."""
+        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/forms/fields_test.py

@@ -20,8 +20,6 @@ class MY_ENUM(LabeledEnum):  # noqa: N801
     SECOND = (2, 'second', "Second")
     THIRD = (3, 'third', "Third")
 
-    __order__ = (FIRST, SECOND, THIRD)
-
 
 DEFAULT_JSONDATA = {'key': "val"}
 

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
@@ -238,51 +238,105 @@ def test_tags(app, ctx, statsd) -> None:
 
 
 def test_request_handler_notags(app, statsd, view) -> None:
-    with patch('statsd.StatsClient.incr') as mock_incr:
-        with patch('statsd.StatsClient.timing') as mock_timing:
-            with app.test_client() as client:
-                client.get('/')
-                # First call
-                mock_incr.assert_any_call(
-                    'flask_app.baseframe_tests.statsd_test.request_handlers'
-                    '.endpoint_index.status_code_200',
-                    1,
-                    rate=1,
-                )
-                # Second and last call
-                mock_incr.assert_called_with(
-                    'flask_app.baseframe_tests.statsd_test.request_handlers'
-                    '.endpoint__overall.status_code_200',
-                    1,
-                    rate=1,
-                )
-                mock_timing.assert_called()
+    """Test request_handlers logging with tags disabled."""
+    with patch('statsd.StatsClient.incr') as mock_incr, patch(
+        'statsd.StatsClient.timing'
+    ) as mock_timing, app.test_client() as client:
+        client.get('/')
+        # First call
+        mock_incr.assert_any_call(
+            'flask_app.baseframe_tests.statsd_test.request_handlers'
+            '.endpoint_index.status_code_200',
+            1,
+            rate=1,
+        )
+        # Second and last call
+        mock_incr.assert_called_with(
+            'flask_app.baseframe_tests.statsd_test.request_handlers'
+            '.endpoint__overall.status_code_200',
+            1,
+            rate=1,
+        )
+        mock_timing.assert_called()
 
 
 def test_request_handler_tags(app, statsd, view) -> None:
+    """Test request_handlers logging with tags enabled."""
     app.config['STATSD_TAGS'] = ','
-    with patch('statsd.StatsClient.incr') as mock_incr:
-        with patch('statsd.StatsClient.timing') as mock_timing:
-            with app.test_client() as client:
-                client.get('/')
-                mock_incr.assert_called_once_with(
-                    'flask_app.request_handlers,endpoint=index,status_code=200'
-                    ',app=baseframe_tests.statsd_test',
-                    1,
-                    rate=1,
-                )
-                mock_timing.assert_called_once()
+    with patch('statsd.StatsClient.incr') as mock_incr, patch(
+        'statsd.StatsClient.timing'
+    ) as mock_timing, app.test_client() as client:
+        client.get('/')
+        mock_incr.assert_called_once_with(
+            'flask_app.request_handlers,endpoint=index,status_code=200'
+            ',app=baseframe_tests.statsd_test',
+            1,
+            rate=1,
+        )
+        mock_timing.assert_called_once()
 
 
 def test_request_handler_disabled(app, view) -> None:
+    """Test request_handlers logging disabled."""
     app.config['STATSD_REQUEST_LOG'] = False
     Statsd(app)
-    with patch('statsd.StatsClient.incr') as mock_incr:
-        with patch('statsd.StatsClient.timing') as mock_timing:
-            with app.test_client() as client:
-                client.get('/')
-                mock_incr.assert_not_called()
-                mock_timing.assert_not_called()
+    with patch('statsd.StatsClient.incr') as mock_incr, patch(
+        'statsd.StatsClient.timing'
+    ) as mock_timing, app.test_client() as client:
+        client.get('/')
+        mock_incr.assert_not_called()
+        mock_timing.assert_not_called()
+
+
+def test_render_template_notags(app, statsd) -> None:
+    """Test render_template logging with tags disabled."""
+    with patch('statsd.StatsClient.incr') as mock_incr, patch(
+        'statsd.StatsClient.timing'
+    ) as mock_timing, app.app_context():
+        render_template_string("Test template")
+        assert mock_incr.call_count == 2
+        assert mock_timing.call_count == 2
+        assert [c[0][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[0][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:
+    """Test render_template logging with tags enabled."""
+    app.config['STATSD_TAGS'] = ','
+    with patch('statsd.StatsClient.incr') as mock_incr, patch(
+        'statsd.StatsClient.timing'
+    ) as mock_timing, 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[0][0] == 'flask_app.render_template,template=_str,'
+            'app=baseframe_tests.statsd_test'
+        )
+        assert (
+            mock_incr.call_args[0][0] == 'flask_app.render_template,template=_str,'
+            'app=baseframe_tests.statsd_test'
+        )
+
+
+def test_render_template_disabled(app, view) -> None:
+    """Test render_template logging disabled."""
+    app.config['STATSD_RENDERTEMPLATE_LOG'] = False
+    Statsd(app)
+    with patch('statsd.StatsClient.incr') as mock_incr, patch(
+        'statsd.StatsClient.timing'
+    ) as mock_timing, 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: