Merge pull request #1766 from matrix-org/markjh/linear_logging

More logging for the linearizer and for get_events

synapse/storage/events.py

@@ -1084,8 +1084,10 @@ class EventsStore(SQLBaseStore):
                     self._do_fetch
                 )
 
+        logger.info("Loading %d events", len(events))
         with PreserveLoggingContext():
             rows = yield events_d
+        logger.info("Loaded %d events (%d rows)", len(events), len(rows))
 
         if not allow_rejected:
             rows[:] = [r for r in rows if not r["rejects"]]

synapse/util/async.py

@@ -166,7 +166,11 @@ class Linearizer(object):
             # do some work.
 
     """
-    def __init__(self):
+    def __init__(self, name=None):
+        if name is None:
+            self.name = id(self)
+        else:
+            self.name = name
         self.key_to_defer = {}
 
     @defer.inlineCallbacks
@@ -185,15 +189,20 @@ class Linearizer(object):
         self.key_to_defer[key] = new_defer
 
         if current_defer:
-            logger.info("Waiting to acquire linearizer lock for key %r", key)
+            logger.info(
+                "Waiting to acquire linearizer lock %r for key %r", self.name, key
+            )
             with PreserveLoggingContext():
                 yield current_defer
 
+        logger.info("Acquired linearizer lock %r for key %r", self.name, key)
+
         @contextmanager
         def _ctx_manager():
             try:
                 yield
             finally:
+                logger.info("Releasing linearizer lock %r for key %r", self.name, key)
                 new_defer.callback(None)
                 current_d = self.key_to_defer.get(key)
                 if current_d is new_defer: