element-hq / element-hq/synapse
getrusage represents about 20% of cpu usage
- 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
Assessment
This issue has not been assessed yet.