When a lot of locks are waiting for a single lock, notifying all locks
independently with `call_later` on each release is really costly and
incurs some kind of async contention, where the CPU is spinning a lot
for not much.
The included test is taking around 30s before the change, and 0.5s
after.
It was found following failing tests with
https://github.com/element-hq/synapse/pull/16827.
Background: we have a `matrixdotorg/synapse-workers` docker image, which
is intended for running multiple workers within the same container. That
image includes a `prefix-log` script which, for each line printed to
stdout or stderr by one of the processes, prepends the name of the
process.
This commit disables buffering in that script, so that lines are logged
quickly after they are printed. This makes it much easier to understand
the output, since they then come out in a natural order.
This PR aims to fix#16895, caused by a regression in #7 and not fixed
by #16903. The PR #16903 only fixes a starvation issue, where the CPU
isn't released. There is a second issue, where the execution is blocked.
This theory is supported by the flame graphs provided in #16895 and the
fact that I see the CPU usage reducing and far below the limit.
Since the changes in #7, the method `check_state_independent_auth_rules`
is called with the additional parameter `batched_auth_events`:
6fa13b4f92/synapse/handlers/federation_event.py (L1741-L1743)
It makes the execution enter this if clause, introduced with #151956fa13b4f92/synapse/event_auth.py (L178-L189)
There are two issues in the above code snippet.
First, there is the blocking issue. I'm not entirely sure if this is a
deadlock, starvation, or something different. In the beginning, I
thought the copy operation was responsible. It wasn't. Then I
investigated the nested `store.get_events` inside the function `update`.
This was also not causing the blocking issue. Only when I replaced the
set difference operation (`-` ) with a list comprehension, the blocking
was resolved. Creating and comparing sets with a very large amount of
events seems to be problematic.
This is how the flamegraph looks now while persisting outliers. As you
can see, the execution no longer locks up in the above function.
Second, the copying here doesn't serve any purpose, because only a
shallow copy is created. This means the same objects from the original
dict are referenced. This fails the intention of protecting these
objects from mutation. The review of the original PR
https://github.com/matrix-org/synapse/pull/15195 had an extensive
discussion about this matter.
Various approaches to copying the auth_events were attempted:
1) Implementing a deepcopy caused issues due to
builtins.EventInternalMetadata not being pickleable.
2) Creating a dict with new objects akin to a deepcopy.
3) Creating a dict with new objects containing only necessary
attributes.
Concluding, there is no easy way to create an actual copy of the
objects. Opting for a deepcopy can significantly strain memory and CPU
resources, making it an inefficient choice. I don't see why the copy is
necessary in the first place. Therefore I'm proposing to remove it
altogether.
After these changes, I was able to successfully join these rooms,
without the main worker locking up:
- #synapse:matrix.org
- #element-android:matrix.org
- #element-web:matrix.org
- #ecips:matrix.org
- #ipfs-chatter:ipfs.io
- #python:matrix.org
- #matrix:matrix.org
Since Synapse 1.76.0, any module which registers a `on_new_event`
callback would brick the ability to join remote rooms.
This is because this callback tried to get the full state of the room,
which would end up in a deadlock.
Related:
https://github.com/matrix-org/synapse-auto-accept-invite/issues/18
The following module would brick the ability to join remote rooms:
```python
from typing import Any, Dict, Literal, Union
import logging
from synapse.module_api import ModuleApi, EventBase
logger = logging.getLogger(__name__)
class MyModule:
def __init__(self, config: None, api: ModuleApi):
self._api = api
self._config = config
self._api.register_third_party_rules_callbacks(
on_new_event=self.on_new_event,
)
async def on_new_event(self, event: EventBase, _state_map: Any) -> None:
logger.info(f"Received new event: {event}")
@staticmethod
def parse_config(_config: Dict[str, Any]) -> None:
return None
```
This is technically a breaking change, as we are now passing partial
state on the `on_new_event` callback.
However, this callback was broken for federated rooms since 1.76.0, and
local rooms have full state anyway, so it's unlikely that it would
change anything.
