diff --git a/changelog.d/17501.misc b/changelog.d/17501.misc new file mode 100644 index 0000000000..ba96472acb --- /dev/null +++ b/changelog.d/17501.misc @@ -0,0 +1 @@ +Add some opentracing tags and logging to the experimental sliding sync implementation. diff --git a/synapse/handlers/sliding_sync.py b/synapse/handlers/sliding_sync.py index 84f2fa18ff..73414dbf69 100644 --- a/synapse/handlers/sliding_sync.py +++ b/synapse/handlers/sliding_sync.py @@ -41,7 +41,7 @@ from synapse.events import EventBase from synapse.events.utils import strip_event from synapse.handlers.relations import BundledAggregations -from synapse.logging.opentracing import start_active_span, tag_args, trace +from synapse.logging.opentracing import log_kv, start_active_span, tag_args, trace from synapse.storage.databases.main.roommember import extract_heroes_from_room_summary from synapse.storage.databases.main.stream import CurrentStateDeltaMembership from synapse.storage.roommember import MemberSummary @@ -444,6 +444,7 @@ async def current_sync_callback( return result + @trace async def current_sync_for_user( self, sync_config: SlidingSyncConfig, @@ -682,8 +683,9 @@ async def handle_room(room_id: str) -> None: if room_sync_result or not from_token: rooms[room_id] = room_sync_result - with start_active_span("sliding_sync.generate_room_entries"): - await concurrently_execute(handle_room, relevant_room_map, 10) + if relevant_room_map: + with start_active_span("sliding_sync.generate_room_entries"): + await concurrently_execute(handle_room, relevant_room_map, 10) extensions = await self.get_extensions_response( sync_config=sync_config, @@ -1161,6 +1163,7 @@ async def check_room_subscription_allowed_for_user( # return None + @trace async def filter_rooms( self, user: UserID, @@ -1284,6 +1287,7 @@ async def filter_rooms( # Assemble a new sync room map but only with the `filtered_room_id_set` return {room_id: sync_room_map[room_id] for room_id in filtered_room_id_set} + @trace async def sort_rooms( self, sync_room_map: Dict[str, _RoomMembershipForUser], @@ -1492,6 +1496,10 @@ async def get_room_sync_data( else: assert_never(room_status.status) + log_kv({"sliding_sync.room_status": room_status}) + + log_kv({"sliding_sync.from_bound": from_bound, "sliding_sync.initial": initial}) + # Assemble the list of timeline events # # FIXME: It would be nice to make the `rooms` response more uniform regardless of @@ -1890,6 +1898,7 @@ async def get_room_sync_data( highlight_count=0, ) + @trace async def get_extensions_response( self, sync_config: SlidingSyncConfig, @@ -1942,6 +1951,7 @@ async def get_extensions_response( account_data=account_data_response, ) + @trace async def get_to_device_extension_response( self, sync_config: SlidingSyncConfig, @@ -2016,6 +2026,7 @@ async def get_to_device_extension_response( events=messages, ) + @trace async def get_e2ee_extension_response( self, sync_config: SlidingSyncConfig, @@ -2066,6 +2077,7 @@ async def get_e2ee_extension_response( device_unused_fallback_key_types=device_unused_fallback_key_types, ) + @trace async def get_account_data_extension_response( self, sync_config: SlidingSyncConfig, diff --git a/synapse/rest/client/sync.py b/synapse/rest/client/sync.py index bf3ac8d483..ccfce6bd53 100644 --- a/synapse/rest/client/sync.py +++ b/synapse/rest/client/sync.py @@ -52,7 +52,7 @@ parse_string, ) from synapse.http.site import SynapseRequest -from synapse.logging.opentracing import trace_with_opname +from synapse.logging.opentracing import log_kv, set_tag, trace_with_opname from synapse.rest.admin.experimental_features import ExperimentalFeature from synapse.types import JsonDict, Requester, SlidingSyncStreamToken, StreamToken from synapse.types.rest.client import SlidingSyncBody @@ -897,7 +897,23 @@ async def on_POST(self, request: SynapseRequest) -> Tuple[int, JsonDict]: # by filter ID. For now, we will just prototype with always passing everything # in. body = parse_and_validate_json_object_from_request(request, SlidingSyncBody) - logger.info("Sliding sync request: %r", body) + + # Tag and log useful data to differentiate requests. + set_tag("sliding_sync.conn_id", body.conn_id or "") + log_kv( + { + "sliding_sync.lists": { + list_name: { + "ranges": list_config.ranges, + "timeline_limit": list_config.timeline_limit, + } + for list_name, list_config in (body.lists or {}).items() + }, + "sliding_sync.room_subscriptions": list( + (body.room_subscriptions or {}).keys() + ), + } + ) sync_config = SlidingSyncConfig( user=user,