Skip to content
This repository has been archived by the owner on Apr 26, 2024. It is now read-only.

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

Closed
DoM1niC opened this issue Jul 23, 2023 · 5 comments
Closed

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

DoM1niC opened this issue Jul 23, 2023 · 5 comments
Labels
A-Performance Performance, both client-facing and admin-facing A-Presence A-Sync defects related to /sync O-Uncommon Most users are unlikely to come across this or unexpected workflow S-Major Major functionality / product severely impaired, no satisfactory workaround. T-Other Questions, user support, anything else.
Milestone
Revisit: Next Month

Comments

@DoM1niC
Copy link

DoM1niC commented Jul 23, 2023 •
edited
Loading

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

  • set presence: enabled: false start your Workers, all is fine
  • start Workers with Boolean True and the CPU Usage will start

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
@DoM1niC DoM1niC changed the title Sync v2 feat v3 takes a lot of CPU since because Presence Sync v2 feat v3 takes a lot of CPU causing by Presence Jul 23, 2023
This was referenced Jul 24, 2023
Closed
Closed
@reivilibre
Copy link
Contributor

reivilibre commented Jul 24, 2023 •
edited
Loading

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: matrix-org/sliding-sync#218 and matrix-org/sliding-sync#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.

@reivilibre reivilibre added A-Presence A-Sync defects related to /sync S-Major Major functionality / product severely impaired, no satisfactory workaround. T-Other Questions, user support, anything else. labels Jul 24, 2023
@reivilibre reivilibre changed the title Sync v2 feat v3 takes a lot of CPU causing by Presence Sliding Sync Proxy + Presence enabled leads to high CPU usage Jul 24, 2023
@reivilibre reivilibre added this to the Revisit: Next Month milestone Jul 24, 2023
@reivilibre reivilibre added O-Uncommon Most users are unlikely to come across this or unexpected workflow A-Performance Performance, both client-facing and admin-facing labels Jul 24, 2023
@realtyem realtyem mentioned this issue Jul 24, 2023
Open
@MTRNord MTRNord mentioned this issue Jul 31, 2023
Closed
@QEDeD QEDeD mentioned this issue Aug 2, 2023
Closed
@t3chguy t3chguy mentioned this issue Aug 3, 2023
Closed
@phil-s phil-s mentioned this issue Aug 3, 2023
Open
@DMRobertson
Copy link
Contributor

DMRobertson commented Sep 7, 2023 •
edited
Loading

Once matrix-org/sliding-sync#292 is in the proxy and clokep's recent presence work has landed (#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
Copy link
Author

DoM1niC commented Sep 7, 2023

Sure I will do 👍

@DoM1niC
Copy link
Author

DoM1niC commented Sep 11, 2023

Looks good so far .... no issues yet

@erikjohnston
Copy link
Member

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

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
A-Performance Performance, both client-facing and admin-facing A-Presence A-Sync defects related to /sync O-Uncommon Most users are unlikely to come across this or unexpected workflow S-Major Major functionality / product severely impaired, no satisfactory workaround. T-Other Questions, user support, anything else.
Projects
None yet
Milestone
Revisit: Next Month
Development

No branches or pull requests
4 participants
@DoM1niC @erikjohnston @DMRobertson @reivilibre