diff --git a/changelog.d/18804.misc b/changelog.d/18804.misc new file mode 100644 index 00000000000..3814dd668d0 --- /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 45c74d68f93..e395f79894c 100644 --- a/synapse/http/server.py +++ b/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: