element-hq / element-hq/synapse

Synapse takes forever to send responses - dead time gap after `encode_json_response`

Open
#17,722 11 comments 0 reactions 0 assignees View on GitHub
A-Performance
Dominant language
Python
Stars
4.6k
Forks
600
Avg merge
5d 22h
Merged PRs (30d)
51

Description

Synapse takes forever to send large responses. It takes us longer to send just the response than it does for us to process and `encode_json_response` in some cases.

### Examples

98s to process the request and `encode_json_response` but the request isn't finished sending until 484s (8 minutes) which is 6.5 minutes of dead-time. The response size is 36MB

Jaeger trace: [`4238bdbadd9f3077.json`](https://gist.github.com/MadLittleMods/9b1613825848310a95326d532746a344)

Jaeger trace with big gap for sending the response

59s to process and finishes after 199s. The response size is 36MB

Jaeger trace: [`2149cc5e59306446.json`](https://gist.github.com/MadLittleMods/d8dd06e7e0cbbee5f42d5478476cc4d3)

Jaeger trace with big gap for sending the response

I've come across this before and it's not a new thing. For example in https://github.com/element-hq/synapse/issues/13620 ([original issue](https://github.com/matrix-org/synapse/issues/13620)), I described as the "mystery gap at the end after we encode the JSON response (`encode_json_response`)" but never encountered it being *this* egregious.

It can also happen for small requests. 2s to process and finishes after 5s. The response size is 120KB

Jaeger trace with big gap for sending the response

### Investigation

@kegsay pointed out `_write_bytes_to_request` which runs after `encode_json_response` and has comments like "Write until there's backpressure telling us to stop." that definitely hint at some areas of interest.

https://github.com/element-hq/synapse/blob/03937a1cae18900350a6d16a2714111a2847c821/synapse/http/server.py#L869-L873

The JSON serialization is done in a background thread because it can block the reactor for many seconds. This part seems normal and fast (no problem).

But we also use `_ByteProducer` to send the bytes down to the client. Using a producer ensures we can send down all of the bytes to the client without hitting a 60s timeout (see context in comments below)

https://github.com/element-hq/synapse/blob/d40bc279ed44ae4921d20d94e380c2d442cbfc44/synapse/http/server.py#L883-L889

This logic was added in:

- https://github.com/matrix-org/synapse/pull/8013
- https://github.com/matrix-org/synapse/pull/8116

Some extra time is expected as we're working *with* the reactor instead of blocking it but it seems like something isn't tuned optimally (chunk size, starting/stopping too much, etc)

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.