From 356cc4a0a11f83dd1c3c68a7a94afd9b82a25e48 Mon Sep 17 00:00:00 2001
From: Eric Eastwood <erice@element.io>
Date: Wed, 27 Aug 2025 12:26:42 -0500
Subject: [PATCH] Instrument `_ByteProducer` with tracing to measure potential
 dead time while writing bytes to the request (#18804)

This will allow to easily see how much time is taken up by
being able to filter by the `write_bytes_to_request` operation
in Jaeger.

Spawning from https://github.com/element-hq/synapse/issues/17722

The `write_bytes_to_request` span won't show up in the trace until
https://github.com/element-hq/synapse/pull/18849 is merged.

Note: It's totally fine for a span child to finish after the parent. See
https://opentracing.io/specification/#references-between-spans which
shows "Child Span D" outliving the "Parent Span"
---
 changelog.d/18804.misc |  1 +
 synapse/http/server.py | 14 +++++++++++++-
 2 files changed, 14 insertions(+), 1 deletion(-)
 create mode 100644 changelog.d/18804.misc

diff --git a/changelog.d/18804.misc b/changelog.d/18804.misc
new file mode 100644
index 000000000..3814dd668
--- /dev/null
+++ b/changelog.d/18804.misc
@@ -0,0 +1 @@
+Instrument `_ByteProducer` with tracing to measure potential dead time while writing bytes to the request.
diff --git a/synapse/http/server.py b/synapse/http/server.py
index 45c74d68f..e395f7989 100644
--- a/synapse/http/server.py
+++ b/synapse/http/server.py
@@ -702,6 +702,10 @@ class _ByteProducer:
         self._request: Optional[Request] = request
         self._iterator = iterator
         self._paused = False
+        self.tracing_scope = start_active_span(
+            "write_bytes_to_request",
+        )
+        self.tracing_scope.__enter__()
 
         try:
             self._request.registerProducer(self, True)
@@ -712,8 +716,8 @@ class _ByteProducer:
             logger.info("Connection disconnected before response was written: %r", e)
 
             # We drop our references to data we'll not use.
-            self._request = None
             self._iterator = iter(())
+            self.tracing_scope.__exit__(type(e), None, e.__traceback__)
         else:
             # Start producing if `registerProducer` was successful
             self.resumeProducing()
@@ -727,6 +731,9 @@ class _ByteProducer:
         self._request.write(b"".join(data))
 
     def pauseProducing(self) -> None:
+        opentracing_span = active_span()
+        if opentracing_span is not None:
+            opentracing_span.log_kv({"event": "producer_paused"})
         self._paused = True
 
     def resumeProducing(self) -> None:
@@ -737,6 +744,10 @@ class _ByteProducer:
 
         self._paused = False
 
+        opentracing_span = active_span()
+        if opentracing_span is not None:
+            opentracing_span.log_kv({"event": "producer_resumed"})
+
         # Write until there's backpressure telling us to stop.
         while not self._paused:
             # Get the next chunk and write it to the request.
@@ -771,6 +782,7 @@ class _ByteProducer:
     def stopProducing(self) -> None:
         # Clear a circular reference.
         self._request = None
+        self.tracing_scope.__exit__(None, None, None)
 
 
 def _encode_json_bytes(json_object: object) -> bytes: