Improve logging of state resolution (#8371)

I'd like to get a better insight into what we are doing with respect to state
res. The list of state groups we are resolving across should be short (if it
isn't, that's a massive problem in itself), so it should be fine to log it in
ite entiretly.

I've done some grepping and found approximately zero cases in which the
"shortcut" code delivered the result, so I've ripped that out too.
This commit is contained in:
Richard van der Hoff 2020-09-23 16:42:44 +01:00 committed by GitHub
parent 302dc89f6a
commit 91c60f3042
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
2 changed files with 17 additions and 48 deletions

1
changelog.d/8371.misc Normal file
View File

@ -0,0 +1 @@
Improve logging of state resolution.

View File

@ -25,7 +25,6 @@ from typing import (
Sequence, Sequence,
Set, Set,
Union, Union,
cast,
overload, overload,
) )
@ -42,7 +41,7 @@ from synapse.logging.utils import log_function
from synapse.state import v1, v2 from synapse.state import v1, v2
from synapse.storage.databases.main.events_worker import EventRedactBehaviour from synapse.storage.databases.main.events_worker import EventRedactBehaviour
from synapse.storage.roommember import ProfileInfo from synapse.storage.roommember import ProfileInfo
from synapse.types import Collection, MutableStateMap, StateMap from synapse.types import Collection, StateMap
from synapse.util import Clock from synapse.util import Clock
from synapse.util.async_helpers import Linearizer from synapse.util.async_helpers import Linearizer
from synapse.util.caches.expiringcache import ExpiringCache from synapse.util.caches.expiringcache import ExpiringCache
@ -472,10 +471,9 @@ class StateResolutionHandler:
def __init__(self, hs): def __init__(self, hs):
self.clock = hs.get_clock() self.clock = hs.get_clock()
# dict of set of event_ids -> _StateCacheEntry.
self._state_cache = None
self.resolve_linearizer = Linearizer(name="state_resolve_lock") self.resolve_linearizer = Linearizer(name="state_resolve_lock")
# dict of set of event_ids -> _StateCacheEntry.
self._state_cache = ExpiringCache( self._state_cache = ExpiringCache(
cache_name="state_cache", cache_name="state_cache",
clock=self.clock, clock=self.clock,
@ -519,57 +517,28 @@ class StateResolutionHandler:
Returns: Returns:
The resolved state The resolved state
""" """
logger.debug("resolve_state_groups state_groups %s", state_groups_ids.keys())
group_names = frozenset(state_groups_ids.keys()) group_names = frozenset(state_groups_ids.keys())
with (await self.resolve_linearizer.queue(group_names)): with (await self.resolve_linearizer.queue(group_names)):
if self._state_cache is not None: cache = self._state_cache.get(group_names, None)
cache = self._state_cache.get(group_names, None) if cache:
if cache: return cache
return cache
logger.info( logger.info(
"Resolving state for %s with %d groups", room_id, len(state_groups_ids) "Resolving state for %s with groups %s", room_id, list(group_names),
) )
state_groups_histogram.observe(len(state_groups_ids)) state_groups_histogram.observe(len(state_groups_ids))
# start by assuming we won't have any conflicted state, and build up the new with Measure(self.clock, "state._resolve_events"):
# state map by iterating through the state groups. If we discover a conflict, new_state = await resolve_events_with_store(
# we give up and instead use `resolve_events_with_store`. self.clock,
# room_id,
# XXX: is this actually worthwhile, or should we just let room_version,
# resolve_events_with_store do it? list(state_groups_ids.values()),
new_state = {} # type: MutableStateMap[str] event_map=event_map,
conflicted_state = False state_res_store=state_res_store,
for st in state_groups_ids.values(): )
for key, e_id in st.items():
if key in new_state:
conflicted_state = True
break
new_state[key] = e_id
if conflicted_state:
break
if conflicted_state:
logger.info("Resolving conflicted state for %r", room_id)
with Measure(self.clock, "state._resolve_events"):
# resolve_events_with_store returns a StateMap, but we can
# treat it as a MutableStateMap as it is above. It isn't
# actually mutated anymore (and is frozen in
# _make_state_cache_entry below).
new_state = cast(
MutableStateMap,
await resolve_events_with_store(
self.clock,
room_id,
room_version,
list(state_groups_ids.values()),
event_map=event_map,
state_res_store=state_res_store,
),
)
# if the new state matches any of the input state groups, we can # if the new state matches any of the input state groups, we can
# use that state group again. Otherwise we will generate a state_id # use that state group again. Otherwise we will generate a state_id
@ -579,8 +548,7 @@ class StateResolutionHandler:
with Measure(self.clock, "state.create_group_ids"): with Measure(self.clock, "state.create_group_ids"):
cache = _make_state_cache_entry(new_state, state_groups_ids) cache = _make_state_cache_entry(new_state, state_groups_ids)
if self._state_cache is not None: self._state_cache[group_names] = cache
self._state_cache[group_names] = cache
return cache return cache