Performance logging: push into development.py (i.e. remove from non-development servers)

bugsink/middleware.py

@@ -48,8 +48,7 @@ class PerformanceStatsMiddleware:
         t0 = time()
         result = view_func(request, *view_args, **view_kwargs)
         took = (time() - t0) * 1000
-        if took > 1 and not request.path.startswith("/static"):
-            performance_logger.info(
-                f"    {took:6.2f}ms / {len(connection.queries)} queries: '{ view_func.__name__ }' ↴")
+        if not request.path.startswith("/static"):
+            performance_logger.info(f"{took:6.2f}ms / {len(connection.queries)} queries: '{ view_func.__name__ }'")
 
         return result

bugsink/settings/default.py

@@ -192,11 +192,19 @@ if I_AM_RUNNING != "TEST":
     # DEBUG=False and we don't want the visual pollution.
     LOGGING['handlers']['console']['filters'] = []
 
+# Top-level bugsink logger
 LOGGING['loggers']['bugsink'] = {
     "level": "INFO",
     "handlers": ["console"],
 }
 
+# Performance logging is hidden by default, but it can be enabled by adding a handler to the logger.
+LOGGING['loggers']['bugsink.performance'] = {
+    "level": "INFO",
+    "handlers": [],
+    "propagate": False,
+}
+
 # Snappea Logging
 LOGGING["formatters"]["snappea"] = {
     "format": "{threadName} - {levelname:7} - {message}",
@@ -205,11 +213,10 @@ LOGGING["formatters"]["snappea"] = {
 
 LOGGING["handlers"]["snappea"] = {
     "level": "INFO",
-    "class": "logging.StreamHandler"
+    "class": "logging.StreamHandler",
+    "formatter": "snappea",
 }
 
-LOGGING["handlers"]["snappea"]["formatter"] = "snappea"
-
 LOGGING['loggers']['snappea'] = {
     "level": "INFO",
     "handlers": ["snappea"],

bugsink/settings/development.py

@@ -93,8 +93,23 @@ BUGSINK = {
     "SITE_TITLE": "Bugsink",  # you can customize this as e.g. "My Bugsink" or "Bugsink for My Company"
 }
 
+
+# performance development settings: show inline in the console, with a nice little arrow
+LOGGING["formatters"]["performance"] = {
+    "format": "    {message} ↴",
+    "style": "{",
+}
+
+LOGGING["handlers"]["performance"] = {
+    "level": "INFO",
+    "class": "logging.StreamHandler",
+    "formatter": "performance",
+}
+
+LOGGING['loggers']['bugsink.performance']["handlers"] = ["performance"]
+
+
+# snappea development settings: see all details, and include timestamps (we have no sytemd journal here)
 LOGGING["handlers"]["snappea"]["level"] = "DEBUG"
 LOGGING["loggers"]["snappea"]["level"] = "DEBUG"
-
-# include timestamps too
 LOGGING["formatters"]["snappea"]["format"] = "{asctime} - {threadName} - {levelname:7} - {message}"

bugsink/transaction.py

@@ -109,14 +109,14 @@ class ImmediateAtomic(SuperDurableAtomic):
         self.t0 = time.time()
         super(ImmediateAtomic, self).__enter__()
         took = (time.time() - self.t0) * 1_000
-        performance_logger.info(f"    {took:6.2f}ms BEGIN IMMEDIATE, A.K.A. get-write-lock' ↴")
+        performance_logger.info(f"{took:6.2f}ms BEGIN IMMEDIATE, A.K.A. get-write-lock'")
         self.t0 = time.time()
 
     def __exit__(self, exc_type, exc_value, traceback):
         super(ImmediateAtomic, self).__exit__(exc_type, exc_value, traceback)
 
         took = (time.time() - self.t0) * 1000
-        performance_logger.info(f"    {took:6.2f}ms IMMEDIATE transaction' ↴")
+        performance_logger.info(f"{took:6.2f}ms IMMEDIATE transaction'")
 
         connection = django_db_transaction.get_connection(self.using)
         if hasattr(connection, "_start_transaction_under_autocommit"):

snappea/foreman.py

@@ -248,7 +248,7 @@ class Foreman:
             self.check_for_stopping()  # check_for_stopping() right before taking on the work
 
             # 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
+            # * no explicit transaction needed, autocommit is fine: we're the only ones touching this row in the DB
             # * delete-before-run is the implementation of our at-most-once guarantee
             task.delete()
             self.run_in_thread(task_id, function, *args, **kwargs)