Synapse takes 5 minutes to startup

[samcday]

Description

My personal Synapse homeserver has started taking a very long time to startup. I switched on debug logging and discovered that it's issuing this SQL query that takes 5 minutes or so to execute:

2024-08-13 15:21:31,444 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {get_cache_dict} SELECT room_id, stream_ordering FROM events ORDER BY stream_ordering DESC LIMIT ?
2024-08-13 15:21:31,444 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {get_cache_dict} (100000,)
2024-08-13 15:25:29,451 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {get_cache_dict} 238.006934 sec

Steps to reproduce

Start Synapse
Wait 5 minutes
Scratch head
Open this issue

Homeserver

https://homeserver.samcday.com/

Synapse Version

v1.112.0 + v1.113.0

Installation Method

Docker (matrixdotorg/synapse)

Database

Single PostgreSQL, not ported from SQLite, have not restored DB from backup

Workers

Single process

Platform

Fedora CoreOS 40

Kubernetes 1.30

containerd 1.6.23

Kernel 6.8.11-300.fc40.x86_64

Configuration

https://github.com/samcday/home-cluster/blob/cb2ecba/cluster/synapse/config/homeserver.yaml

Relevant log output

Starting synapse with args -m synapse.app.homeserver --config-path /config/homeserver.yaml
2024-08-13 15:21:25,161 - root - 355 - WARNING - main - ***** STARTING SERVER *****
2024-08-13 15:21:25,161 - root - 356 - WARNING - main - Server /usr/local/lib/python3.11/site-packages/synapse/app/homeserver.py version 1.113.0
2024-08-13 15:21:25,161 - root - 361 - WARNING - main - Copyright (c) 2023 New Vector, Inc
2024-08-13 15:21:25,161 - root - 362 - WARNING - main - Licensed under the AGPL 3.0 license. Website: https://github.com/element-hq/synapse
2024-08-13 15:21:25,161 - root - 365 - INFO - main - Server hostname: samcday.com
2024-08-13 15:21:25,161 - root - 366 - INFO - main - Instance name: master
2024-08-13 15:21:25,161 - root - 367 - INFO - main - Twisted reactor: EPollReactor
2024-08-13 15:21:25,161 - synapse.app.homeserver - 356 - INFO - main - Setting up server
2024-08-13 15:21:25,162 - synapse.server - 351 - INFO - main - Setting up.
2024-08-13 15:21:25,179 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {startup} SET bytea_output TO escape
2024-08-13 15:21:25,179 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {startup} ()
2024-08-13 15:21:25,179 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {startup} 0.000352 sec
2024-08-13 15:21:25,179 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {startup} SET statement_timeout TO ?
2024-08-13 15:21:25,179 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {startup} (3600000,)
2024-08-13 15:21:25,180 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {startup} 0.000175 sec
2024-08-13 15:21:25,180 - synapse.storage.databases - 73 - INFO - main - [database config 'master']: Checking database server
2024-08-13 15:21:25,180 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {startup} SHOW SERVER_ENCODING
2024-08-13 15:21:25,180 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {startup} ()
2024-08-13 15:21:25,180 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {startup} 0.000340 sec
2024-08-13 15:21:25,181 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {startup} SELECT datcollate, datctype FROM pg_database WHERE datname = current_database()
2024-08-13 15:21:25,181 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {startup} ()
2024-08-13 15:21:25,304 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {startup} 0.123031 sec
2024-08-13 15:21:25,304 - synapse.storage.databases - 76 - INFO - main - [database config 'master']: Preparing for databases ['main', 'state']
2024-08-13 15:21:25,305 - synapse.storage.prepare_database - 135 - INFO - main - ['main', 'state']: Checking existing schema version
2024-08-13 15:21:25,306 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {prepare_database} COMMIT; BEGIN TRANSACTION; -- -- This file is licensed under the Affero General Public License (AGPL) version 3. -- -- Copyright (C) 2023 New Vector, Ltd -- -- This program is free software: you can redistribute it and/or modify -- it under the terms of the GNU Affero General Public License as -- published by the Free Software Foundation, either version 3 of the -- License, or (at your option) any later version. -- -- See the GNU Affero General Public License for more details: -- <https://www.gnu.org/licenses/agpl-3.0.html>. -- -- Originally licensed under the Apache License, Version 2.0: -- <http://www.apache.org/licenses/LICENSE-2.0>. -- -- [This file includes modifications made by New Vector Limited] -- -- /* Copyright 2015, 2016 OpenMarket Ltd * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at * *    http://www.apache.org/licenses/LICENSE-2.0 * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. * See the License for the specific language governing permissions and * limitations under the License. */ CREATE TABLE IF NOT EXISTS schema_version( Lock CHAR(1) NOT NULL DEFAULT 'X' UNIQUE,  -- Makes sure this table only has one row. version INTEGER NOT NULL, upgraded BOOL NOT NULL,  -- Whether we reached this version from an upgrade or an initial schema. CHECK (Lock='X') ); CREATE TABLE IF NOT EXISTS schema_compat_version( Lock CHAR(1) NOT NULL DEFAULT 'X' UNIQUE,  -- Makes sure this table only has one row. -- The SCHEMA_VERSION of the oldest synapse this database can be used with compat_version INTEGER NOT NULL, CHECK (Lock='X') ); CREATE TABLE IF NOT EXISTS applied_schema_deltas( version INTEGER NOT NULL, file TEXT NOT NULL, UNIQUE(version, file) ); -- a list of schema files we have loaded on behalf of dynamic modules CREATE TABLE IF NOT EXISTS applied_module_schemas( module_name TEXT NOT NULL, file TEXT NOT NULL, UNIQUE(module_name, file) );
2024-08-13 15:21:25,306 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {prepare_database} ()
2024-08-13 15:21:25,336 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {prepare_database} 0.029356 sec
2024-08-13 15:21:25,337 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {prepare_database} SELECT version, upgraded FROM schema_version
2024-08-13 15:21:25,337 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {prepare_database} ()
2024-08-13 15:21:25,344 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {prepare_database} 0.007535 sec
2024-08-13 15:21:25,345 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {prepare_database} SELECT compat_version FROM schema_compat_version
2024-08-13 15:21:25,345 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {prepare_database} ()
2024-08-13 15:21:25,576 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {prepare_database} 0.230658 sec
2024-08-13 15:21:25,576 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {prepare_database} SELECT file FROM applied_schema_deltas WHERE version >= ?
2024-08-13 15:21:25,576 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {prepare_database} (86,)
2024-08-13 15:21:25,609 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {prepare_database} 0.032173 sec
2024-08-13 15:21:25,609 - synapse.storage.prepare_database - 139 - INFO - main - ['main', 'state']: Existing schema is 86 (+1 deltas)
2024-08-13 15:21:25,609 - synapse.storage.databases.main - 391 - INFO - main - Checking database for consistency with configuration...
2024-08-13 15:21:25,609 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {prepare_database} SELECT name FROM users LIMIT 1
2024-08-13 15:21:25,610 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {prepare_database} ()
2024-08-13 15:21:25,647 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {prepare_database} 0.037430 sec
2024-08-13 15:21:25,648 - synapse.storage.prepare_database - 422 - DEBUG - main - applied_delta_files: ('86/01_authenticate_media.sql',)
2024-08-13 15:21:25,648 - synapse.storage.prepare_database - 433 - INFO - main - Applying schema deltas for v86
2024-08-13 15:21:25,648 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {prepare_database} DELETE FROM schema_version
2024-08-13 15:21:25,648 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {prepare_database} ()
2024-08-13 15:21:25,652 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {prepare_database} 0.002955 sec
2024-08-13 15:21:25,652 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {prepare_database} INSERT INTO schema_version (version, upgraded) VALUES (?,?)
2024-08-13 15:21:25,652 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {prepare_database} (86, True)
2024-08-13 15:21:25,661 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {prepare_database} 0.008463 sec
2024-08-13 15:21:25,661 - synapse.storage.prepare_database - 458 - DEBUG - main - Looking for schema deltas in /usr/local/lib/python3.11/site-packages/synapse/storage/schema/common/delta/86
2024-08-13 15:21:25,662 - synapse.storage.prepare_database - 458 - DEBUG - main - Looking for schema deltas in /usr/local/lib/python3.11/site-packages/synapse/storage/schema/main/delta/86
2024-08-13 15:21:25,662 - synapse.storage.prepare_database - 458 - DEBUG - main - Looking for schema deltas in /usr/local/lib/python3.11/site-packages/synapse/storage/schema/state/delta/86
2024-08-13 15:21:25,662 - synapse.storage.prepare_database - 497 - DEBUG - main - Found file: 86/01_authenticate_media.sql (/usr/local/lib/python3.11/site-packages/synapse/storage/schema/main/delta/86/01_authenticate_media.sql)
2024-08-13 15:21:25,662 - synapse.storage.prepare_database - 568 - INFO - main - Schema now up to date
2024-08-13 15:21:25,682 - synapse.storage.databases - 91 - INFO - main - [database config 'master']: Starting 'main' database
2024-08-13 15:21:25,696 - synapse.config.appservice - 96 - INFO - main - Loaded application service: ApplicationService: {'token': '<redacted>', 'url': 'http://bridge-heisenbridge:9898', 'hs_token': '<redacted>', 'sender': '@heisenbridge:samcday.com', 'namespaces': {'users': [Namespace(exclusive=True, regex=re.compile('@irc_.*'))], 'aliases': [], 'rooms': []}, 'id': 'heisenbridge', 'ip_range_whitelist': None, 'supports_ephemeral': False, 'msc3202_transaction_extensions': False, 'protocols': set(), 'rate_limited': False}
2024-08-13 15:21:25,704 - synapse.config.appservice - 96 - INFO - main - Loaded application service: ApplicationService: {'token': '<redacted>', 'url': 'http://bridge-meta:29319', 'hs_token': '<redacted>', 'sender': '@meta:samcday.com', 'namespaces': {'users': [Namespace(exclusive=True, regex=re.compile('@metabot:samcday\\.com')), Namespace(exclusive=True, regex=re.compile('@meta_.*:samcday\\.com'))], 'aliases': [], 'rooms': []}, 'id': 'meta', 'ip_range_whitelist': None, 'supports_ephemeral': False, 'msc3202_transaction_extensions': False, 'protocols': set(), 'rate_limited': False}
2024-08-13 15:21:25,712 - synapse.config.appservice - 96 - INFO - main - Loaded application service: ApplicationService: {'token': '<redacted>', 'url': 'http://bridge-signal:29328', 'hs_token': '<redacted>', 'sender': '@7a42e22038f94d43a4f3fb88d2c05b615499e6e4:samcday.com', 'namespaces': {'users': [Namespace(exclusive=True, regex=re.compile('@signal_.*:samcday\\.com')), Namespace(exclusive=True, regex=re.compile('@signalbot:samcday\\.com'))], 'aliases': [], 'rooms': []}, 'id': 'signal', 'ip_range_whitelist': None, 'supports_ephemeral': False, 'msc3202_transaction_extensions': False, 'protocols': set(), 'rate_limited': False}
2024-08-13 15:21:25,720 - synapse.config.appservice - 96 - INFO - main - Loaded application service: ApplicationService: {'token': '<redacted>', 'url': 'http://bridge-telegram:29317', 'hs_token': '<redacted>', 'sender': '@IrBHVlqoJsxPrMpFgkCEaaN8Q26rey8ZGGxv4KO_orzOny81eBcHsb8l7DdquPdP:samcday.com', 'namespaces': {'users': [Namespace(exclusive=True, regex=re.compile('@telegram_.*:samcday\\.com')), Namespace(exclusive=True, regex=re.compile('@telegrambot:samcday\\.com'))], 'aliases': [Namespace(exclusive=True, regex=re.compile('\\#telegram_.*:samcday\\.com'))], 'rooms': []}, 'id': 'telegram', 'ip_range_whitelist': None, 'supports_ephemeral': False, 'msc3202_transaction_extensions': False, 'protocols': set(), 'rate_limited': False}
2024-08-13 15:21:25,728 - synapse.config.appservice - 96 - INFO - main - Loaded application service: ApplicationService: {'token': '<redacted>', 'url': 'http://bridge-whatsapp:29318', 'hs_token': '<redacted>', 'sender': '@d3ca28056e0d1ebf3b219fed16c3262e1b98920d:samcday.com', 'namespaces': {'users': [Namespace(exclusive=True, regex=re.compile('^@whatsappbot2:samcday\\.com$')), Namespace(exclusive=True, regex=re.compile('^@whatsapp2_[0-9]+:samcday\\.com$'))], 'aliases': [], 'rooms': []}, 'id': 'whatsapp2', 'ip_range_whitelist': None, 'supports_ephemeral': False, 'msc3202_transaction_extensions': False, 'protocols': set(), 'rate_limited': False}
2024-08-13 15:21:25,731 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {sequence.check_consistency} SELECT GREATEST(MAX(txn_id), 0) FROM application_services_txns
2024-08-13 15:21:25,731 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {sequence.check_consistency} ()
2024-08-13 15:21:25,753 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {sequence.check_consistency} 0.021641 sec
2024-08-13 15:21:25,753 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {sequence.check_consistency} SELECT last_value, is_called FROM application_services_txn_id_seq
2024-08-13 15:21:25,753 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {sequence.check_consistency} ()
2024-08-13 15:21:25,754 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {sequence.check_consistency} 0.000814 sec
2024-08-13 15:21:25,755 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {sequence.check_consistency} SELECT GREATEST(MAX(stream_id), 0) FROM receipts_linearized
2024-08-13 15:21:25,755 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {sequence.check_consistency} ()
2024-08-13 15:21:26,333 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {sequence.check_consistency} 0.578336 sec
2024-08-13 15:21:26,334 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {sequence.check_consistency} SELECT last_value, is_called FROM receipts_sequence
2024-08-13 15:21:26,334 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {sequence.check_consistency} ()
2024-08-13 15:21:26,335 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {sequence.check_consistency} 0.000857 sec
2024-08-13 15:21:26,335 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {sequence.check_consistency} SELECT MAX(stream_id) FROM stream_positions WHERE stream_name = ?
2024-08-13 15:21:26,335 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {sequence.check_consistency} ('receipts',)
2024-08-13 15:21:26,337 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {sequence.check_consistency} 0.001557 sec
2024-08-13 15:21:26,337 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {_load_current_ids} DELETE FROM stream_positions WHERE stream_name = ? AND instance_name != ALL(?)
2024-08-13 15:21:26,338 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {_load_current_ids} ['receipts', ['master']]
2024-08-13 15:21:26,339 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {_load_current_ids} 0.001226 sec
2024-08-13 15:21:26,339 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {_load_current_ids} SELECT instance_name, stream_id FROM stream_positions WHERE stream_name = ?
2024-08-13 15:21:26,339 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {_load_current_ids} ('receipts',)
2024-08-13 15:21:26,340 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {_load_current_ids} 0.000576 sec
2024-08-13 15:21:26,340 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {_load_current_ids} SELECT last_value FROM receipts_sequence
2024-08-13 15:21:26,341 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {_load_current_ids} ()
2024-08-13 15:21:26,341 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {_load_current_ids} 0.000523 sec
2024-08-13 15:21:26,342 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {_load_current_ids} SELECT instance_name, stream_id FROM receipts_linearized WHERE ? <= stream_id
2024-08-13 15:21:26,342 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {_load_current_ids} (958799,)
2024-08-13 15:21:26,343 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {_load_current_ids} 0.001048 sec
2024-08-13 15:21:26,344 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {sequence.check_consistency} SELECT GREATEST(MAX(stream_id), 0) FROM cache_invalidation_stream_by_instance
2024-08-13 15:21:26,344 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {sequence.check_consistency} ()
2024-08-13 15:21:26,351 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {sequence.check_consistency} 0.005851 sec
2024-08-13 15:21:26,351 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {sequence.check_consistency} SELECT last_value, is_called FROM cache_invalidation_stream_seq
2024-08-13 15:21:26,351 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {sequence.check_consistency} ()
2024-08-13 15:21:26,354 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {sequence.check_consistency} 0.002813 sec
2024-08-13 15:21:26,354 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {sequence.check_consistency} SELECT MAX(stream_id) FROM stream_positions WHERE stream_name = ?
2024-08-13 15:21:26,355 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {sequence.check_consistency} ('caches',)
2024-08-13 15:21:26,356 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {sequence.check_consistency} 0.001025 sec
2024-08-13 15:21:26,356 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {_load_current_ids} SELECT GREATEST(COALESCE(MAX(stream_id), 1), 1) FROM cache_invalidation_stream_by_instance
2024-08-13 15:21:26,356 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {_load_current_ids} ()
2024-08-13 15:21:26,358 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {_load_current_ids} 0.001059 sec
2024-08-13 15:21:26,359 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {sequence.check_consistency} SELECT GREATEST(MAX(stream_ordering), 0) FROM events
2024-08-13 15:21:26,359 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {sequence.check_consistency} ()
2024-08-13 15:21:27,408 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {sequence.check_consistency} 1.049518 sec
2024-08-13 15:21:27,409 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {sequence.check_consistency} SELECT last_value, is_called FROM events_stream_seq
2024-08-13 15:21:27,409 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {sequence.check_consistency} ()
2024-08-13 15:21:27,411 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {sequence.check_consistency} 0.001363 sec
2024-08-13 15:21:27,411 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {sequence.check_consistency} SELECT MAX(stream_id) FROM stream_positions WHERE stream_name = ?
2024-08-13 15:21:27,412 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {sequence.check_consistency} ('events',)
2024-08-13 15:21:27,415 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {sequence.check_consistency} 0.002652 sec
2024-08-13 15:21:27,415 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {sequence.check_consistency} SELECT GREATEST(MAX(stream_id), 0) FROM current_state_delta_stream
2024-08-13 15:21:27,415 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {sequence.check_consistency} ()
2024-08-13 15:21:27,420 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {sequence.check_consistency} 0.004845 sec
2024-08-13 15:21:27,421 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {sequence.check_consistency} SELECT last_value, is_called FROM events_stream_seq
2024-08-13 15:21:27,421 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {sequence.check_consistency} ()
2024-08-13 15:21:27,422 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {sequence.check_consistency} 0.000777 sec
2024-08-13 15:21:27,423 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {sequence.check_consistency} SELECT MAX(stream_id) FROM stream_positions WHERE stream_name = ?
2024-08-13 15:21:27,423 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {sequence.check_consistency} ('events',)
2024-08-13 15:21:27,424 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {sequence.check_consistency} 0.000904 sec
2024-08-13 15:21:27,424 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {sequence.check_consistency} SELECT GREATEST(MAX(event_stream_ordering), 0) FROM ex_outlier_stream
2024-08-13 15:21:27,424 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {sequence.check_consistency} ()
2024-08-13 15:21:30,581 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {sequence.check_consistency} 3.156281 sec
2024-08-13 15:21:30,581 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {sequence.check_consistency} SELECT last_value, is_called FROM events_stream_seq
2024-08-13 15:21:30,581 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {sequence.check_consistency} ()
2024-08-13 15:21:30,582 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {sequence.check_consistency} 0.000738 sec
2024-08-13 15:21:30,583 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {sequence.check_consistency} SELECT MAX(stream_id) FROM stream_positions WHERE stream_name = ?
2024-08-13 15:21:30,583 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {sequence.check_consistency} ('events',)
2024-08-13 15:21:30,584 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {sequence.check_consistency} 0.001101 sec
2024-08-13 15:21:30,585 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {_load_current_ids} DELETE FROM stream_positions WHERE stream_name = ? AND instance_name != ALL(?)
2024-08-13 15:21:30,585 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {_load_current_ids} ['events', ['master']]
2024-08-13 15:21:30,586 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {_load_current_ids} 0.000878 sec
2024-08-13 15:21:30,586 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {_load_current_ids} SELECT instance_name, stream_id FROM stream_positions WHERE stream_name = ?
2024-08-13 15:21:30,586 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {_load_current_ids} ('events',)
2024-08-13 15:21:30,587 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {_load_current_ids} 0.000856 sec
2024-08-13 15:21:30,588 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {_load_current_ids} SELECT last_value FROM events_stream_seq
2024-08-13 15:21:30,588 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {_load_current_ids} ()
2024-08-13 15:21:30,589 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {_load_current_ids} 0.000892 sec
2024-08-13 15:21:30,590 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {_load_current_ids} SELECT instance_name, stream_ordering FROM events WHERE ? <= stream_ordering
2024-08-13 15:21:30,590 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {_load_current_ids} (322625,)
2024-08-13 15:21:30,591 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {_load_current_ids} 0.001004 sec
2024-08-13 15:21:30,591 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {_load_current_ids} SELECT instance_name, stream_id FROM current_state_delta_stream WHERE ? <= stream_id
2024-08-13 15:21:30,592 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {_load_current_ids} (322625,)
2024-08-13 15:21:30,593 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {_load_current_ids} 0.000883 sec
2024-08-13 15:21:30,593 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {_load_current_ids} SELECT instance_name, event_stream_ordering FROM ex_outlier_stream WHERE ? <= event_stream_ordering
2024-08-13 15:21:30,594 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {_load_current_ids} (322625,)
2024-08-13 15:21:30,595 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {_load_current_ids} 0.000954 sec
2024-08-13 15:21:30,596 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {sequence.check_consistency} SELECT GREATEST(-MIN(stream_ordering), 0) FROM events
2024-08-13 15:21:30,596 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {sequence.check_consistency} ()
2024-08-13 15:21:30,978 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {sequence.check_consistency} 0.381896 sec
2024-08-13 15:21:30,978 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {sequence.check_consistency} SELECT last_value, is_called FROM events_backfill_stream_seq
2024-08-13 15:21:30,979 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {sequence.check_consistency} ()
2024-08-13 15:21:30,981 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {sequence.check_consistency} 0.002465 sec
2024-08-13 15:21:30,982 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {sequence.check_consistency} SELECT MAX(stream_id) FROM stream_positions WHERE stream_name = ?
2024-08-13 15:21:30,982 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {sequence.check_consistency} ('backfill',)
2024-08-13 15:21:30,983 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {sequence.check_consistency} 0.001273 sec
2024-08-13 15:21:30,984 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {sequence.check_consistency} SELECT GREATEST(-MIN(event_stream_ordering), 0) FROM ex_outlier_stream
2024-08-13 15:21:30,984 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {sequence.check_consistency} ()
2024-08-13 15:21:30,985 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {sequence.check_consistency} 0.001146 sec
2024-08-13 15:21:30,986 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {sequence.check_consistency} SELECT last_value, is_called FROM events_backfill_stream_seq
2024-08-13 15:21:30,986 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {sequence.check_consistency} ()
2024-08-13 15:21:30,987 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {sequence.check_consistency} 0.000755 sec
2024-08-13 15:21:30,987 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {sequence.check_consistency} SELECT MAX(stream_id) FROM stream_positions WHERE stream_name = ?
2024-08-13 15:21:30,988 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {sequence.check_consistency} ('backfill',)
2024-08-13 15:21:30,989 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {sequence.check_consistency} 0.001121 sec
2024-08-13 15:21:30,989 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {_load_current_ids} DELETE FROM stream_positions WHERE stream_name = ? AND instance_name != ALL(?)
2024-08-13 15:21:30,990 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {_load_current_ids} ['backfill', ['master']]
2024-08-13 15:21:30,991 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {_load_current_ids} 0.001081 sec
2024-08-13 15:21:30,991 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {_load_current_ids} SELECT instance_name, stream_id FROM stream_positions WHERE stream_name = ?
2024-08-13 15:21:30,992 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {_load_current_ids} ('backfill',)
2024-08-13 15:21:30,993 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {_load_current_ids} 0.000809 sec
2024-08-13 15:21:30,993 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {_load_current_ids} SELECT last_value FROM events_backfill_stream_seq
2024-08-13 15:21:30,993 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {_load_current_ids} ()
2024-08-13 15:21:30,994 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {_load_current_ids} 0.000644 sec
2024-08-13 15:21:30,994 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {_load_current_ids} SELECT instance_name, stream_ordering FROM events WHERE ? >= stream_ordering
2024-08-13 15:21:30,995 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {_load_current_ids} (-479500,)
2024-08-13 15:21:30,996 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {_load_current_ids} 0.001082 sec
2024-08-13 15:21:30,996 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {_load_current_ids} SELECT instance_name, event_stream_ordering FROM ex_outlier_stream WHERE ? >= event_stream_ordering
2024-08-13 15:21:30,996 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {_load_current_ids} (-479500,)
2024-08-13 15:21:30,998 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {_load_current_ids} 0.000875 sec
2024-08-13 15:21:30,998 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {get_cache_dict} SELECT room_id, stream_id FROM current_state_delta_stream ORDER BY stream_id DESC LIMIT ?
2024-08-13 15:21:30,998 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {get_cache_dict} (1000,)
2024-08-13 15:21:31,089 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {get_cache_dict} 0.090048 sec
2024-08-13 15:21:31,094 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {sequence.check_consistency} SELECT GREATEST(MAX(chain_id), 0) FROM event_auth_chains
2024-08-13 15:21:31,094 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {sequence.check_consistency} ()
2024-08-13 15:21:31,311 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {sequence.check_consistency} 0.217210 sec
2024-08-13 15:21:31,312 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {sequence.check_consistency} SELECT last_value, is_called FROM event_auth_chain_id
2024-08-13 15:21:31,312 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {sequence.check_consistency} ()
2024-08-13 15:21:31,313 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {sequence.check_consistency} 0.001050 sec
2024-08-13 15:21:31,314 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {sequence.check_consistency} SELECT GREATEST(MAX(stream_id), 0) FROM un_partial_stated_event_stream
2024-08-13 15:21:31,314 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {sequence.check_consistency} ()
2024-08-13 15:21:31,319 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {sequence.check_consistency} 0.005296 sec
2024-08-13 15:21:31,320 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {sequence.check_consistency} SELECT last_value, is_called FROM un_partial_stated_event_stream_sequence
2024-08-13 15:21:31,320 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {sequence.check_consistency} ()
2024-08-13 15:21:31,322 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {sequence.check_consistency} 0.002292 sec
2024-08-13 15:21:31,323 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {sequence.check_consistency} SELECT MAX(stream_id) FROM stream_positions WHERE stream_name = ?
2024-08-13 15:21:31,323 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {sequence.check_consistency} ('un_partial_stated_event_stream',)
2024-08-13 15:21:31,324 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {sequence.check_consistency} 0.001225 sec
2024-08-13 15:21:31,325 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {_load_current_ids} DELETE FROM stream_positions WHERE stream_name = ? AND instance_name != ALL(?)
2024-08-13 15:21:31,325 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {_load_current_ids} ['un_partial_stated_event_stream', ['master']]
2024-08-13 15:21:31,326 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {_load_current_ids} 0.001050 sec
2024-08-13 15:21:31,327 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {_load_current_ids} SELECT instance_name, stream_id FROM stream_positions WHERE stream_name = ?
2024-08-13 15:21:31,327 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {_load_current_ids} ('un_partial_stated_event_stream',)
2024-08-13 15:21:31,328 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {_load_current_ids} 0.000813 sec
2024-08-13 15:21:31,328 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {_load_current_ids} SELECT last_value FROM un_partial_stated_event_stream_sequence
2024-08-13 15:21:31,328 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {_load_current_ids} ()
2024-08-13 15:21:31,329 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {_load_current_ids} 0.000611 sec
2024-08-13 15:21:31,329 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {_load_current_ids} SELECT instance_name, stream_id FROM un_partial_stated_event_stream WHERE ? <= stream_id
2024-08-13 15:21:31,330 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {_load_current_ids} (261,)
2024-08-13 15:21:31,332 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {_load_current_ids} 0.002302 sec
2024-08-13 15:21:31,334 - synapse.storage.txn - 758 - DEBUG - main - [TXN START] {initialise_mau_threepids-0}
2024-08-13 15:21:31,335 - synapse.storage.txn - 862 - DEBUG - main - [TXN END] {initialise_mau_threepids-0} 0.000959 sec
2024-08-13 15:21:31,336 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {sequence.check_consistency} SELECT GREATEST(MAX(stream_id), 0) FROM device_inbox
2024-08-13 15:21:31,336 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {sequence.check_consistency} ()
2024-08-13 15:21:31,350 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {sequence.check_consistency} 0.014381 sec
2024-08-13 15:21:31,351 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {sequence.check_consistency} SELECT last_value, is_called FROM device_inbox_sequence
2024-08-13 15:21:31,351 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {sequence.check_consistency} ()
2024-08-13 15:21:31,356 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {sequence.check_consistency} 0.005133 sec
2024-08-13 15:21:31,357 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {sequence.check_consistency} SELECT MAX(stream_id) FROM stream_positions WHERE stream_name = ?
2024-08-13 15:21:31,357 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {sequence.check_consistency} ('to_device',)
2024-08-13 15:21:31,359 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {sequence.check_consistency} 0.001321 sec
2024-08-13 15:21:31,359 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {sequence.check_consistency} SELECT GREATEST(MAX(stream_id), 0) FROM device_federation_outbox
2024-08-13 15:21:31,360 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {sequence.check_consistency} ()
2024-08-13 15:21:31,402 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {sequence.check_consistency} 0.042053 sec
2024-08-13 15:21:31,402 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {sequence.check_consistency} SELECT last_value, is_called FROM device_inbox_sequence
2024-08-13 15:21:31,403 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {sequence.check_consistency} ()
2024-08-13 15:21:31,403 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {sequence.check_consistency} 0.000724 sec
2024-08-13 15:21:31,404 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {sequence.check_consistency} SELECT MAX(stream_id) FROM stream_positions WHERE stream_name = ?
2024-08-13 15:21:31,404 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {sequence.check_consistency} ('to_device',)
2024-08-13 15:21:31,405 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {sequence.check_consistency} 0.001092 sec
2024-08-13 15:21:31,406 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {_load_current_ids} DELETE FROM stream_positions WHERE stream_name = ? AND instance_name != ALL(?)
2024-08-13 15:21:31,406 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {_load_current_ids} ['to_device', ['master']]
2024-08-13 15:21:31,407 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {_load_current_ids} 0.001283 sec
2024-08-13 15:21:31,408 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {_load_current_ids} SELECT instance_name, stream_id FROM stream_positions WHERE stream_name = ?
2024-08-13 15:21:31,408 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {_load_current_ids} ('to_device',)
2024-08-13 15:21:31,410 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {_load_current_ids} 0.001287 sec
2024-08-13 15:21:31,410 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {_load_current_ids} SELECT last_value FROM device_inbox_sequence
2024-08-13 15:21:31,410 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {_load_current_ids} ()
2024-08-13 15:21:31,412 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {_load_current_ids} 0.000778 sec
2024-08-13 15:21:31,412 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {_load_current_ids} SELECT instance_name, stream_id FROM device_inbox WHERE ? <= stream_id
2024-08-13 15:21:31,412 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {_load_current_ids} (1774,)
2024-08-13 15:21:31,414 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {_load_current_ids} 0.001312 sec
2024-08-13 15:21:31,414 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {_load_current_ids} SELECT instance_name, stream_id FROM device_federation_outbox WHERE ? <= stream_id
2024-08-13 15:21:31,414 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {_load_current_ids} (1774,)
2024-08-13 15:21:31,416 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {_load_current_ids} 0.000919 sec
2024-08-13 15:21:31,416 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {get_cache_dict} SELECT user_id, stream_id FROM device_inbox ORDER BY stream_id DESC LIMIT ?
2024-08-13 15:21:31,417 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {get_cache_dict} (1000,)
2024-08-13 15:21:31,438 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {get_cache_dict} 0.020755 sec
2024-08-13 15:21:31,441 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {get_cache_dict} SELECT destination, stream_id FROM device_federation_outbox ORDER BY stream_id DESC LIMIT ?
2024-08-13 15:21:31,441 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {get_cache_dict} (1000,)
2024-08-13 15:21:31,442 - synapse.storage.SQL - 492 - DEBUG - main - [SQL time] {get_cache_dict} 0.000970 sec
2024-08-13 15:21:31,444 - synapse.storage.SQL - 466 - DEBUG - main - [SQL] {get_cache_dict} SELECT room_id, stream_ordering FROM events ORDER BY stream_ordering DESC LIMIT ?
2024-08-13 15:21:31,444 - synapse.storage.SQL - 471 - DEBUG - main - [SQL values] {get_cache_dict} (100000,)

Anything else that would be useful to know?

No response

[amandahla]

Hey, I'm not one of the maintainers but I'm leaving a comment here because I'm facing some similar issues and would like to know if you tested it after setting keepalives_* configuration in the Postgresql datasource.
https://element-hq.github.io/synapse/latest/postgres.html#synapse-config

[samcday]

Hey, I'm not one of the maintainers but I'm leaving a comment here because I'm facing some similar issues and would like to know if you tested it after setting keepalives_* configuration in the Postgresql datasource. https://element-hq.github.io/synapse/latest/postgres.html#synapse-config

Hiya! I'm not tuning the connection keepalive settings at all: https://github.com/samcday/home-cluster/blob/cb2ecba/cluster/synapse/config/homeserver.yaml#L7-L13

FWIW, I think it's the query itself that is to blame, not the connection that carries that query. I tried to run it directly in psql and observed that it was running for at least 30+ seconds before I ctrl-c'd it.

[erikjohnston]

I would be interested to know what EXPLAIN SELECT room_id, stream_ordering FROM events ORDER BY stream_ordering DESC LIMIT 100000 says, and then how long EXPLAIN ANAYLZE ... takes. It really shouldn't take 5 minutes to load 100k rows from the DB

[samcday]

Hm, yeah... right you are! I think maybe I was having deeper I/O issues with my DB, because that query is not taking an extremely long time any more:

synapse=# EXPLAIN SELECT room_id, stream_ordering FROM events ORDER BY stream_ordering DESC LIMIT 100000;
                                                  QUERY PLAN                                                  
--------------------------------------------------------------------------------------------------------------
 Limit  (cost=0.42..27008.97 rows=100000 width=40)
   ->  Index Scan Backward using events_stream_ordering on events  (cost=0.42..97079.67 rows=359439 width=40)
(2 rows)

synapse=# EXPLAIN ANALYZE SELECT room_id, stream_ordering FROM events ORDER BY stream_ordering DESC LIMIT 100000 ;
                                                                          QUERY PLAN                                                                           
---------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=0.42..27008.97 rows=100000 width=40) (actual time=0.065..643.568 rows=100000 loops=1)
   ->  Index Scan Backward using events_stream_ordering on events  (cost=0.42..97079.67 rows=359439 width=40) (actual time=0.063..633.336 rows=100000 loops=1)
 Planning Time: 0.121 ms
 Execution Time: 649.150 ms
(4 rows)

I don't know if it's related (seems doubtful), but I did also purge out some big(-ish) rooms via the v2 room delete API yesterday, after I raised this issue. Anyway, my Postgres cluster is running on top of Ceph block storage, and I think there might have been some wobbliness there causing the weird I/O issues... That seems like a more likely culprit.

I'll close this out now since it's an environmental issue and seems nothing to do with Synapse itself. Thanks ya'll!

[erikjohnston]

Thanks for following up! Sounds likely it was an environmental issue then. We do know that starting synapse can be pretty intensive for the DB, though generally we're talking about seconds for startup time rather than minutes.