misc: add a record_timings utility decorator (#85102)

tests/form_pages/test_live.py

@@ -2635,4 +2635,4 @@ def test_field_live_too_long(pub, freezer):
         assert pub.loggederror_class.count() == 1
         logged_error = pub.loggederror_class.select()[0]
         assert logged_error.summary == '/live call is taking too long'
-        assert 'timings = {' in logged_error.traceback
+        assert 'timings = ' in logged_error.traceback

wcs/forms/common.py

@@ -34,6 +34,7 @@ from wcs.blocks import BlockSubWidget, BlockWidget
 from wcs.fields import FileField
 from wcs.qommon.admin.texts import TextsDirectory
 from wcs.qommon.upload_storage import get_storage_object
+from wcs.utils import record_timings
 from wcs.wf.editable import EditableWorkflowStatusItem
 from wcs.workflows import RedisplayFormException
 
@@ -812,26 +813,18 @@ class FormStatusPage(Directory, FormTemplateMixin):
         return redirect(file_url)
 
     @classmethod
+    @record_timings(name='/live call', record_if_over=5)
     def live_process_fields(cls, form, formdata, displayed_fields):
         if form is None:
             return json.dumps({'result': {}})
 
-        t0 = time.time()
-        timings = {'relative_start': get_request().get_duration()}
-
-        def add_timing(key):
-            nonlocal t0
-            new_t0 = time.time()
-            timings[key], t0 = '%.4f' % (new_t0 - t0), new_t0
-
-        def reset_timing():
-            nonlocal t0
-            t0 = time.time()
+        request = get_request()
+        request.add_timing_mark('relative_start')
 
         result = {}
         for field in displayed_fields:
             result[field.id] = {'visible': field.is_visible(formdata.data, formdata.formdef)}
-        add_timing('visibility')
+        request.add_timing_mark('visibility')
 
         modified_field_ids = get_request().form.get('modified_field_id[]') or []
         modified_field_varnames = set()
@@ -853,7 +846,7 @@ class FormStatusPage(Directory, FormTemplateMixin):
                 break
 
         for field in displayed_fields:
-            reset_timing()
+            t0 = time.time()
             if field.key in ('item', 'items') and field.data_source:
                 data_source = data_sources.get_object(field.data_source)
                 if data_source.type not in (
@@ -876,7 +869,7 @@ class FormStatusPage(Directory, FormTemplateMixin):
                         # but reduce payload weight by removing the API URLs
                         for options in result[field.id]['items']:
                             options.pop('api', None)
-                add_timing(f'item-options-{field.id}')
+                request.add_timing_mark(f'item-options-{field.id}', relative_start=t0)
 
         def get_all_field_widgets(form):
             for widget in form.widgets:
@@ -892,7 +885,7 @@ class FormStatusPage(Directory, FormTemplateMixin):
                             block_row += 1
 
         for block, block_row, field, widget in get_all_field_widgets(form):
-            reset_timing()
+            t0 = time.time()
             if block:
                 try:
                     block_data = formdata.data.get(block.id)['data'][block_row]
@@ -966,12 +959,9 @@ class FormStatusPage(Directory, FormTemplateMixin):
                     entry['content'] = value
                     entry['locked'] = locked
 
-            add_timing(f'field-block-{block.id}-row-{block_row}' if block else f'field-{field.id}')
-
-        if (get_request().get_duration() - timings['relative_start']) > 5:
-            # timings will be displayed in the traceback part of the error.
-            timings['total'] = get_request().get_duration()
-            get_publisher().record_error(_('/live call is taking too long'))
+            request.add_timing_mark(
+                f'field-block-{block.id}-row-{block_row}' if block else f'field-{field.id}', relative_start=t0
+            )
 
         return json.dumps({'result': result})
 

wcs/qommon/http_request.py

@@ -42,6 +42,7 @@ class HTTPRequest(quixote.http_request.HTTPRequest):
         self.ignore_session = False
         self.wscalls_cache = {}
         self.datasources_cache = {}
+        self.timings = []
         # keep a copy of environment to make sure it's not reused along
         # uwsgi/gunicorn processes.
         self.environ = copy.copy(self.environ)
@@ -252,3 +253,19 @@ class HTTPRequest(quixote.http_request.HTTPRequest):
 
     def get_duration(self):
         return time.time() - self.t0
+
+    def start_timing(self, name):
+        self.timings.append({'name': name, 'start': time.time()})
+        return self.timings[-1]
+
+    def stop_timing(self, timing):
+        timing['end'] = time.time()
+        timing['duration'] = timing['end'] - timing['start']
+        return timing['duration']
+
+    def add_timing_mark(self, name, relative_start=None):
+        timestamp = time.time()
+        duration = timestamp - (
+            relative_start or self.timings[-1].get('timestamp') or self.timings[-1].get('start')
+        )
+        self.timings.append({'mark': name, 'timestamp': timestamp, 'duration': duration})

wcs/utils.py

@@ -19,9 +19,10 @@ import os
 import re
 
 import django.template.loaders.filesystem
+from quixote import get_publisher, get_request
 
 from .qommon import _
-from .qommon.publisher import get_cfg, get_publisher
+from .qommon.publisher import get_cfg
 from .qommon.template import get_theme_directory
 
 
@@ -167,3 +168,26 @@ def grep_strings(string, hit_function):
                 else:
                     continue
                 break
+
+
+class record_timings:
+    def __init__(self, name=None, record_if_over=None):
+        self.record_if_over = record_if_over
+        self.name = name
+
+    def __call__(self, func):
+        name = self.name or func.__name__
+
+        def f(*args, **kwargs):
+            request = get_request()
+            timing = request.start_timing(name=name)
+            try:
+                return func(*args, **kwargs)
+            finally:
+                duration = request.stop_timing(timing)
+                if self.record_if_over and duration > self.record_if_over:
+                    # timings will be displayed in the traceback part of the error.
+                    timings = request.timings  # noqa pylint: disable=unused-variable
+                    get_publisher().record_error(_('%s is taking too long') % name)
+
+        return f