Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

My server takes up a lot of CPU and RAM after a database restore #17138

Open
Cocam123 opened this issue Apr 30, 2024 · 17 comments
Open

My server takes up a lot of CPU and RAM after a database restore #17138

Cocam123 opened this issue Apr 30, 2024 · 17 comments

Comments

@Cocam123
Copy link

Description

Since I restored a backup of my database, I've been unable to connect to synapse matrix. It simply takes up all the RAM and CPU available on the server.

I've talked about it on the matrix channel, but we haven't managed to solve the problem.

I tried REINDEX and VACUUM FULL. I also disabled presence and changed some federation parameters in homeserver.yalm :
federation:
destination_min_retry_interval: 1m
destination_retry_multiplier: 5
destination_max_retry_interval: 365d

but after reboot, the same problems occur

Steps to reproduce

  • Drop database
  • Install the backup
  • Launch synapse matrix

Homeserver

matrix.cocamserverguild.com

Synapse Version

1.105.1

Installation Method

Debian packages from packages.matrix.org

Database

PostgreSQL (single one, restored from a backup)

Workers

Single process

Platform

It's running on a Debian machine on a VPS.

2 CPU, 4 Go RAM

Configuration

No response

Relevant log output

2024-04-30 18:21:38,774 - synapse.app.homeserver - 356 - INFO - main - Setting up server
2024-04-30 18:21:38,775 - synapse.server - 345 - INFO - main - Setting up.
2024-04-30 18:21:38,832 - synapse.storage.databases - 73 - INFO - main - [database config 'master']: Checking database server
2024-04-30 18:21:38,870 - synapse.storage.databases - 76 - INFO - main - [database config 'master']: Preparing for databases ['main', 'state']
2024-04-30 18:21:38,870 - synapse.storage.prepare_database - 135 - INFO - main - ['main', 'state']: Checking existing schema version
2024-04-30 18:21:38,896 - synapse.storage.prepare_database - 139 - INFO - main - ['main', 'state']: Existing schema is 84 (+4 deltas)
2024-04-30 18:21:38,896 - synapse.storage.databases.main - 391 - INFO - main - Checking database for consistency with configuration...
2024-04-30 18:21:38,904 - synapse.storage.prepare_database - 433 - INFO - main - Applying schema deltas for v84
2024-04-30 18:21:38,916 - synapse.storage.prepare_database - 568 - INFO - main - Schema now up to date
2024-04-30 18:21:38,920 - synapse.storage.databases - 91 - INFO - main - [database config 'master']: Starting 'main' database
2024-04-30 18:21:42,990 - synapse.storage.util.id_generators - 99 - INFO - main - Initialising stream generator for pushers(id): 3770
2024-04-30 18:21:42,994 - synapse.storage.util.id_generators - 99 - INFO - main - Initialising stream generator for deleted_pushers(stream_id): 3733
2024-04-30 18:21:42,999 - synapse.storage.util.id_generators - 99 - INFO - main - Initialising stream generator for push_rules_stream(stream_id): 176
2024-04-30 18:21:43,010 - synapse.storage.util.id_generators - 99 - INFO - main - Initialising stream generator for push_rules(id): 37
2024-04-30 18:21:43,014 - synapse.storage.util.id_generators - 99 - INFO - main - Initialising stream generator for push_rules_enable(id): 63
2024-04-30 18:21:43,049 - synapse.storage.util.id_generators - 99 - INFO - main - Initialising stream generator for e2e_cross_signing_keys(stream_id): 51451
2024-04-30 18:21:43,050 - synapse.storage.databases.main.event_push_actions - 1247 - INFO - main - Searching for stream ordering 1 month ago
2024-04-30 18:21:43,073 - synapse.storage.databases.main.event_push_actions - 1251 - INFO - main - Found stream ordering 1 month ago: it's 522175
2024-04-30 18:21:43,073 - synapse.storage.databases.main.event_push_actions - 1254 - INFO - main - Searching for stream ordering 1 day ago
2024-04-30 18:21:43,085 - synapse.storage.databases.main.event_push_actions - 1258 - INFO - main - Found stream ordering 1 day ago: it's 611265
2024-04-30 18:21:43,392 - synapse.storage.util.id_generators - 99 - INFO - main - Initialising stream generator for access_tokens(id): 213
2024-04-30 18:21:43,396 - synapse.storage.util.id_generators - 99 - INFO - main - Initialising stream generator for refresh_tokens(id): 1
2024-04-30 18:21:43,408 - synapse.storage.util.id_generators - 99 - INFO - main - Initialising stream generator for event_reports(id): 2
2024-04-30 18:21:43,415 - synapse.storage.util.id_generators - 99 - INFO - main - Initialising stream generator for device_lists_stream(stream_id): 1472508
2024-04-30 18:21:43,417 - synapse.storage.util.id_generators - 99 - INFO - main - Initialising stream generator for user_signature_stream(stream_id): 1
2024-04-30 18:21:43,427 - synapse.storage.util.id_generators - 99 - INFO - main - Initialising stream generator for device_lists_outbound_pokes(stream_id): 1454833
2024-04-30 18:21:43,436 - synapse.storage.util.id_generators - 99 - INFO - main - Initialising stream generator for device_lists_changes_in_room(stream_id): 1472508
2024-04-30 18:21:43,440 - synapse.storage.util.id_generators - 99 - INFO - main - Initialising stream generator for device_lists_remote_pending(stream_id): 1472510
2024-04-30 18:21:43,448 - synapse.storage.util.id_generators - 99 - INFO - main - Initialising stream generator for device_lists_changes_converted_stream_position(stream_id): 1472510
2024-04-30 18:21:43,755 - synapse.storage.databases - 108 - INFO - main - [database config 'master']: Starting 'state' database
2024-04-30 18:21:43,764 - synapse.storage.databases - 123 - INFO - main - [database config 'master']: prepared
2024-04-30 18:21:43,770 - synapse.server - 348 - INFO - main - Finished setting up.
2024-04-30 18:21:43,819 - synapse.push.pusher - 45 - INFO - main - email enable notifs: False
2024-04-30 18:21:43,822 - synapse.federation.federation_server - 1379 - INFO - main - Registering federation EDU handler for 'm.device_list_update'
2024-04-30 18:21:43,823 - synapse.federation.federation_server - 1399 - INFO - main - Registering federation query handler for 'profile'
2024-04-30 18:21:43,824 - synapse.federation.federation_server - 1379 - INFO - main - Registering federation EDU handler for 'm.presence'
2024-04-30 18:21:43,830 - synapse.federation.federation_server - 1379 - INFO - main - Registering federation EDU handler for 'm.typing'
2024-04-30 18:21:43,831 - synapse.federation.federation_server - 1399 - INFO - main - Registering federation query handler for 'directory'
2024-04-30 18:21:43,832 - twisted - 282 - INFO - main - Redirected stdout/stderr to logs
2024-04-30 18:21:43,833 - synapse.app.homeserver - 179 - INFO - sentinel - Running
2024-04-30 18:21:43,836 - synapse.app.homeserver - 36 - INFO - sentinel - Set file limit to: 524288
2024-04-30 18:21:43,842 - synapse.handlers.deactivate_account - 245 - INFO - user_parter_loop-0 - Starting user parter
2024-04-30 18:21:43,933 - synapse.util.caches.lrucache - 231 - INFO - sentinel - Expiring LRU caches after 1800 seconds
2024-04-30 18:21:43,942 - synapse.push.mailer - 138 - INFO - sentinel - Created Mailer for app_name Cocamserverguild
2024-04-30 18:21:43,943 - synapse.push.mailer - 138 - INFO - sentinel - Created Mailer for app_name Cocamserverguild
2024-04-30 18:21:43,944 - synapse.push.mailer - 138 - INFO - sentinel - Created Mailer for app_name Cocamserverguild
2024-04-30 18:21:43,944 - synapse.federation.federation_server - 1379 - INFO - sentinel - Registering federation EDU handler for 'm.receipt'
2024-04-30 18:21:43,945 - synapse.federation.federation_server - 1379 - INFO - sentinel - Registering federation EDU handler for 'm.signing_key_update'
2024-04-30 18:21:43,945 - synapse.federation.federation_server - 1379 - INFO - sentinel - Registering federation EDU handler for 'org.matrix.signing_key_update'
2024-04-30 18:21:43,945 - synapse.federation.federation_server - 1399 - INFO - sentinel - Registering federation query handler for 'client_keys'
2024-04-30 18:21:43,945 - synapse.federation.federation_server - 1379 - INFO - sentinel - Registering federation EDU handler for 'm.direct_to_device'
2024-04-30 18:21:43,964 - synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching <synapse.rest.health.HealthResource object at 0x7f4c9829d100> to path b'/health'
2024-04-30 18:21:43,964 - synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching <synapse.rest.ClientRestResource object at 0x7f4c9829d220> to path b'/_matrix/client'
2024-04-30 18:21:43,964 - synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching <twisted.web.resource.Resource object at 0x7f4c9825cca0> to path b'/.well-known'
2024-04-30 18:21:43,964 - synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching <synapse.rest.admin.AdminRestResource object at 0x7f4c9825ceb0> to path b'/_synapse/admin'
2024-04-30 18:21:43,964 - synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching <synapse.rest.synapse.client.pick_idp.PickIdpResource object at 0x7f4c981f4910> to path b'/_synapse/client/pick_idp'
2024-04-30 18:21:43,964 - synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching <twisted.web.resource.Resource object at 0x7f4c981f49d0> to path b'/_synapse/client/pick_username'
2024-04-30 18:21:43,964 - synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching <synapse.rest.synapse.client.new_user_consent.NewUserConsentResource object at 0x7f4c981f4d00> to path b'/_synapse/client/new_user_consent'
2024-04-30 18:21:43,964 - synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching <synapse.rest.synapse.client.sso_register.SsoRegisterResource object at 0x7f4c981f4d30> to path b'/_synapse/client/sso_register'
2024-04-30 18:21:43,964 - synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching <synapse.rest.synapse.client.unsubscribe.UnsubscribeResource object at 0x7f4c981f4fa0> to path b'/_synapse/client/unsubscribe'
2024-04-30 18:21:43,965 - synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching <synapse.rest.synapse.client.password_reset.PasswordResetSubmitTokenResource object at 0x7f4c981f4fd0> to path b'/_synapse/client/password_reset/email/submit_token'
2024-04-30 18:21:43,965 - synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching FilePath('/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/static') to path b'/_matrix/static'
2024-04-30 18:21:43,965 - synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching <synapse.rest.media.media_repository_resource.MediaRepositoryResource object at 0x7f4c981fb040> to path b'/_matrix/media/r0'
2024-04-30 18:21:43,965 - synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching <synapse.rest.media.media_repository_resource.MediaRepositoryResource object at 0x7f4c981fb040> to path b'/_matrix/media/v3'
2024-04-30 18:21:43,965 - synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching <synapse.rest.media.media_repository_resource.MediaRepositoryResource object at 0x7f4c981fb040> to path b'/_matrix/media/v1'
2024-04-30 18:21:43,965 - synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching <synapse.federation.transport.server.TransportLayerServer object at 0x7f4c981fb6a0> to path b'/_matrix/federation'
2024-04-30 18:21:43,965 - synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching <synapse.rest.key.v2.KeyResource object at 0x7f4c981fb760> to path b'/_matrix/key'
2024-04-30 18:21:43,965 - synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching <synapse.rest.consent.consent_resource.ConsentResource object at 0x7f4c9820d790> to path b'/_matrix/consent'
2024-04-30 18:21:43,966 - twisted - 282 - INFO - sentinel - SynapseSite starting on 8008
2024-04-30 18:21:43,966 - twisted - 282 - INFO - sentinel - SynapseSite starting on 8008
2024-04-30 18:21:43,967 - synapse.app._base - 438 - INFO - sentinel - Synapse now listening on TCP port 8008
2024-04-30 18:21:44,108 - synapse.storage.background_updates - 415 - INFO - background_updates-0 - Starting background schema updates for database master
2024-04-30 18:21:44,110 - synapse.handlers.deactivate_account - 255 - INFO - user_parter_loop-0 - User parter finished: stopping
2024-04-30 18:21:44,111 - synapse.federation.sender - 1019 - INFO - wake_destinations_needing_catchup-0 - Destination xmr.se has outstanding catch-up, waking up.
2024-04-30 18:21:44,147 - synapse.storage.background_updates - 433 - INFO - background_updates-0 - No more background updates to do. Unscheduling background update task.
2024-04-30 18:21:44,148 - synapse.push.pusherpool - 424 - INFO - start_pushers-0 - Starting pusher @misaki:matrix.cocamserverguild.com / im.vector.app.android:eYzsIrKgTlCTZXLArVex2h:APA91bGh_09iiotAPpBNsga2fprmVqfoNmdtdzE7SgkOFKsDu-FxDXhIGCGlrHdpNiGRs772rH_0G4H8azbYpsa-IayBV_XxBsfxKQTTfa7F3eCr-Tvp7OUEr3iScRBUV9W2w1Sol9xK
2024-04-30 18:21:44,149 - synapse.push.pusherpool - 424 - INFO - start_pushers-0 - Starting pusher @deathlock666:matrix.cocamserverguild.com / im.vector.app.ios.prod:ftea9GWaL/oXoGmCnYHI52q6qXk35dG3IMFAKJJUjwc=
2024-04-30 18:21:44,150 - synapse.push.pusherpool - 424 - INFO - start_pushers-0 - Starting pusher @bruneau:matrix.cocamserverguild.com / im.vector.app.android:d3sBZXREQn-fg4lOle6HYR:APA91bGNlu8NeyorDyX87mT51hggxbtWmJNTw_4pN5DE0Wf5vy8hcXgavdxSOqXVlrQ_VD1rXW3MX9MKUQGw0fV692AgZyWV3zjAPYzE4niYlpLVCY6evuZmfJW7lk4jZPcIjm1_RFwm
2024-04-30 18:21:44,152 - synapse.push.pusherpool - 424 - INFO - start_pushers-0 - Starting pusher @sandra:matrix.cocamserverguild.com / im.vector.app.android:fTx6LibkSvqUte3EK663_k:APA91bGAfyrCb0b6loApJDOw5dFFnok5BAXX0LeakDzZloDOQUVE1PXTo93UxgejyhUB6WcP_Ba0csfrmDd5zIkWML3biPjt5yfergkC4ZklYk7OSXO8iNabsoy5xeGjBdE22km4Su-o
2024-04-30 18:21:44,155 - synapse.push.pusherpool - 424 - INFO - start_pushers-0 - Starting pusher @vert_of_leanbox:matrix.cocamserverguild.com / im.vector.app.android:dyzYTAvdRQ-SuMus1uzZDo:APA91bGWhYk_3YSeruWMogXYxnVZ7aJxW1zw5799ZeJFgFwVrs6Vsajl0vqw70olRQ5mesX3EC5w65lwxmGNe4PIvBIWfBAB7o4WPPc6AWTGpn-1h22J0Sozt-zO8w4naSIH-dkYBHqz
2024-04-30 18:21:44,155 - synapse.push.pusherpool - 424 - INFO - start_pushers-0 - Starting pusher @alexisauvinet1999:matrix.cocamserverguild.com / im.vector.app.android:fLp0WSl3TDyPu1OrDJCE8D:APA91bG7QCEte0kZMuUo4v5WqBvUwsx8aYo6BIjIYHon0jSjOkPJ-j4ri9Abu9KFXgzIUYOZ0tWvBAu73r2P9TVZCdH12CHRpJTXEXdQ3RJK9lfX9mL2oQ776mEaE5qe8zRMyZ62BS9Z
2024-04-30 18:21:44,158 - synapse.push.pusherpool - 424 - INFO - start_pushers-0 - Starting pusher @seiso_san:matrix.cocamserverguild.com / im.vector.app.ios.prod:kmbOMwOS2gAi8RBiEpYe/BVZA6EeVRcXqH3J1brFuyw=
2024-04-30 18:21:44,170 - synapse.push.pusherpool - 424 - INFO - start_pushers-0 - Starting pusher @ahykono:matrix.cocamserverguild.com / im.vector.app.android:fSY6IGsQRFug9Hzd0u1Z0X:APA91bEfr-ziSCQZWM3HWAg20bzt2xsGhvLvDXmUO5gdkUMPPSIc4a-h3a3LGxPnkExC3AHW_V6MQbJHam6Fntj_SuBukLwrsT47Wz9vfwiqikHRBrXNC5LuZaAVuPtxxIQs9dFSf7Eq
2024-04-30 18:21:44,171 - synapse.push.pusherpool - 424 - INFO - start_pushers-0 - Starting pusher @dragonwielder200:matrix.cocamserverguild.com / im.vector.app.ios.prod:mMaEMxcZ4geHI7T+RD4dbPNl9vFyb/mamaqZPBPvEJg=
2024-04-30 18:21:44,172 - synapse.push.pusherpool - 424 - INFO - start_pushers-0 - Starting pusher @jaymel120:matrix.cocamserverguild.com / im.vector.app.ios.prod:Eo4Whj7Lu9OkMsUoAIQqmnRk6wNDqLWWyp0MxoMN4i8=
2024-04-30 18:21:44,205 - synapse.push.pusherpool - 372 - INFO - start_pushers-0 - Started pushers
2024-04-30 18:21:44,235 - synapse.federation.sender.transaction_manager - 127 - INFO - federation_transaction_transmission_loop-0 - TX [xmr.se] {1714501303820} Sending transaction [1714501303820], (PDUs: 0, EDUs: 3)
2024-04-30 18:21:44,237 - synapse.http.federation.well_known_resolver - 260 - INFO - federation_transaction_transmission_loop-0 - Fetching https://xmr.se/.well-known/matrix/server
2024-04-30 18:21:44,247 - synapse.http.client - 200 - INFO - sentinel - Blocked 45.154.252.164 from DNS resolution to xmr.se
2024-04-30 18:21:44,247 - synapse.http.federation.well_known_resolver - 291 - INFO - federation_transaction_transmission_loop-0 - Error fetching https://xmr.se/.well-known/matrix/server: DNS lookup failed: no results for hostname lookup: xmr.se.
2024-04-30 18:21:44,249 - twisted - 282 - INFO - federation_transaction_transmission_loop-0 - b'/etc/resolv.conf' changed, reparsing
2024-04-30 18:21:44,250 - twisted - 282 - INFO - federation_transaction_transmission_loop-0 - Resolver added ('8.8.8.8', 53) to server list
2024-04-30 18:21:44,250 - twisted - 282 - INFO - federation_transaction_transmission_loop-0 - Resolver added ('8.8.4.4', 53) to server list
2024-04-30 18:21:44,309 - synapse.http.client - 200 - INFO - sentinel - Blocked 45.154.252.164 from DNS resolution to xmr.se
2024-04-30 18:21:44,309 - synapse.http.federation.matrix_federation_agent - 371 - INFO - federation_transaction_transmission_loop-0 - Failed to connect to xmr.se:443: DNS lookup failed: no results for hostname lookup: xmr.se.
2024-04-30 18:21:44,310 - synapse.http.matrixfederationclient - 799 - INFO - federation_transaction_transmission_loop-0 - {PUT-O-1} [xmr.se] Request failed: PUT matrix-federation://xmr.se/_matrix/federation/v1/send/1714501303820: DNSLookupError('no results for hostname lookup: xmr.se')
2024-04-30 18:21:44,423 - synapse.crypto.keyring - 677 - INFO - PerspectivesKeyFetcher-0 - Requesting keys [_FetchKeyRequest(server_name='reboot.fi', minimum_valid_until_ts=1714501304410, key_ids=['ed25519:a_vsul'])] from notary server matrix.org
2024-04-30 18:21:44,424 - synapse.crypto.keyring - 677 - INFO - PerspectivesKeyFetcher-0 - Requesting keys [_FetchKeyRequest(server_name='reboot.fi', minimum_valid_until_ts=1714501304410, key_ids=['ed25519:a_vsul'])] from notary server cocamserverguild.com
2024-04-30 18:21:44,429 - synapse.http.federation.well_known_resolver - 260 - INFO - PerspectivesKeyFetcher-0 - Fetching https://matrix.org/.well-known/matrix/server
2024-04-30 18:21:44,431 - synapse.crypto.keyring - 632 - WARNING - PerspectivesKeyFetcher-0 - Key lookup failed from 'cocamserverguild.com': Not retrying server cocamserverguild.com because we tried it recently retry_last_ts=1714500351439 and we won't check for another retry_interval=12990479ms.
2024-04-30 18:21:44,498 - synapse.http.federation.well_known_resolver - 197 - INFO - PerspectivesKeyFetcher-0 - Response from .well-known: {'m.server': 'matrix-federation.matrix.org:443'}
2024-04-30 18:21:44,650 - synapse.http.matrixfederationclient - 362 - INFO - PerspectivesKeyFetcher-0 - {POST-O-2} [matrix.org] Completed request: 200 OK in 0.23 secs, got 438 bytes - POST matrix-federation://matrix.org/_matrix/key/v2/query
2024-04-30 18:21:44,688 - synapse.federation.transport.server.federation - 112 - INFO - PUT-0 - Received txn 1713943604393 from reboot.fi. (PDUs: 0, EDUs: 1)
2024-04-30 18:21:44,755 - synapse.access.http.8008 - 472 - INFO - PUT-0 - 81.6.39.188 - 8008 - {reboot.fi} Processed request: 0.344sec/0.001sec (0.008sec, 0.002sec) (0.004sec/0.050sec/8) 11B 200 "PUT /_matrix/federation/v1/send/1713943604393 HTTP/1.1" "Synapse/1.105.1" [0 dbevts]
2024-04-30 18:21:49,634 - synapse.crypto.keyring - 677 - INFO - PerspectivesKeyFetcher-1 - Requesting keys [_FetchKeyRequest(server_name='roguesrepast.cafe', minimum_valid_until_ts=1714501309628, key_ids=['ed25519:a_OHzH'])] from notary server matrix.org
2024-04-30 18:21:49,637 - synapse.crypto.keyring - 677 - INFO - PerspectivesKeyFetcher-1 - Requesting keys [_FetchKeyRequest(server_name='roguesrepast.cafe', minimum_valid_until_ts=1714501309628, key_ids=['ed25519:a_OHzH'])] from notary server cocamserverguild.com
2024-04-30 18:21:49,637 - synapse.crypto.keyring - 632 - WARNING - PerspectivesKeyFetcher-1 - Key lookup failed from 'cocamserverguild.com': Not retrying server cocamserverguild.com because we tried it recently retry_last_ts=1714500351439 and we won't check for another retry_interval=12990479ms.
2024-04-30 18:21:49,857 - synapse.http.client - 200 - INFO - sentinel - Blocked 45.154.252.164 from DNS resolution to xmr.se
2024-04-30 18:21:49,857 - synapse.http.federation.matrix_federation_agent - 371 - INFO - federation_transaction_transmission_loop-0 - Failed to connect to xmr.se:443: DNS lookup failed: no results for hostname lookup: xmr.se.
2024-04-30 18:21:49,857 - synapse.http.matrixfederationclient - 799 - INFO - federation_transaction_transmission_loop-0 - {PUT-O-1} [xmr.se] Request failed: PUT matrix-federation://xmr.se/_matrix/federation/v1/send/1714501303820: DNSLookupError('no results for hostname lookup: xmr.se')
2024-04-30 18:21:50,264 - synapse.http.matrixfederationclient - 362 - INFO - PerspectivesKeyFetcher-1 - {POST-O-4} [matrix.org] Completed request: 200 OK in 0.63 secs, got 454 bytes - POST matrix-federation://matrix.org/_matrix/key/v2/query
2024-04-30 18:21:50,281 - synapse.federation.transport.server.federation - 112 - INFO - PUT-1 - Received txn 1714181631145 from roguesrepast.cafe. (PDUs: 0, EDUs: 1)
2024-04-30 18:21:50,282 - synapse.federation.transport.server.federation - 112 - INFO - PUT-2 - Received txn 1714181631145 from roguesrepast.cafe. (PDUs: 0, EDUs: 1)
2024-04-30 18:21:50,282 - synapse.util.caches.response_cache - 275 - INFO - PUT-2 - [fed_txn_handler]: using incomplete cached result for [('roguesrepast.cafe', '1714181631145')]
2024-04-30 18:21:50,282 - synapse.federation.transport.server.federation - 112 - INFO - PUT-3 - Received txn 1714181631145 from roguesrepast.cafe. (PDUs: 0, EDUs: 1)
2024-04-30 18:21:50,282 - synapse.util.caches.response_cache - 275 - INFO - PUT-3 - [fed_txn_handler]: using incomplete cached result for [('roguesrepast.cafe', '1714181631145')]
2024-04-30 18:21:50,282 - synapse.federation.transport.server.federation - 112 - INFO - PUT-4 - Received txn 1714181631145 from roguesrepast.cafe. (PDUs: 0, EDUs: 1)
2024-04-30 18:21:50,284 - synapse.util.caches.response_cache - 275 - INFO - PUT-4 - [fed_txn_handler]: using incomplete cached result for [('roguesrepast.cafe', '1714181631145')]
2024-04-30 18:21:50,284 - synapse.federation.transport.server.federation - 112 - INFO - PUT-5 - Received txn 1714181631145 from roguesrepast.cafe. (PDUs: 0, EDUs: 1)
2024-04-30 18:21:50,284 - synapse.util.caches.response_cache - 275 - INFO - PUT-5 - [fed_txn_handler]: using incomplete cached result for [('roguesrepast.cafe', '1714181631145')]
2024-04-30 18:21:50,284 - synapse.federation.transport.server.federation - 112 - INFO - PUT-6 - Received txn 1714181631145 from roguesrepast.cafe. (PDUs: 0, EDUs: 1)
2024-04-30 18:21:50,284 - synapse.util.caches.response_cache - 275 - INFO - PUT-6 - [fed_txn_handler]: using incomplete cached result for [('roguesrepast.cafe', '1714181631145')]
2024-04-30 18:21:50,330 - synapse.access.http.8008 - 472 - INFO - PUT-1 - 154.38.186.98 - 8008 - {roguesrepast.cafe} Processed request: 0.696sec/0.006sec (0.011sec, 0.003sec) (0.006sec/0.031sec/8) 11B 200 "PUT /_matrix/federation/v1/send/1714181631145 HTTP/1.1" "Synapse/1.105.1" [0 dbevts]
2024-04-30 18:21:50,331 - synapse.access.http.8008 - 472 - INFO - PUT-2 - 154.38.186.98 - 8008 - {roguesrepast.cafe} Processed request: 0.694sec/0.006sec (0.002sec, 0.000sec) (0.000sec/0.000sec/0) 11B 200 "PUT /_matrix/federation/v1/send/1714181631145 HTTP/1.1" "Synapse/1.105.1" [0 dbevts]
2024-04-30 18:21:50,332 - synapse.access.http.8008 - 472 - INFO - PUT-3 - 154.38.186.98 - 8008 - {roguesrepast.cafe} Processed request: 0.694sec/0.006sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 11B 200 "PUT /_matrix/federation/v1/send/1714181631145 HTTP/1.1" "Synapse/1.105.1" [0 dbevts]
2024-04-30 18:21:50,333 - synapse.access.http.8008 - 472 - INFO - PUT-4 - 154.38.186.98 - 8008 - {roguesrepast.cafe} Processed request: 0.604sec/0.006sec (0.001sec, 0.000sec) (0.000sec/0.000sec/0) 11B 200 "PUT /_matrix/federation/v1/send/1714181631145 HTTP/1.1" "Synapse/1.105.1" [0 dbevts]
2024-04-30 18:21:50,333 - synapse.access.http.8008 - 472 - INFO - PUT-5 - 154.38.186.98 - 8008 - {roguesrepast.cafe} Processed request: 0.599sec/0.006sec (0.001sec, 0.000sec) (0.000sec/0.000sec/0) 11B 200 "PUT /_matrix/federation/v1/send/1714181631145 HTTP/1.1" "Synapse/1.105.1" [0 dbevts]
2024-04-30 18:21:50,335 - synapse.access.http.8008 - 472 - INFO - PUT-6 - 154.38.186.98 - 8008 - {roguesrepast.cafe} Processed request: 0.297sec/0.007sec (0.001sec, 0.000sec) (0.000sec/0.000sec/0) 11B 200 "PUT /_matrix/federation/v1/send/1714181631145 HTTP/1.1" "Synapse/1.105.1" [0 dbevts]
2024-04-30 18:21:54,406 - synapse.crypto.keyring - 677 - INFO - PerspectivesKeyFetcher-2 - Requesting keys [_FetchKeyRequest(server_name='nope.chat', minimum_valid_until_ts=1714501314402, key_ids=['ed25519:a_UVsC'])] from notary server matrix.org
2024-04-30 18:21:54,408 - synapse.crypto.keyring - 677 - INFO - PerspectivesKeyFetcher-2 - Requesting keys [_FetchKeyRequest(server_name='nope.chat', minimum_valid_until_ts=1714501314402, key_ids=['ed25519:a_UVsC'])] from notary server cocamserverguild.com
2024-04-30 18:21:54,408 - synapse.crypto.keyring - 632 - WARNING - PerspectivesKeyFetcher-2 - Key lookup failed from 'cocamserverguild.com': Not retrying server cocamserverguild.com because we tried it recently retry_last_ts=1714500351439 and we won't check for another retry_interval=12990479ms.
2024-04-30 18:21:54,603 - synapse.http.matrixfederationclient - 362 - INFO - PerspectivesKeyFetcher-2 - {POST-O-6} [matrix.org] Completed request: 200 OK in 0.20 secs, got 438 bytes - POST matrix-federation://matrix.org/_matrix/key/v2/query
2024-04-30 18:21:54,628 - synapse.federation.transport.server.federation - 112 - INFO - PUT-7 - Received txn 1713964796668 from nope.chat. (PDUs: 0, EDUs: 1)
2024-04-30 18:21:54,666 - synapse.access.http.8008 - 472 - INFO - PUT-7 - 88.198.7.62 - 8008 - {nope.chat} Processed request: 0.263sec/0.001sec (0.009sec, 0.005sec) (0.004sec/0.024sec/8) 11B 200 "PUT /_matrix/federation/v1/send/1713964796668 HTTP/1.1" "Synapse/1.105.1" [0 dbevts]
2024-04-30 18:21:54,699 - synapse.federation.transport.server.federation - 112 - INFO - PUT-8 - Received txn 1713964799102 from nope.chat. (PDUs: 0, EDUs: 1)
2024-04-30 18:21:54,736 - synapse.access.http.8008 - 472 - INFO - PUT-8 - 88.198.7.62 - 8008 - {nope.chat} Processed request: 0.043sec/0.001sec (0.009sec, 0.003sec) (0.004sec/0.023sec/9) 11B 200 "PUT /_matrix/federation/v1/send/1713964799102 HTTP/1.1" "Synapse/1.105.1" [0 dbevts]
2024-04-30 18:21:55,714 - synapse.crypto.keyring - 677 - INFO - PerspectivesKeyFetcher-3 - Requesting keys [_FetchKeyRequest(server_name='josh.tel', minimum_valid_until_ts=1714501315708, key_ids=['ed25519:KUIETc'])] from notary server matrix.org
2024-04-30 18:21:55,717 - synapse.crypto.keyring - 677 - INFO - PerspectivesKeyFetcher-3 - Requesting keys [_FetchKeyRequest(server_name='josh.tel', minimum_valid_until_ts=1714501315708, key_ids=['ed25519:KUIETc'])] from notary server cocamserverguild.com
2024-04-30 18:21:55,717 - synapse.crypto.keyring - 632 - WARNING - PerspectivesKeyFetcher-3 - Key lookup failed from 'cocamserverguild.com': Not retrying server cocamserverguild.com because we tried it recently retry_last_ts=1714500351439 and we won't check for another retry_interval=12990479ms.
2024-04-30 18:21:55,890 - synapse.http.matrixfederationclient - 362 - INFO - PerspectivesKeyFetcher-3 - {POST-O-8} [matrix.org] Completed request: 200 OK in 0.18 secs, got 436 bytes - POST matrix-federation://matrix.org/_matrix/key/v2/query
2024-04-30 18:21:55,919 - synapse.federation.transport.server.federation - 112 - INFO - PUT-9 - Received txn 1714194892016 from josh.tel. (PDUs: 5, EDUs: 0)
2024-04-30 18:21:55,985 - synapse.federation.federation_server - 1241 - INFO - _process_incoming_pdus_in_room_inner-0 - handling received PDU in room !KlacjKWnARbprTLuRM:nova.chat: <FrozenEventV3 event_id=$i4Wz0YCL0cz_fyTXuASbXKX1i-b0Gssd0RNgyyRyTdA, type=m.room.member, state_key=@josh:josh.tel, outlier=False>
2024-04-30 18:21:56,001 - synapse.federation.federation_server - 1241 - INFO - _process_incoming_pdus_in_room_inner-1 - handling received PDU in room !ZVIOUxtbNRapDHyAQK:etke.cc: <FrozenEventV3 event_id=$nO4ZCosi8hTqP2I_r7YrhphtcMZLXoStbueUeDx04To, type=m.room.member, state_key=@josh:josh.tel, outlier=False>
2024-04-30 18:21:56,051 - synapse.access.http.8008 - 472 - INFO - PUT-9 - 143.110.144.192 - 8008 - {josh.tel} Processed request: 0.343sec/0.001sec (0.027sec, 0.004sec) (0.045sec/0.076sec/17) 260B 200 "PUT /_matrix/federation/v1/send/1714194892016 HTTP/1.1" "Synapse/1.105.1" [0 dbevts]
2024-04-30 18:21:56,074 - synapse.handlers.federation_event - 261 - INFO - _process_incoming_pdus_in_room_inner-0-$i4Wz0YCL0cz_fyTXuASbXKX1i-b0Gssd0RNgyyRyTdA - Ignoring PDU from josh.tel as we're not in the room
2024-04-30 18:21:56,075 - synapse.handlers.federation_event - 261 - INFO - _process_incoming_pdus_in_room_inner-1-$nO4ZCosi8hTqP2I_r7YrhphtcMZLXoStbueUeDx04To - Ignoring PDU from josh.tel as we're not in the room
2024-04-30 18:21:56,121 - synapse.federation.federation_server - 1241 - INFO - _process_incoming_pdus_in_room_inner-1 - handling received PDU in room !ZVIOUxtbNRapDHyAQK:etke.cc: <FrozenEventV3 event_id=$yLQvimPFbD3Yulb6MBrXO4xkdDOeAYLYpVw18xI044U, type=m.room.member, state_key=@josh:josh.tel, outlier=False>
2024-04-30 18:21:56,123 - synapse.federation.federation_server - 1241 - INFO - _process_incoming_pdus_in_room_inner-0 - handling received PDU in room !KlacjKWnARbprTLuRM:nova.chat: <FrozenEventV3 event_id=$H2kRjlsKLgUXbu1nYSV9yhWNbbx9ZGnSoVPPhf9F_d0, type=m.room.member, state_key=@josh:josh.tel, outlier=False>
2024-04-30 18:21:56,132 - synapse.handlers.federation_event - 261 - INFO - _process_incoming_pdus_in_room_inner-0-$H2kRjlsKLgUXbu1nYSV9yhWNbbx9ZGnSoVPPhf9F_d0 - Ignoring PDU from josh.tel as we're not in the room

Anything else that would be useful to know?

No response

@TheDidek
Copy link

TheDidek commented May 1, 2024

Did you update along with restore?
Maybe related to: #17129

@Cocam123
Copy link
Author

Cocam123 commented May 1, 2024

Nope. It was up to date before the restore
(I always try to keep it up to date. Security is one of my priority)

@Cocam123
Copy link
Author

Cocam123 commented May 1, 2024

But yea, if there is a way to fix it quickly, I won't say no. The ressources are so saturated, it's impossible to use it (the server is supposed to be online)

@Cocam123
Copy link
Author

Cocam123 commented May 1, 2024

I updated Synapse (now I'm in 1.106). The problem isn't fixed

@greentore
Copy link

@Cocam123 try rolling back to v1.104.0 or whatever version you were using before. For me database performance issues started with v1.105.0.

@Cocam123
Copy link
Author

Cocam123 commented May 1, 2024

how do I do that?

@Cocam123
Copy link
Author

Cocam123 commented May 1, 2024

I installed Synapse with apt install matrix-synapse-py3

@Cocam123
Copy link
Author

Cocam123 commented May 1, 2024

okay I found the package and seems like it doesn't work

@reivilibre
Copy link
Contributor

reivilibre commented May 8, 2024

Did you possibly restore the backup multiple times, e.g. partially restore it once, run into an error or interrupt it manually, then restore it again without clearing the database that you (partially) restored to the first time?

edit: I should provide the context, I say this because this is known to cause problems as it can lead to duplicate rows. matrix-org/synapse#11779 was a previous example though looks like that particular case got patched.

@reivilibre
Copy link
Contributor

Another suggestion is to ANALYZE your database in Postgres, in case it disrupted the statistics and is leading to poor query plans being generated. I am not sure if that's a realistic problem, but it came to mind.

@Cocam123
Copy link
Author

Cocam123 commented May 8, 2024

I completely reinstalled everything (after a reset). The server is working but it's extremely slow. The CPU is overloaded and it takes the storage (when I restart synapse, it frees up storage)

@reivilibre
Copy link
Contributor

If you definitely restored your database from fresh in one attempt then that clears the first point at least :)

Did you try to ANALYZE the tables in your database in the end? I still can't really see what else would have changed by doing a database restore, other than maybe coming online after some downtime is causing trouble.

I know it's a faff but using the Prometheus metrics + Grafana dashboard can help to have a little bit more idea of where the time is going.

As mentioned earlier, there is a suspected (or is it safe to say 'known'?) performance regression in this version (#17129), but if you were already running that version before then I don't see why that would be the problem.

@Cocam123
Copy link
Author

Cocam123 commented May 9, 2024

hey! okay I installed Prometheus and Synapse. What information might be of interest? I see federation but I do not know what to send (that could cause the problem except that)

@Cocam123
Copy link
Author

Cocam123 commented May 9, 2024

Okay so I decided to upload everything I have now. The server doesn't reply atm (at least, not correctly)

Capture d'écran 2024-05-09 211318
Capture d'écran 2024-05-09 211245
Capture d'écran 2024-05-09 211231
Capture d'écran 2024-05-09 211212
Capture d'écran 2024-05-09 211149
Capture d'écran 2024-05-09 211129

@Cocam123
Copy link
Author

Cocam123 commented May 9, 2024

I've also run a vacuum analysis on the entire database, but it doesn't give anything

@Cocam123
Copy link
Author

Cocam123 commented May 9, 2024

it found deadrows but despite the analysis and a vacuum full verbose it didn't improve the server's situation

@reivilibre
Copy link
Contributor

Thanks for your graphs!

I notice that 'Age of oldest event in staging area' is high (2+ days) and that you have ~500 events in the staging area and this number seems to not be decreasing.

This probably means that your server is struggling to persist the events.

Since the CPU usage doesn't look very high, I guess something is going slowly in the database? (Is Postgres the source of your high CPU use on your server?)

If you open up the 'Database' section in the Grafana dashboard, that probably has some interesting info, if you don't mind?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants
@reivilibre @Cocam123 @greentore @TheDidek and others