search

matrix-org / synapse

Synapse: Matrix homeserver written in Python/Twisted.
https://matrix-org.github.io/synapse
Apache License 2.0
11.79k stars 2.13k forks source link

Sliding Sync Proxy + Presence enabled leads to high CPU usage #15980

Closed DoM1niC closed 11 months ago

DoM1niC commented 1 year ago

Description

I try out to reduce my issue while disable presence fully, now I only enable presence to events / sync workers. I never saw this impact since I use Sync v3 Proxy for test purpose of Element X.

Steps to reproduce

Homeserver

3dns.eu

Synapse Version

1.88.0

Installation Method

Docker (matrixdotorg/synapse)

Database

PostgresSQL 15

Workers

Multiple process

Platform

Arch Linux (Rolling)

Configuration

No response

Relevant log output

[root@messenger matrix]# /opt/matrix/bin/python -m synapse.app.generic_worker --config-path=instance/3DNS/config.yaml --config-path=instance/3DNS/conf.d/ --config-path=instance/3DNS/workers/synchrotron.yaml
2023-07-23 19:59:10,066 - root - 348 - WARNING - main - ***** STARTING SERVER *****
2023-07-23 19:59:10,066 - root - 349 - WARNING - main - Server /opt/matrix/lib/python3.11/site-packages/synapse/app/generic_worker.py version 1.88.0 (b=main,d105ed4a)
2023-07-23 19:59:10,066 - root - 354 - INFO - main - Server hostname: 3dns.eu
2023-07-23 19:59:10,067 - root - 355 - INFO - main - Instance name: sync_worker
2023-07-23 19:59:10,067 - root - 356 - INFO - main - Twisted reactor: EPollReactor
2023-07-23 19:59:10,067 - synapse.server - 336 - INFO - main - Setting up.
2023-07-23 19:59:10,083 - synapse.storage.databases - 66 - INFO - main - [database config 'master']: Checking database server
2023-07-23 19:59:10,085 - synapse.storage.databases - 69 - INFO - main - [database config 'master']: Preparing for databases ['main', 'state']
2023-07-23 19:59:10,085 - synapse.storage.prepare_database - 120 - INFO - main - ['main', 'state']: Checking existing schema version
2023-07-23 19:59:10,088 - synapse.storage.prepare_database - 124 - INFO - main - ['main', 'state']: Existing schema is 79 (+2 deltas)
2023-07-23 19:59:10,089 - synapse.storage.databases.main - 323 - INFO - main - Checking database for consistency with configuration...
2023-07-23 19:59:10,089 - synapse.storage.prepare_database - 553 - INFO - main - Schema now up to date
2023-07-23 19:59:10,090 - synapse.storage.databases - 84 - INFO - main - [database config 'master']: Starting 'main' database
2023-07-23 19:59:10,091 - synapse.config.appservice - 81 - INFO - main - Loaded application service: ApplicationService: {'token': '<redacted>', 'url': 'http://127.0.0.1:8010', 'hs_token': '<redacted>', 'sender': '@_webhook:3dns.eu', 'namespaces': {'users': [Namespace(exclusive=True, regex=re.compile('@_webhook.*'))], 'aliases': [], 'rooms': []}, 'id': 'a04b302b68d6d342d67825857b40cf7afae9fc7443d7c861696f96f3ad0cc3d7', 'ip_range_whitelist': None, 'supports_ephemeral': False, 'msc3202_transaction_extensions': False, 'protocols': set(), 'rate_limited': False}
2023-07-23 19:59:10,093 - synapse.config.appservice - 81 - INFO - main - Loaded application service: ApplicationService: {'token': '<redacted>', 'url': 'http://127.0.0.1:8015', 'hs_token': '<redacted>', 'sender': '@HVLBlveHl1jiXDJfX8aIGAiAO6DLtMYO:3dns.eu', 'namespaces': {'users': [Namespace(exclusive=True, regex=re.compile('^@whatsapp_[0-9]+:3dns.eu$')), Namespace(exclusive=True, regex=re.compile('^@whatsappbot:3dns.eu$'))], 'aliases': [], 'rooms': []}, 'id': 'whatsapp', 'ip_range_whitelist': None, 'supports_ephemeral': False, 'msc3202_transaction_extensions': False, 'protocols': set(), 'rate_limited': False}
2023-07-23 19:59:10,095 - synapse.config.appservice - 81 - INFO - main - Loaded application service: ApplicationService: {'token': '<redacted>', 'url': 'http://127.0.0.1:8012', 'hs_token': '<redacted>', 'sender': '@xHLpqFdRZT9Y7ffCuBwnAzlF7T8swiK6Dk5dMoKwDa9d60yT6pXks3pGKlZfREXh:3dns.eu', 'namespaces': {'users': [Namespace(exclusive=True, regex=re.compile('@facebook_.*:3dns\\.eu')), Namespace(exclusive=True, regex=re.compile('@facebookbot:3dns\\.eu'))], 'aliases': [], 'rooms': []}, 'id': 'facebook', 'ip_range_whitelist': None, 'supports_ephemeral': True, 'msc3202_transaction_extensions': False, 'protocols': set(), 'rate_limited': False}
2023-07-23 19:59:10,097 - synapse.config.appservice - 81 - INFO - main - Loaded application service: ApplicationService: {'token': '<redacted>', 'url': 'http://127.0.0.1:8011', 'hs_token': '<redacted>', 'sender': '@ircbot:3dns.eu', 'namespaces': {'users': [Namespace(exclusive=True, regex=re.compile('@irc_.*:3dns\\.eu')), Namespace(exclusive=True, regex=re.compile('@primal_.*:3dns\\.eu'))], 'aliases': [Namespace(exclusive=True, regex=re.compile('#freenode_.*:3dns\\.eu')), Namespace(exclusive=True, regex=re.compile('#primal_.*:3dns\\.eu'))], 'rooms': [Namespace(exclusive=False, regex=re.compile('!qrqeqjoKbOpPpbEInU:3dns.eu')), Namespace(exclusive=False, regex=re.compile('!YczbNMgxGSZBPOqkKZ:3dns.eu'))]}, 'id': 'b4ac82e92b4918047145b493fd8a76f189c7bac0a9fe69e459c1110f6647ca13', 'ip_range_whitelist': None, 'supports_ephemeral': True, 'msc3202_transaction_extensions': False, 'protocols': {'irc'}, 'rate_limited': False}
2023-07-23 19:59:10,099 - synapse.config.appservice - 81 - INFO - main - Loaded application service: ApplicationService: {'token': '<redacted>', 'url': 'http://127.0.0.1:8002', 'hs_token': '<redacted>', 'sender': '@dleHGZcAdCo7WMaGynyjpUCRT5BLgyOleCr-z2NWOw_UIiB8mh-xAOlFQObH96ao:3dns.eu', 'namespaces': {'users': [Namespace(exclusive=True, regex=re.compile('@instagram_.*:3dns\\.eu')), Namespace(exclusive=True, regex=re.compile('@instagrambot:3dns\\.eu'))], 'aliases': [], 'rooms': []}, 'id': 'instagram', 'ip_range_whitelist': None, 'supports_ephemeral': True, 'msc3202_transaction_extensions': False, 'protocols': set(), 'rate_limited': False}
2023-07-23 19:59:10,101 - synapse.config.appservice - 81 - INFO - main - Loaded application service: ApplicationService: {'token': '<redacted>', 'url': 'http://127.0.0.1:8017', 'hs_token': '<redacted>', 'sender': '@Q2RAnKrPYtBuiuWtpU9S1GxdhE-2FhP5gYPwu_cueHRkmZm1Zf9mmyyXL_2bnn4D:3dns.eu', 'namespaces': {'users': [Namespace(exclusive=True, regex=re.compile('@signal_.*:3dns\\.eu')), Namespace(exclusive=True, regex=re.compile('@signalbot:3dns\\.eu'))], 'aliases': [], 'rooms': []}, 'id': 'signal', 'ip_range_whitelist': None, 'supports_ephemeral': True, 'msc3202_transaction_extensions': False, 'protocols': set(), 'rate_limited': False}
2023-07-23 19:59:10,103 - synapse.config.appservice - 81 - INFO - main - Loaded application service: ApplicationService: {'token': '<redacted>', 'url': 'http://127.0.0.1:8018', 'hs_token': '<redacted>', 'sender': '@7QA7amMTK-yTipacxH-RVIrXI51DM43L9R1I3piWmkrNbsD8rZsY6YUSvI7iKybe:3dns.eu', 'namespaces': {'users': [Namespace(exclusive=True, regex=re.compile('@telegram_.*:3dns\\.eu')), Namespace(exclusive=True, regex=re.compile('@telegrambot:3dns\\.eu'))], 'aliases': [Namespace(exclusive=True, regex=re.compile('\\#telegram_.*:3dns\\.eu'))], 'rooms': []}, 'id': 'telegram', 'ip_range_whitelist': None, 'supports_ephemeral': False, 'msc3202_transaction_extensions': False, 'protocols': set(), 'rate_limited': False}
2023-07-23 19:59:10,105 - synapse.config.appservice - 81 - INFO - main - Loaded application service: ApplicationService: {'token': '<redacted>', 'url': 'http://127.0.0.1:8014', 'hs_token': '<redacted>', 'sender': '@45Qlu7yWJpucwnBhcRluqYkFjZgtnmMK:3dns.eu', 'namespaces': {'users': [Namespace(exclusive=True, regex=re.compile('^@discordbot:3dns\\.eu$')), Namespace(exclusive=True, regex=re.compile('^@discord_[0-9]+:3dns\\.eu$'))], 'aliases': [], 'rooms': []}, 'id': 'discord', 'ip_range_whitelist': None, 'supports_ephemeral': True, 'msc3202_transaction_extensions': False, 'protocols': set(), 'rate_limited': False}
2023-07-23 19:59:10,282 - synapse.storage.databases.main.event_push_actions - 1152 - INFO - main - Searching for stream ordering 1 month ago
2023-07-23 19:59:10,292 - synapse.storage.databases.main.event_push_actions - 1156 - INFO - main - Found stream ordering 1 month ago: it's 2227105
2023-07-23 19:59:10,293 - synapse.storage.databases.main.event_push_actions - 1159 - INFO - main - Searching for stream ordering 1 day ago
2023-07-23 19:59:10,301 - synapse.storage.databases.main.event_push_actions - 1163 - INFO - main - Found stream ordering 1 day ago: it's 2315643
2023-07-23 19:59:10,303 - synapse.storage.util.id_generators - 92 - INFO - main - Initialising stream generator for pushers(id): 41899
2023-07-23 19:59:10,303 - synapse.storage.util.id_generators - 92 - INFO - main - Initialising stream generator for deleted_pushers(stream_id): 41824
2023-07-23 19:59:10,304 - synapse.storage.util.id_generators - 92 - INFO - main - Initialising stream generator for push_rules_stream(stream_id): 658
2023-07-23 19:59:10,318 - synapse.storage.util.id_generators - 92 - INFO - main - Initialising stream generator for device_lists_stream(stream_id): 4721181
2023-07-23 19:59:10,320 - synapse.storage.util.id_generators - 92 - INFO - main - Initialising stream generator for user_signature_stream(stream_id): 4421890
2023-07-23 19:59:10,320 - synapse.storage.util.id_generators - 92 - INFO - main - Initialising stream generator for device_lists_outbound_pokes(stream_id): 4721107
2023-07-23 19:59:10,321 - synapse.storage.util.id_generators - 92 - INFO - main - Initialising stream generator for device_lists_changes_in_room(stream_id): 4721181
2023-07-23 19:59:10,322 - synapse.storage.util.id_generators - 92 - INFO - main - Initialising stream generator for device_lists_remote_pending(stream_id): 1
2023-07-23 19:59:10,323 - synapse.storage.util.id_generators - 92 - INFO - main - Initialising stream generator for device_lists_changes_converted_stream_position(stream_id): 4721109
2023-07-23 19:59:10,472 - synapse.storage.databases - 101 - INFO - main - [database config 'master']: Starting 'state' database
2023-07-23 19:59:10,475 - synapse.storage.databases - 116 - INFO - main - [database config 'master']: prepared
2023-07-23 19:59:10,476 - synapse.server - 339 - INFO - main - Finished setting up.
2023-07-23 19:59:10,518 - synapse.push.pusher - 38 - INFO - main - email enable notifs: False
2023-07-23 19:59:10,520 - twisted - 275 - INFO - main - Redirected stdout/stderr to logs
2023-07-23 19:59:10,520 - synapse.app.generic_worker - 175 - INFO - sentinel - Running
2023-07-23 19:59:10,523 - synapse.app.homeserver - 29 - INFO - sentinel - Set file limit to: 524288
2023-07-23 19:59:10,523 - synapse.metrics._gc - 120 - INFO - sentinel - Collecting gc 1
2023-07-23 19:59:10,536 - synapse.federation.federation_server - 1447 - INFO - sentinel - Registering federation query handler for 'profile'
2023-07-23 19:59:10,537 - matrix_http_rendezvous_synapse - 65 - INFO - sentinel - Mounting rendez-vous server on /_synapse/client/org.matrix.msc3886/rendezvous, with a TTL of 1m and max payload size of 4.0 kiB
2023-07-23 19:59:10,537 - synapse.app._base - 577 - INFO - sentinel - Loaded module <builtins.SynapseRendezvousModule object at 0x7f4aaf863d70>
2023-07-23 19:59:10,538 - rest_auth_provider - 45 - INFO - sentinel - Endpoint: https://v4.3dns.eu
2023-07-23 19:59:10,538 - rest_auth_provider - 46 - INFO - sentinel - Enforce lowercase username during registration: True
2023-07-23 19:59:10,538 - synapse.app._base - 577 - INFO - sentinel - Loaded module <rest_auth_provider.RestAuthProvider object at 0x7f4ab01d7c10>
2023-07-23 19:59:10,538 - synapse.util.caches.lrucache - 223 - INFO - sentinel - Expiring LRU caches after 1800 seconds
2023-07-23 19:59:10,547 - synapse.server - 870 - INFO - sentinel - Connecting to redis (host='10.0.0.3' port=6379) for external cache
2023-07-23 19:59:10,547 - synapse.replication.tcp.redis - 285 - INFO - sentinel - Connecting to redis server 10.0.0.3:6379
2023-07-23 19:59:10,551 - synapse.federation.federation_server - 1447 - INFO - sentinel - Registering federation query handler for 'directory'
2023-07-23 19:59:10,555 - synapse.federation.federation_server - 1447 - INFO - sentinel - Registering federation query handler for 'client_keys'
2023-07-23 19:59:10,559 - synapse.util.httpresourcetree - 49 - INFO - sentinel - Attaching <synapse.rest.health.HealthResource object at 0x7f4aaf86a550> to path b'/health'
2023-07-23 19:59:10,560 - synapse.util.httpresourcetree - 49 - INFO - sentinel - Attaching <synapse.rest.ClientRestResource object at 0x7f4aaf86b390> to path b'/_matrix/client'
2023-07-23 19:59:10,560 - synapse.util.httpresourcetree - 49 - INFO - sentinel - Attaching <synapse.rest.synapse.client.pick_idp.PickIdpResource object at 0x7f4aafc36cd0> to path b'/_synapse/client/pick_idp'
2023-07-23 19:59:10,560 - synapse.util.httpresourcetree - 49 - INFO - sentinel - Attaching <twisted.web.resource.Resource object at 0x7f4ab01d6fd0> to path b'/_synapse/client/pick_username'
2023-07-23 19:59:10,560 - synapse.util.httpresourcetree - 49 - INFO - sentinel - Attaching <synapse.rest.synapse.client.new_user_consent.NewUserConsentResource object at 0x7f4ab01873d0> to path b'/_synapse/client/new_user_consent'
2023-07-23 19:59:10,560 - synapse.util.httpresourcetree - 49 - INFO - sentinel - Attaching <synapse.rest.synapse.client.sso_register.SsoRegisterResource object at 0x7f4aafd59250> to path b'/_synapse/client/sso_register'
2023-07-23 19:59:10,560 - synapse.util.httpresourcetree - 49 - INFO - sentinel - Attaching <synapse.rest.synapse.client.unsubscribe.UnsubscribeResource object at 0x7f4aafc37450> to path b'/_synapse/client/unsubscribe'
2023-07-23 19:59:10,560 - synapse.util.httpresourcetree - 49 - INFO - sentinel - Attaching <twisted.web.resource.Resource object at 0x7f4aaf88f790> to path b'/.well-known'
2023-07-23 19:59:10,560 - synapse.util.httpresourcetree - 49 - INFO - sentinel - Attaching <synapse.replication.http.ReplicationRestResource object at 0x7f4aafc37650> to path b'/_synapse/replication'
2023-07-23 19:59:10,560 - synapse.util.httpresourcetree - 49 - INFO - sentinel - Attaching <builtins.Resource object at 0x7f4aaf86e5e0> to path b'/_synapse/client/org.matrix.msc3886/rendezvous'
2023-07-23 19:59:10,561 - twisted - 275 - INFO - sentinel - SynapseSite starting on 9006
2023-07-23 19:59:10,561 - synapse.app._base - 432 - INFO - sentinel - Synapse now listening on TCP port 9006
2023-07-23 19:59:10,563 - synapse.replication.tcp.redis - 285 - INFO - sentinel - Connecting to redis server 10.0.0.3:6379
2023-07-23 19:59:10,563 - synapse.push.pusherpool - 93 - INFO - sentinel - Not starting pushers because they are disabled in the config
2023-07-23 19:59:10,627 - synapse.replication.tcp.redis - 119 - INFO - sentinel - Connected to redis
2023-07-23 19:59:10,628 - synapse.replication.tcp.redis - 131 - INFO - subscribe-replication-0 - Sending redis SUBSCRIBE for ['3dns.eu']
2023-07-23 19:59:10,630 - synapse.replication.tcp.redis - 134 - INFO - subscribe-replication-0 - Successfully subscribed to redis stream, sending REPLICATE command
2023-07-23 19:59:10,641 - synapse.replication.tcp.redis - 139 - INFO - subscribe-replication-0 - REPLICATE successfully sent
2023-07-23 19:59:10,646 - synapse.replication.tcp.handler - 611 - INFO - process-replication-data-0 - Fetching replication rows for 'caches' between 1847967 and 1847952
2023-07-23 19:59:10,662 - synapse.replication.tcp.handler - 634 - INFO - process-replication-data-0 - Caught up with stream 'caches' to 1847952
2023-07-23 19:59:10,662 - synapse.replication.tcp.handler - 611 - INFO - process-replication-data-0 - Fetching replication rows for 'caches' between 1847967 and 1847952
2023-07-23 19:59:10,670 - synapse.replication.tcp.handler - 611 - INFO - process-replication-data-11 - Fetching replication rows for 'typing' between 0 and 30
2023-07-23 19:59:10,689 - synapse.replication.tcp.handler - 634 - INFO - process-replication-data-0 - Caught up with stream 'caches' to 1847952
2023-07-23 19:59:10,689 - synapse.replication.tcp.handler - 611 - INFO - process-replication-data-0 - Fetching replication rows for 'caches' between 1847967 and 1847954
2023-07-23 19:59:10,692 - synapse.replication.tcp.handler - 634 - INFO - process-replication-data-0 - Caught up with stream 'caches' to 1847954
2023-07-23 19:59:10,692 - synapse.replication.tcp.handler - 611 - INFO - process-replication-data-0 - Fetching replication rows for 'caches' between 1847967 and 1847952
2023-07-23 19:59:10,695 - synapse.replication.tcp.handler - 634 - INFO - process-replication-data-0 - Caught up with stream 'caches' to 1847952
2023-07-23 19:59:10,695 - synapse.replication.tcp.handler - 611 - INFO - process-replication-data-0 - Fetching replication rows for 'caches' between 1847967 and 1847964
2023-07-23 19:59:10,697 - synapse.replication.tcp.handler - 634 - INFO - process-replication-data-0 - Caught up with stream 'caches' to 1847964
2023-07-23 19:59:10,697 - synapse.replication.tcp.handler - 611 - INFO - process-replication-data-0 - Fetching replication rows for 'caches' between 1847967 and 1847952
2023-07-23 19:59:10,702 - synapse.replication.tcp.handler - 634 - INFO - process-replication-data-0 - Caught up with stream 'caches' to 1847952
2023-07-23 19:59:10,702 - synapse.replication.tcp.handler - 611 - INFO - process-replication-data-0 - Fetching replication rows for 'caches' between 1847967 and 1847965
2023-07-23 19:59:10,704 - synapse.replication.tcp.handler - 634 - INFO - process-replication-data-0 - Caught up with stream 'caches' to 1847965
2023-07-23 19:59:10,704 - synapse.replication.tcp.handler - 611 - INFO - process-replication-data-0 - Fetching replication rows for 'caches' between 1847967 and 1847952
2023-07-23 19:59:10,707 - synapse.replication.tcp.handler - 634 - INFO - process-replication-data-0 - Caught up with stream 'caches' to 1847952
2023-07-23 19:59:10,707 - synapse.replication.tcp.handler - 611 - INFO - process-replication-data-0 - Fetching replication rows for 'caches' between 1847967 and 1847964
2023-07-23 19:59:10,709 - synapse.replication.tcp.handler - 634 - INFO - process-replication-data-0 - Caught up with stream 'caches' to 1847964
2023-07-23 19:59:10,709 - synapse.replication.tcp.handler - 611 - INFO - process-replication-data-0 - Fetching replication rows for 'caches' between 1847967 and 1847952
2023-07-23 19:59:10,710 - synapse.replication.tcp.handler - 634 - INFO - process-replication-data-0 - Caught up with stream 'caches' to 1847952
2023-07-23 19:59:10,718 - synapse.http.client - 924 - INFO - process-replication-data-11 - Received response to GET synapse-replication://event_worker/_synapse/replication/get_repl_stream_updates/typing/jyZIYXdyGO?from_token=0&upto_token=30: 200
2023-07-23 19:59:10,719 - synapse.replication.tcp.handler - 634 - INFO - process-replication-data-11 - Caught up with stream 'typing' to 30
2023-07-23 19:59:10,723 - synapse.http.client - 924 - INFO - GET-0 - Received response to POST synapse-replication://event_worker/_synapse/replication/presence_set_state/%40bot%3A3dns.eu: 200
2023-07-23 19:59:10,758 - synapse.access.http.9006 - 461 - INFO - GET-0 - 127.0.0.1 - 9006 - {@bot:3dns.eu} Processed request: 0.131sec/0.000sec (0.012sec, 0.001sec) (0.056sec/0.027sec/14) 1153B 200 "GET /_matrix/client/r0/sync?access_token=<redacted>&since=s2320197_59310996_30_2900375_729264_658_67342_4721181_0_8&timeout=3000 HTTP/1.1" "Python/3.11 aiohttp/3.8.4" [0 dbevts]
2023-07-23 19:59:10,769 - synapse.http.client - 924 - INFO - GET-1 - Received response to POST synapse-replication://event_worker/_synapse/replication/presence_set_state/%40bot%3A3dns.eu: 200
2023-07-23 19:59:11,208 - synapse.http.client - 924 - INFO - GET-2 - Received response to POST synapse-replication://event_worker/_synapse/replication/presence_set_state/%40cryexx%3A3dns.eu: 200
2023-07-23 19:59:11,212 - synapse.access.http.9006 - 461 - INFO - GET-1 - 127.0.0.1 - 9006 - {@bot:3dns.eu} Processed request: 0.444sec/0.001sec (0.005sec, 0.000sec) (0.001sec/0.005sec/3) 357B 200 "GET /_matrix/client/r0/sync?access_token=<redacted>&since=s2320200_59311008_30_2900375_729264_658_67342_4721181_0_8&timeout=3000 HTTP/1.1" "Python/3.11 aiohttp/3.8.4" [0 dbevts]
2023-07-23 19:59:11,225 - synapse.http.client - 924 - INFO - GET-3 - Received response to POST synapse-replication://event_worker/_synapse/replication/presence_set_state/%40bot%3A3dns.eu: 200
2023-07-23 19:59:11,248 - synapse.access.http.9006 - 461 - INFO - GET-2 - 178.13.85.140 - 9006 - {@cryexx:3dns.eu} Processed request: 0.069sec/0.002sec (0.009sec, 0.002sec) (0.004sec/0.028sec/13) 1172B 200 "GET /_matrix/client/r0/sync?filter=9&timeout=0&set_presence=unavailable&since=s2320197_59310996_30_2900375_729264_658_67342_4721181_0_8 HTTP/1.1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36.0 (KHTML, like Gecko) Chrome/114.0.5735.134 Safari/537.36.0" [0 dbevts]
2023-07-23 19:59:11,287 - synapse.http.client - 924 - INFO - GET-5 - Received response to POST synapse-replication://event_worker/_synapse/replication/presence_set_state/%40aimphetamin%3A3dns.eu: 200
2023-07-23 19:59:11,310 - synapse.http.client - 924 - INFO - GET-9 - Received response to POST synapse-replication://event_worker/_synapse/replication/presence_set_state/%40cryexx%3A3dns.eu: 200
2023-07-23 19:59:11,318 - synapse.http.client - 924 - INFO - GET-8 - Received response to POST synapse-replication://event_worker/_synapse/replication/presence_set_state/%40test5%3A3dns.eu: 200
2023-07-23 19:59:11,328 - synapse.http.client - 924 - INFO - GET-4 - Received response to POST synapse-replication://event_worker/_synapse/replication/presence_set_state/%40dom1nic%3A3dns.eu: 200
2023-07-23 19:59:11,330 - synapse.http.client - 924 - INFO - GET-7 - Received response to POST synapse-replication://event_worker/_synapse/replication/presence_set_state/%40test5%3A3dns.eu: 200
2023-07-23 19:59:11,331 - synapse.http.client - 924 - INFO - GET-6 - Received response to POST synapse-replication://event_worker/_synapse/replication/presence_set_state/%40dom1nic%3A3dns.eu: 200
2023-07-23 19:59:11,354 - synapse.http.client - 924 - INFO - GET-10 - Received response to POST synapse-replication://event_worker/_synapse/replication/presence_set_state/%40cryexx%3A3dns.eu: 200
2023-07-23 19:59:11,371 - synapse.http.client - 924 - INFO - GET-11 - Received response to POST synapse-replication://event_worker/_synapse/replication/presence_set_state/%40test6%3A3dns.eu: 200
2023-07-23 19:59:11,373 - synapse.http.client - 924 - INFO - GET-12 - Received response to POST synapse-replication://event_worker/_synapse/replication/presence_set_state/%40test6%3A3dns.eu: 200
2023-07-23 19:59:11,373 - synapse.access.http.9006 - 461 - INFO - GET-3 - 127.0.0.1 - 9006 - {@bot:3dns.eu} Processed request: 0.137sec/0.015sec (0.004sec, 0.000sec) (0.006sec/0.011sec/3) 373B 200 "GET /_matrix/client/r0/sync?access_token=<redacted>&since=s2320200_59311009_30_2900375_729264_658_67342_4721181_0_8&timeout=3000 HTTP/1.1" "Python/3.11 aiohttp/3.8.4" [0 dbevts]
2023-07-23 19:59:11,379 - synapse.http.client - 924 - INFO - GET-13 - Received response to POST synapse-replication://event_worker/_synapse/replication/presence_set_state/%40test5%3A3dns.eu: 200
2023-07-23 19:59:11,397 - synapse.access.http.9006 - 461 - INFO - GET-9 - 127.0.0.1 - 9006 - {@cryexx:3dns.eu} Processed request: 0.133sec/0.010sec (0.009sec, 0.002sec) (0.013sec/0.018sec/5) 1189B 200 "GET /_matrix/client/r0/sync?timeout=30000&since=s2320197_59310997_30_2900375_729264_658_67342_4721181_0_8&filter=%7B%22room%22%3A%7B%22timeline%22%3A%7B%22limit%22%3A50%7D%7D%7D HTTP/1.1" "sync-v3-proxy-0.99.4" [0 dbevts]
2023-07-23 19:59:11,412 - synapse.http.client - 924 - INFO - GET-15 - Received response to POST synapse-replication://event_worker/_synapse/replication/presence_set_state/%40bot%3A3dns.eu: 200
2023-07-23 19:59:11,433 - synapse.http.client - 924 - INFO - GET-14 - Received response to POST synapse-replication://event_worker/_synapse/replication/presence_set_state/%40cryexx%3A3dns.eu: 200
2023-07-23 19:59:11,433 - synapse.replication.tcp.client - 321 - INFO - GET-14 - Waiting for repl stream 'presence' to reach 59311011 (event_worker); currently at: 59311010
2023-07-23 19:59:11,435 - synapse.replication.tcp.client - 341 - INFO - GET-14 - Finished waiting for repl stream 'presence' to reach 59311011 (event_worker)
2023-07-23 19:59:11,447 - synapse.access.http.9006 - 461 - INFO - GET-10 - 127.0.0.1 - 9006 - {@cryexx:3dns.eu} Processed request: 0.149sec/0.003sec (0.009sec, 0.001sec) (0.019sec/0.046sec/9) 1151B 200 "GET /_matrix/client/r0/sync?timeout=30000&since=s2320197_59310994_30_2900375_729264_658_67342_4721181_0_8&filter=%7B%22room%22%3A%7B%22timeline%22%3A%7B%22limit%22%3A50%7D%7D%7D HTTP/1.1" "sync-v3-proxy-0.99.4" [0 dbevts]
2023-07-23 19:59:11,467 - synapse.http.client - 924 - INFO - GET-16 - Received response to POST synapse-replication://event_worker/_synapse/replication/presence_set_state/%40cryexx%3A3dns.eu: 200
2023-07-23 19:59:11,476 - synapse.http.client - 924 - INFO - GET-17 - Received response to POST synapse-replication://event_worker/_synapse/replication/presence_set_state/%40cryexx%3A3dns.eu: 200
2023-07-23 19:59:11,494 - synapse.access.http.9006 - 461 - INFO - GET-5 - 127.0.0.1 - 9006 - {@aimphetamin:3dns.eu} Processed request: 0.240sec/0.008sec (0.013sec, 0.002sec) (0.075sec/0.054sec/14) 1042B 200 "GET /_matrix/client/r0/sync?timeout=30000&since=s2320197_59310996_30_2900375_729264_658_67342_4721181_0_8&filter=%7B%22room%22%3A%7B%22timeline%22%3A%7B%22limit%22%3A50%7D%7D%7D HTTP/1.1" "sync-v3-proxy-0.99.4" [0 dbevts]
2023-07-23 19:59:11,500 - synapse.access.http.9006 - 461 - INFO - GET-15 - 127.0.0.1 - 9006 - {@bot:3dns.eu} Processed request: 0.086sec/0.007sec (0.002sec, 0.001sec) (0.013sec/0.028sec/3) 373B 200 "GET /_matrix/client/r0/sync?access_token=<redacted>&since=s2320200_59311010_30_2900375_729264_658_67342_4721181_0_8&timeout=3000 HTTP/1.1" "Python/3.11 aiohttp/3.8.4" [0 dbevts]
2023-07-23 19:59:11,505 - synapse.access.http.9006 - 461 - INFO - GET-14 - 178.13.85.140 - 9006 - {@cryexx:3dns.eu} Processed request: 0.097sec/0.012sec (0.004sec, 0.001sec) (0.007sec/0.027sec/3) 411B 200 "GET /_matrix/client/r0/sync?filter=9&timeout=30000&set_presence=unavailable&since=s2320200_59311009_30_2900375_729264_658_67342_4721181_0_8 HTTP/1.1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36.0 (KHTML, like Gecko) Chrome/114.0.5735.134 Safari/537.36.0" [0 dbevts]
2023-07-23 19:59:11,540 - synapse.access.http.9006 - 461 - INFO - GET-17 - 127.0.0.1 - 9006 - {@cryexx:3dns.eu} Processed request: 0.061sec/0.019sec (0.004sec, 0.003sec) (0.008sec/0.017sec/3) 373B 200 "GET /_matrix/client/r0/sync?timeout=30000&since=s2320200_59311010_30_2900375_729264_658_67342_4721181_0_8&filter=%7B%22room%22%3A%7B%22timeline%22%3A%7B%22limit%22%3A50%7D%7D%7D HTTP/1.1" "sync-v3-proxy-0.99.4" [0 dbevts]
2023-07-23 19:59:11,540 - synapse.access.http.9006 - 461 - INFO - GET-16 - 127.0.0.1 - 9006 - {@cryexx:3dns.eu} Processed request: 0.110sec/0.016sec (0.008sec, 0.001sec) (0.008sec/0.025sec/3) 411B 200 "GET /_matrix/client/r0/sync?timeout=30000&since=s2320200_59311010_30_2900375_729264_658_67342_4721181_0_8&filter=%7B%22room%22%3A%7B%22timeline%22%3A%7B%22limit%22%3A50%7D%7D%7D HTTP/1.1" "sync-v3-proxy-0.99.4" [0 dbevts]
2023-07-23 19:59:11,559 - synapse.http.client - 924 - INFO - GET-19 - Received response to POST synapse-replication://event_worker/_synapse/replication/presence_set_state/%40bot%3A3dns.eu: 200
2023-07-23 19:59:11,560 - synapse.http.client - 924 - INFO - GET-18 - Received response to POST synapse-replication://event_worker/_synapse/replication/presence_set_state/%40aimphetamin%3A3dns.eu: 200

Anything else that would be useful to know?

No response

reivilibre commented 1 year ago

Hi, thanks for your report!

I think what may be happening here is that the sliding sync proxy, which is always polling /sync for the devices that use it, is accidentally updating the presence state of its users to 'online'. This directly creates a bit of extra busy work for Synapse to do, but probably more importantly causes a knock-on effect where we wake up the /sync loops for other devices that are syncing in order to tell them about this updated presence.

Ideally the sliding sync proxy would not get involved in presence if it's not equipped to do so properly (as far as I know this is being left as a future extension).

I've opened a couple of tickets with the Sliding Sync proxy team: https://github.com/matrix-org/sliding-sync/issues/218 and https://github.com/matrix-org/sliding-sync/issues/217.

Once they're solved it would be worth looking at this situation again.

Edit: will put this on a list for us to come back to in the future.

DMRobertson commented 1 year ago

Once https://github.com/matrix-org/sliding-sync/pull/292 is in the proxy and clokep's recent presence work has landed (https://github.com/matrix-org/synapse/issues/16057 I think?) we think this should be mitigated. These should be available in the next sliding sync proxy release (0.99.11? current is 0.99.10) and the next Synapse release (1.93).

@DoM1niC: when these releases are out, can you test this with your deployment to confirm that the CPU usage is more reasonable?

DoM1niC commented 1 year ago

Sure I will do 👍

DoM1niC commented 1 year ago

Looks good so far .... no issues yet

erikjohnston commented 11 months ago

We think this is now fixed. Shout if its not and we'll reopen!