diff --git a/synapse/federation/federation_server.py b/synapse/federation/federation_server.py index 3fa7b2315c..f4c60e67e3 100644 --- a/synapse/federation/federation_server.py +++ b/synapse/federation/federation_server.py @@ -538,7 +538,16 @@ class FederationServer(FederationBase): if get_missing and prevs - seen: # If we're missing stuff, ensure we only fetch stuff one # at a time. + logger.info( + "Acquiring lock for room %r to fetch %d missing events: %r...", + pdu.room_id, len(prevs - seen), list(prevs - seen)[:5], + ) with (yield self._room_pdu_linearizer.queue(pdu.room_id)): + logger.info( + "Acquired lock for room %r to fetch %d missing events", + pdu.room_id, len(prevs - seen), + ) + # We recalculate seen, since it may have changed. have_seen = yield self.store.have_events(prevs) seen = set(have_seen.keys()) diff --git a/synapse/util/async.py b/synapse/util/async.py index 16ed183d4c..4280455cbe 100644 --- a/synapse/util/async.py +++ b/synapse/util/async.py @@ -23,6 +23,10 @@ from synapse.util import unwrapFirstError from contextlib import contextmanager +import logging + +logger = logging.getLogger(__name__) + @defer.inlineCallbacks def sleep(seconds): @@ -181,6 +185,7 @@ class Linearizer(object): self.key_to_defer[key] = new_defer if current_defer: + logger.info("Waiting to acquire linearizer lock for key %r", key) with PreserveLoggingContext(): yield current_defer