element-hq / element-hq/synapse

Performance regression since 1.147.0: Tight loop in `_get_new_state_after_events` causes ~5× CPU increase via race condition during event de-outliering

Open
#19,472 1 comment 3 reactions 0 assignees View on GitHub
Dominant language
Python
Stars
4.6k
Forks
600
Avg merge
5d 22h
Merged PRs (30d)
51

Description

## Summary

Since upgrading from **1.146.x** to **1.147.0**, CPU usage has risen from **~5%** to **~25%** on a 4-core server. The root cause is a race condition in `_get_new_state_after_events` that triggers a tight event-persistence retry loop affecting any large federated room that receives events with missing `prev_events`.

---

## Symptoms

- **CPU load:** 5% → 25% (4 cores) after upgrade to 1.147.0
- **PostgreSQL** `pg_stat_user_tables` shows `state_groups_persisting` being seq-scanned **12.6 times/second** with **0 live rows** — a clear tight-loop signature
- **418 tracebacks** in `homeserver.log` since last stats reset (4 days)
- `federation_transaction_transmission_loop` counter reaches **378,000+ iterations**
- Constant `_process_new_pulled_events_with_failed_pull_attempts` background process exceptions

---

## Stack Trace

```
File "synapse/storage/controllers/persist_events.py", line 435, in persist_events
File "...", line 430, in enqueue
File "...", line 251, in add_to_queue
File "...", line 294, in handle_queue_loop
File "...", line 376, in _process_event_persist_queue_task
File "...", line 637, in _persist_event_batch
File "...", line 746, in _calculate_new_forward_extremities_and_state_delta
File "...", line 940, in _get_new_state_after_events
event_id_to_state_group[evid] for evid in old_latest_event_ids

KeyError: '$CUUA3u0Bi52j-5EV74WCyBD2vgFOmei9K79XgZbiHGU'

The above exception was the direct cause of the following exception:
Exception: Error fetching missing prev_events for $zHaFKG9...
```

---

## Root Cause Analysis

In `_get_new_state_after_events` (`persist_events.py`):

```python
missing_event_ids = set(old_latest_event_ids) # ← all old extremities go here
# ... fetch new extremities from context or DB ...
if missing_event_ids:
event_to_groups = await self.main_store._get_state_group_for_events(
missing_event_ids
)
event_id_to_state_group.update(event_to_groups)

old_state_groups = {
event_id_to_state_group[evid] # ← KeyError if evid missing!
for evid in old_latest_event_ids
}
```

### Race Condition Step-by-Step

1. Event X arrives via federation with missing `prev_events`
2. Synapse fetches and stores the missing events as **outliers**
3. During de-outliering, event Y becomes a new **forward extremity**
4. A concurrent persistence attempt queries `event_to_state_groups` for event Y
5. The `INSERT INTO event_to_state_groups` for event Y has **not committed yet** (it is being written as part of the de-outlier transaction)
6. `_get_state_group_for_events` returns an incomplete mapping (in 1.147.0) or raises `RuntimeError` (in 1.147.1 after the hardening fix)
7. Either way, **persistence fails** for the room
8. The failed event is re-queued in `failed_pull_attempts`
9. `_process_new_pulled_events_with_failed_pull_attempts` retries → same failure
10. **→ Tight retry loop** that continuously scans `state_groups_persisting`

> **Note:** The affected event `$CUUA3u0Bi52j...` is *not* an outlier in the DB (`outlier=false`, `state_group=1182141`), confirming the state group was eventually written — but too late for the concurrent persistence attempt.

---

## Database Evidence

`state_groups_persisting`: **4.3M seq_scans** in 4 days on a table with **0 live rows** = 12.62 scans/second → tight polling loop.

```sql
SELECT relname, seq_scan, n_live_tup,
round(seq_scan::numeric / 345600, 2) AS scans_per_sec
FROM pg_stat_user_tables
WHERE relname = 'state_groups_persisting';

-- state_groups_persisting | 4361559 | 0 | 12.62
```

---

## Suggested Fix

### Option A – Guard against missing state groups

```python
event_to_groups = await self.main_store._get_state_group_for_events(
missing_event_ids, allow_missing=True # new parameter
)
event_id_to_state_group.update(event_to_groups)

# Only include old extremities that have a known state group
old_state_groups = {
event_id_to_state_group[evid]
for evid in old_latest_event_ids
if evid in event_id_to_state_group # ← guard
}
```

### Option B – Ensure commit ordering

Ensure that a de-outliered event's `event_to_state_groups` row is committed (via `RETURNING` or a separate read-after-write) **before** the event is added to the room's forward extremities.

---

## Workaround

**None confirmed.** Restarting Synapse provides temporary relief if the retry queue empties, but the problem recurs on the next batch of federation events with missing `prev_events` in the affected room.

---

## Related Issues

- [[#9260](https://github.com/element-hq/synapse/issues/9260)](https://github.com/element-hq/synapse/issues/9260) – *"Unable to leave a certain room (KeyError)"*

### Steps to reproduce

1. Run Synapse 1.147.0 or 1.147.1 as a single-process homeserver
2. Join a large federated room with many servers and members
3. Wait for federation events with missing `prev_events` to arrive
4. Observe `KeyError` tracebacks in `homeserver.log` and rising CPU usage

### Homeserver

matrix.yourdevice.ch

### Synapse Version

1.147.1

### Installation Method

Debian packages from packages.matrix.org

### Database

Single PostgreSQL 14 on the same host, never migrated

### Workers

Single process

### Platform

Ubuntu 24.04 Server

### Configuration

_No response_

### Relevant log output

```shell
File "synapse/storage/controllers/persist_events.py", line 940, in _get_new_state_after_events
event_id_to_state_group[evid] for evid in old_latest_event_ids
KeyError: '$CUUA3u0Bi52j-5EV74WCyBD2vgFOmei9K79XgZbiHGU'
```

### Anything else that would be useful to know?

_No response_

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.