element-hq / element-hq/synapse

getrusage represents about 20% of cpu usage

Open
#8,073 0 comments 0 reactions 0 assignees View on GitHub
A-Logging A-Performance O-Uncommon S-Tolerable T-Enhancement Z-Help-Wanted
Dominant language
Python
Stars
4.6k
Forks
600
Avg merge
5d 22h
Merged PRs (30d)
51

Description

This issue has been migrated from [#8073](https://github.com/matrix-org/synapse/issues/8073).

---

### Description

Hello!

I am working on increasing the scalability of Synapse and have been investigating it's runtime characteristics. I plan on writing a few PRs, but for now am just gathering information.

One interesting note is Synapse 1.18 spends about 20% of its time calling `getrusage`. After about 1000 "sendto" calls (ie: about 1k HTTP requests), Synapse has called getrusage 40k times! Using `strace -c -p PID_OF_SYNAPSE` and passing a few basic calls (list users in room, incremental_sync, etc) recreated this time after time.

Here is some sample output from `strace -c -p ...`:

```
------ ----------- ----------- --------- --------- ----------------
45.74 0.106682 9 11742 800 futex
18.57 0.043314 16 2676 epoll_wait
15.59 0.036372 1 40528 getrusage
4.90 0.011436 10 1171 sendto
3.17 0.007389 2 4550 epoll_ctl
2.17 0.005072 5 1069 shutdown
1.67 0.003893 3 1230 close
1.62 0.003788 3 1482 415 accept4
```

Note that getrusage is called ~10x more than accept4 (so on average, we do about 8 or 9 getrusage calls per http request).

I believe most of the calls come from the Measure() class here https://github.com/matrix-org/synapse/blob/9d1e4942ab728ebfe09ff9a63c66708ceaaf7591/synapse/util/metrics.py#L127

The stats generated by get_resource_usage() reveal that by far and away, the vast vast majority of CPU time is spent in `{method="GET",servlet="SyncRestServlet",tag="incremental_sync"}` which is possibly reasonable - and not entirely surprising. The information from get_resource_usage() is probably not being used terribly often - as it appears to be reporting the vast majority of load in one known place.

I wonder if calls to get_thread_resource_usage() shouldn't be disabled by default (or at least, only enabled when prometheus metrics are enabled). This one line of code is responsible for the vast majority of syscalls Synapse makes: https://github.com/matrix-org/synapse/blob/931b02684481fb6b5daefd9218baf6a4b0b941f6/synapse/logging/context.py#L452

I'll try to update this issue if I can get some stats with getrusage disabled. I suspect there is also work to do in SyncRestServlet/incremental_sync (it seems to be responsible for the vast, vast majority of load). Note that the futex calls and errors are probably due to the FUSE filesystem mounting the media storage which is a default of https://github.com/spantaleev/matrix-docker-ansible-deploy - I plan on removing (in favor of the s3 python driver) that and ideally this resolves the futex errors as well.

### Steps to reproduce

Launch Synapse - use `strace -c -p PID_OF_SYNAPSE_HOMESERVER` to generate table of syscalls.

### Version information

- **Homeserver**:

matrix.nova.chat

- **Version**:

server_version: "1.18.0"
python_version: "3.7.8"

- **Install method**:
https://github.com/spantaleev/matrix-docker-ansible-deploy

- **Platform**:
Linux / Ubuntu 18.04 / 4.15

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.