From dd3df11c5524441db3c9dd638ea59432d6f3d118 Mon Sep 17 00:00:00 2001 From: Mark Haines Date: Thu, 5 Jan 2017 12:32:47 +0000 Subject: [PATCH] More logging for the linearizer and for get_events --- synapse/storage/events.py | 2 ++ synapse/util/async.py | 13 +++++++++++-- 2 files changed, 13 insertions(+), 2 deletions(-) diff --git a/synapse/storage/events.py b/synapse/storage/events.py index ecb79c07e..04dbdac3f 100644 --- a/synapse/storage/events.py +++ b/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"]] diff --git a/synapse/util/async.py b/synapse/util/async.py index 4280455cb..83875edc8 100644 --- a/synapse/util/async.py +++ b/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: