More tracing

synapse/federation/federation_server.py

@@ -61,7 +61,7 @@ from synapse.logging.context import (
     nested_logging_context,
     run_in_background,
 )
-from synapse.logging.tracing import log_kv, start_active_span_from_edu, trace, tag_args
+from synapse.logging.tracing import log_kv, start_active_span_from_edu, tag_args, trace
 from synapse.metrics.background_process_metrics import wrap_as_background_process
 from synapse.replication.http.federation import (
     ReplicationFederationSendEduRestServlet,

synapse/handlers/federation.py

@@ -59,7 +59,13 @@ from synapse.events.validator import EventValidator
 from synapse.federation.federation_client import InvalidResponseError
 from synapse.http.servlet import assert_params_in_dict
 from synapse.logging.context import nested_logging_context
-from synapse.logging.tracing import SynapseTags, set_attribute, trace, tag_args
+from synapse.logging.tracing import (
+    SynapseTags,
+    set_attribute,
+    start_active_span,
+    tag_args,
+    trace,
+)
 from synapse.metrics.background_process_metrics import run_as_background_process
 from synapse.module_api import NOT_SPAM
 from synapse.replication.http.federation import (
@@ -380,13 +386,16 @@ class FederationHandler:
         # First we try hosts that are already in the room
         # TODO: HEURISTIC ALERT.
 
-        curr_state = await self._storage_controllers.state.get_current_state(room_id)
+        with start_active_span("getting likely_domains"):
+            curr_state = await self._storage_controllers.state.get_current_state(
+                room_id
+            )
 
-        curr_domains = get_domains_from_state(curr_state)
+            curr_domains = get_domains_from_state(curr_state)
 
-        likely_domains = [
-            domain for domain, depth in curr_domains if domain != self.server_name
-        ]
+            likely_domains = [
+                domain for domain, depth in curr_domains if domain != self.server_name
+            ]
 
         async def try_backfill(domains: List[str]) -> bool:
             # TODO: Should we try multiple of these at a time?

synapse/handlers/relations.py

@@ -19,7 +19,7 @@ import attr
 from synapse.api.constants import RelationTypes
 from synapse.api.errors import SynapseError
 from synapse.events import EventBase, relation_from_event
-from synapse.logging.tracing import trace
+from synapse.logging.tracing import SynapseTags, set_attribute, trace
 from synapse.storage.databases.main.relations import _RelatedEvent
 from synapse.types import JsonDict, Requester, StreamToken, UserID
 from synapse.visibility import filter_events_for_client
@@ -166,6 +166,7 @@ class RelationsHandler:
 
         return return_value
 
+    @trace
     async def get_relations_for_event(
         self,
         event_id: str,
@@ -200,6 +201,7 @@ class RelationsHandler:
 
         return related_events, next_token
 
+    @trace
     async def get_annotations_for_event(
         self,
         event_id: str,
@@ -245,6 +247,7 @@ class RelationsHandler:
 
         return filtered_results
 
+    @trace
     async def _get_threads_for_events(
         self,
         events_by_id: Dict[str, EventBase],
@@ -406,6 +409,11 @@ class RelationsHandler:
             # The event should get bundled aggregations.
             events_by_id[event.event_id] = event
 
+        set_attribute(
+            SynapseTags.FUNC_ARG_PREFIX + f"event_ids ({len(events_by_id)})",
+            str(events_by_id.keys()),
+        )
+
         # event ID -> bundled aggregation in non-serialized form.
         results: Dict[str, BundledAggregations] = {}
 

synapse/logging/tracing.py

@@ -912,7 +912,6 @@ def trace(func: Callable[P, R]) -> Callable[P, R]:
     Sets the operation name to that of the function's name.
     See the module's doc string for usage examples.
     """
-
     return trace_with_opname(func.__name__)(func)
 
 

synapse/rest/client/room.py

@@ -563,7 +563,6 @@ class RoomMessageListRestServlet(RestServlet):
     async def on_GET(
         self, request: SynapseRequest, room_id: str
     ) -> Tuple[int, JsonDict]:
-        logger.info("RoomMessageListRestServlet afwefaewfewfew")
         requester = await self.auth.get_user_by_req(request, allow_guest=True)
         pagination_config = await PaginationConfig.from_request(
             self.store, request, default_limit=10
@@ -593,7 +592,6 @@ class RoomMessageListRestServlet(RestServlet):
             as_client_event=as_client_event,
             event_filter=event_filter,
         )
-        logger.info("RoomMessageListRestServlet afwefaewfewfew got msgs")
 
         return 200, msgs
 

synapse/storage/databases/main/relations.py

@@ -30,6 +30,7 @@ import attr
 
 from synapse.api.constants import RelationTypes
 from synapse.events import EventBase
+from synapse.logging.tracing import trace
 from synapse.storage._base import SQLBaseStore
 from synapse.storage.database import LoggingTransaction, make_in_list_sql_clause
 from synapse.storage.databases.main.stream import generate_pagination_where_clause
@@ -349,6 +350,10 @@ class RelationsWorkerStore(SQLBaseStore):
     def get_applicable_edit(self, event_id: str) -> Optional[EventBase]:
         raise NotImplementedError()
 
+    # TODO: What's the proper way to fix this so we can stack @trace on top of
+    # @cachedList
+    #
+    # @trace
     @cachedList(cached_method_name="get_applicable_edit", list_name="event_ids")
     async def get_applicable_edits(
         self, event_ids: Collection[str]

synapse/storage/util/partial_state_events_tracker.py

@@ -20,7 +20,7 @@ from twisted.internet import defer
 from twisted.internet.defer import Deferred
 
 from synapse.logging.context import PreserveLoggingContext, make_deferred_yieldable
-from synapse.logging.tracing import trace
+from synapse.logging.tracing import trace_with_opname
 from synapse.storage.databases.main.events_worker import EventsWorkerStore
 from synapse.storage.databases.main.room import RoomWorkerStore
 from synapse.util import unwrapFirstError
@@ -59,7 +59,7 @@ class PartialStateEventsTracker:
             for o in observers:
                 o.callback(None)
 
-    @trace
+    @trace_with_opname("PartialStateEventsTracker.await_full_state")
     async def await_full_state(self, event_ids: Collection[str]) -> None:
         """Wait for all the given events to have full state.
 
@@ -153,7 +153,7 @@ class PartialCurrentStateTracker:
             for o in observers:
                 o.callback(None)
 
-    @trace
+    @trace_with_opname("PartialCurrentStateTracker.await_full_state")
     async def await_full_state(self, room_id: str) -> None:
         # We add the deferred immediately so that the DB call to check for
         # partial state doesn't race when we unpartial the room.

synapse/util/ratelimitutils.py

@@ -21,13 +21,13 @@ from typing import Any, DefaultDict, Iterator, List, Set
 from twisted.internet import defer
 
 from synapse.api.errors import LimitExceededError
-from synapse.logging.tracing import start_active_span
 from synapse.config.ratelimiting import FederationRatelimitSettings
 from synapse.logging.context import (
     PreserveLoggingContext,
     make_deferred_yieldable,
     run_in_background,
 )
+from synapse.logging.tracing import start_active_span
 from synapse.util import Clock
 
 if typing.TYPE_CHECKING:

tests/logging/test_tracing.py

@@ -16,7 +16,7 @@ from twisted.internet import defer
 from twisted.test.proto_helpers import MemoryReactorClock
 
 from synapse.logging.context import make_deferred_yieldable, run_in_background
-from synapse.logging.tracing import start_active_span, trace_with_opname, tag_args
+from synapse.logging.tracing import start_active_span, tag_args, trace_with_opname
 from synapse.util import Clock
 
 from tests.unittest import TestCase