Performance logging of Snappea task create/delete

snappea/decorators.py

@@ -1,10 +1,14 @@
+import logging
 import json
 
-from . import registry
+from performance.context_managers import time_to_logger
 
+from . import registry
 from .models import Task, wakeup_server
 from .settings import get_settings
 
+performance_logger = logging.getLogger("bugsink.performance.snappea")
+
 
 def shared_task(function):
     def delayed_function(*args, **kwargs):
@@ -18,9 +22,12 @@ def shared_task(function):
             # the non-eager case either).
             return
 
-        # No need for a transaction: we just write something (not connected to any other object, and we will never touch
-        # it again).
-        Task.objects.create(task_name=name, args=json.dumps(args), kwargs=json.dumps(kwargs))
+        with time_to_logger(performance_logger, "Snappea Task.create()"):
+            # No need for a transaction: we just write something (not connected to any other object, and we will never
+            # touch it again). Counterpoint: if we'd have a transaction, we could distinguish between "wait for write
+            # lock" and "actually write".
+            Task.objects.create(task_name=name, args=json.dumps(args), kwargs=json.dumps(kwargs))
+
         wakeup_server()
 
     name = function.__module__ + "." + function.__name__

snappea/foreman.py

@@ -13,6 +13,7 @@ from sentry_sdk import capture_exception
 
 from django.conf import settings
 
+from performance.context_managers import time_to_logger
 from bugsink.transaction import durable_atomic
 
 from . import registry
@@ -20,8 +21,8 @@ from .models import Task
 from .datastructures import Workers
 from .settings import get_settings
 
-
 logger = logging.getLogger("snappea.foreman")
+performance_logger = logging.getLogger("bugsink.performance.snappea")
 
 
 def short_id(task_id):
@@ -241,7 +242,8 @@ class Foreman:
                 kwargs = json.loads(task.kwargs)
             except Exception as e:
                 logger.error('Create workers: can\'t execute "%s": %s', task.task_name, e)
-                task.delete()  # we delete the task because we can't do anything with it, and we don't want to hang
+                with time_to_logger(performance_logger, "Snappea delete Task"):
+                    task.delete()  # we delete the task because we can't do anything with it, and we don't want to hang
                 capture_exception(e)
                 continue
 
@@ -249,8 +251,10 @@ class Foreman:
 
             # notes on task.delete()  (mostly apply to task.delete in the except-statement above too)
             # * no explicit transaction needed, autocommit is fine: we're the only ones touching this row in the DB
+            #       (see 'counterpoint' in decorators.py for a counterpoint)
             # * delete-before-run is the implementation of our at-most-once guarantee
-            task.delete()
+            with time_to_logger(performance_logger, "Snappea Task.delete()"):
+                task.delete()
             self.run_in_thread(task_id, function, *args, **kwargs)
 
         task_count = task_i + 1