More tracing for federation

5 files changed, 25 insertions, 10 deletions

diff --git a/synapse/federation/federation_client.py b/synapse/federation/federation_client.py
index 76b39408ec..54c3478a82 100644
--- a/synapse/federation/federation_client.py
+++ b/synapse/federation/federation_client.py
@@ -61,7 +61,7 @@ from synapse.federation.federation_base import (
 )
 from synapse.federation.transport.client import SendJoinResponse
 from synapse.http.types import QueryParams
-from synapse.logging.tracing import trace, tag_args
+from synapse.logging.tracing import tag_args, trace
 from synapse.types import JsonDict, UserID, get_domain_from_id
 from synapse.util.async_helpers import concurrently_execute
 from synapse.util.caches.expiringcache import ExpiringCache
@@ -338,6 +338,8 @@ class FederationClient(FederationBase):
 
         return None
 
+    @trace
+    @tag_args
     async def get_pdu(
         self,
         destinations: Iterable[str],
@@ -475,6 +477,8 @@ class FederationClient(FederationBase):
 
         return state_event_ids, auth_event_ids
 
+    @trace
+    @tag_args
     async def get_room_state(
         self,
         destination: str,
@@ -534,6 +538,7 @@ class FederationClient(FederationBase):
 
         return valid_state_events, valid_auth_events
 
+    @trace
     async def _check_sigs_and_hash_and_fetch(
         self,
         origin: str,
diff --git a/synapse/handlers/federation.py b/synapse/handlers/federation.py
index 0cd9597dc5..d77a0adc3d 100644
--- a/synapse/handlers/federation.py
+++ b/synapse/handlers/federation.py
@@ -59,7 +59,7 @@ 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 trace, set_attribute
+from synapse.logging.tracing import set_attribute, 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 (
diff --git a/synapse/handlers/federation_event.py b/synapse/handlers/federation_event.py
index 60436fe497..7fa80439b2 100644
--- a/synapse/handlers/federation_event.py
+++ b/synapse/handlers/federation_event.py
@@ -59,7 +59,13 @@ from synapse.events import EventBase
 from synapse.events.snapshot import EventContext
 from synapse.federation.federation_client import InvalidResponseError
 from synapse.logging.context import nested_logging_context
-from synapse.logging.tracing import trace, tag_args, set_attribute, SynapseTags
+from synapse.logging.tracing import (
+    SynapseTags,
+    start_active_span,
+    set_attribute,
+    tag_args,
+    trace,
+)
 from synapse.metrics.background_process_metrics import run_as_background_process
 from synapse.replication.http.devices import ReplicationUserDevicesResyncRestServlet
 from synapse.replication.http.federation import (
@@ -1491,7 +1497,7 @@ class FederationEventHandler:
 
         set_attribute(
             SynapseTags.FUNC_ARG_PREFIX + "event_ids",
-            event_map.keys(),
+            str(event_map.keys()),
         )
 
         # filter out any events we have already seen. This might happen because
@@ -2033,7 +2039,6 @@ class FederationEventHandler:
             await self._store.remove_push_actions_from_staging(event.event_id)
             raise
 
-    @trace
     async def persist_events_and_notify(
         self,
         room_id: str,
@@ -2097,8 +2102,13 @@ class FederationEventHandler:
                     self._message_handler.maybe_schedule_expiry(event)
 
             if not backfilled:  # Never notify for backfilled events
-                for event in events:
-                    await self._notify_persisted_event(event, max_stream_token)
+                with start_active_span("notify_persisted_events"):
+                    set_attribute(
+                        SynapseTags.FUNC_ARG_PREFIX + "event_ids",
+                        str([ev.event_id for ev in events]),
+                    )
+                    for event in events:
+                        await self._notify_persisted_event(event, max_stream_token)
 
             return max_stream_token.stream
 
diff --git a/synapse/storage/controllers/persist_events.py b/synapse/storage/controllers/persist_events.py
index 0bdb213286..72b4dcef59 100644
--- a/synapse/storage/controllers/persist_events.py
+++ b/synapse/storage/controllers/persist_events.py
@@ -48,11 +48,11 @@ from synapse.events.snapshot import EventContext
 from synapse.logging.context import PreserveLoggingContext, make_deferred_yieldable
 from synapse.logging.tracing import (
     Link,
+    SynapseTags,
     get_active_span,
     set_attribute,
     start_active_span,
     trace,
-    SynapseTags,
 )
 from synapse.metrics.background_process_metrics import run_as_background_process
 from synapse.storage.controllers.state import StateStorageController
@@ -392,7 +392,7 @@ class EventsPersistenceStorageController:
         """
         set_attribute(
             SynapseTags.FUNC_ARG_PREFIX + "event_ids",
-            [e.event_id for e, _ in events_and_contexts],
+            str([e.event_id for e, _ in events_and_contexts]),
         )
         set_attribute(SynapseTags.FUNC_ARG_PREFIX + "backfilled", str(backfilled))
 
diff --git a/synapse/storage/databases/main/events_worker.py b/synapse/storage/databases/main/events_worker.py
index 449cb03276..00f9298a9f 100644
--- a/synapse/storage/databases/main/events_worker.py
+++ b/synapse/storage/databases/main/events_worker.py
@@ -54,7 +54,7 @@ from synapse.logging.context import (
     current_context,
     make_deferred_yieldable,
 )
-from synapse.logging.tracing import trace, tag_args
+from synapse.logging.tracing import tag_args, trace
 from synapse.metrics.background_process_metrics import (
     run_as_background_process,
     wrap_as_background_process,