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 #17722

The `write_bytes_to_request` span won't show up in the trace until
#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"

Author: MadLittleMods

changelog.d/18804.misc

@@ -0,0 +1 @@
+Instrument `_ByteProducer` with tracing to measure potential dead time while writing bytes to the request.

synapse/http/server.py

@@ -702,6 +702,10 @@ def __init__(
         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 @@ def __init__(
             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 @@ def _send_data(self, data: List[bytes]) -> None:
         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 @@ def resumeProducing(self) -> None:
 
         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 @@ def resumeProducing(self) -> None:
     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: