perf: Improve gapfill logic #1818
No reviewers
Labels
No labels
Abandoned
Blocked
Bug
Changelog
Added
Changelog
Missing
Changelog
None
Cherry-picking
Database
Dependencies
Dependencies/Renovate
Difficulty
Easy
Difficulty
Hard
Difficulty
Medium
Documentation
Enhancement
Good first issue
Help wanted
Inherited
Matrix/Administration
Matrix/Appservices
Matrix/Auth
Matrix/Client
Matrix/Core
Matrix/E2EE
Matrix/Federation
Matrix/Hydra
Matrix/MSC
Matrix/Media
Matrix/T&S
Merge
Merge/Manual
Merge/Squash
Meta
Meta/CI
Meta/Packaging
Priority
Blocking
Priority
High
Priority
Low
Security
Status
Confirmed
Status
Duplicate
Status
Invalid
Status
Needs Investigation
Support
No project
No assignees
4 participants
Notifications
Due date
No due date set.
Dependencies
No dependencies set.
Reference
continuwuation/continuwuity!1818
Loading…
Add table
Add a link
Reference in a new issue
No description provided.
Delete branch "nex/perf/get-missing-events"
Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?
Right now our gapfilling code is pretty awful for performance: for each event we are missing, we make an individual
GET /_matrix/federation/v1/event/$eventIDcall, which is incredibly slow. This also happens for fetching auth events we are missing. Luckily, Matrix defines two bulk-fetch endpoints that help us. So, this PR updates our gapfilling code to be more reliable and effective.This pull request also tries to address #1844 by sending dummy events when the number of forward extremities exceeds a certain threshold (default 10), which should help reduce the number of prev events being referenced in future events (and also passively heals the room).
Pull request checklist:
mainbranch, and the branch is named something other thanmain.myself, if applicable. This includes ensuring code compiles.
a1eeef95e0d15064871ec8e1c657aeb7e0d96b91b7e0d96b91c8e1c657aeSo this PR yields unparalleled speed and consistency improvements over the base branch, even in this unoptimised state, however it highlights a problem. Filling gaps can take an extraordinarily long time, especially if servers pushing events to us are unreachable (e.g. ipv6 only server pushes to a server without ipv6 egress), or the room graph is really complex and actively moving (e.g. the ping room). As a result, the median PDU handle time with this PR can easily go from ~4ms to >500ms, with a few minutes being the worst-case observed thus far, since we now try significantly more aggressively to pull in events that we missed. The best-case remains unchanged, and generally speaking consistency is improved too, but in the future, processing missing events and upgrading outlier PDUs to timeline PDUs will probably need to be cast into a background task, as right now the entire room becomes locked while prev events are being fetched, which as stated, can take minutes. Not sure if that'll get squeezed into this PR's scope or whether it'll end up being a separate job.
c8e1c657aef19daa2365Background management is looking to be massively out of scope for this pull request, so I think it's ready for review. Had this deployed to both
unstable.timedout.uk:8448andexplodie.org(thanks Aranje) for some time now and it looks like all of the quirks, bar the aforementioned overzealous mutex lock, have been ironed out. It looks like tuwunel stole our thunder on this one, so I'll go cross-reference with their implementation to see if there's any ideas I can lift, but otherwise this just needs a touch up, and a round of optimisation, and then it's good to go.Preliminary review greatly appreciated.
cafb269a6a26a4fd5f0fWIP: perf: Improve gapfill logicto perf: Improve gapfill logic@ -102,0 +160,4 @@// that many events per-request. Synapse returns 20, and conduwuit+ return 50.// This means with a hard iteration limit, we might give up too early, before// we get a chance to even come close to max_fetch_prev_events. As such, we'll// calculate the max limit based on that config option based on these averages.this comment seems to be mangled
@ -209,0 +350,4 @@Ok(discovered)}async fn fetch_and_handle_missing_event_via(NO DOCSTRING?
@ -110,0 +88,4 @@for (i, event_id) in to_persist.iter().enumerate() {debug!(elapsed=?start.elapsed(),"[TODO] Persisting fetched prev event: {event_id} ({}/{})","TODO"?
ugh knew I missed one of these
@ -55,0 +28,4 @@/// them directly.////// The end result is a result containing a map of shortstatekeys to event/// IDs. The underlying `Option` is always `Some`.why return an option then 🗿
because that's the type the caller wants 🗿
change the caller then 🗿
unlike someone I want my diff to be a reviewable size 🗿
Context:
debug!(event_id = %incoming_pdu.event_id,"Resolving state at event");let mut state_at_incoming_event = if incoming_pdu.prev_events().count() == 1 {self.state_at_incoming_degree_one(&incoming_pdu).await?} else {self.state_at_incoming_resolved(&incoming_pdu, room_id, &room_version_rules).await?};if state_at_incoming_event.is_none() {state_at_incoming_event = self.fetch_state(origin, create_event, room_id, incoming_pdu.event_id()).await?;}let state_at_incoming_event =state_at_incoming_event.expect("we always set this to some above");change line 84 to
Some(self.fetch_state(...))🗿also that logic is sketchy in general, it could be a single chain of ifs instead of an if -> assignment -> expect() call
womp womp I'll have a play about
@ -86,0 +282,4 @@/// state events as outliers, for use later.////// Any events that cannot be persisted are dropped with a warning./// TODO: make it noisy?another TODO
@ -149,0 +164,4 @@)));}}// TODO: do events received from auth chain need persisting? that soundsanother TODO
@ -395,0 +397,4 @@// sometimes end up sending PDUs to us that we aren't yet ready to accept, and// consequently drop. Holding the mutex over the room while processing mitigates// this.let _room_lock = selfdoes this lock need to be held until the end of the function?
It needs to be held until we've set the state and forward extremities, which is at the end of the function, so yeah. it could probably be dropped before extremity setting but it's practically the end of the function anyway
4e2f36f7f1f2aca3e5b1@ -16,3 +27,2 @@/// Find the event and auth it. Once the event is validated (steps 1 - 8)/// it is appended to the outliers Tree.const GET_MISSING_EVENTS_MAX_BATCH_SIZE: u16 = 50; // matches src/server/get_missing_events.rs#LIMIT_MAXwhy not use the same constant, then?
@ -71,0 +78,4 @@.copied().unwrap_or_else(|| int!(0)).to_string().parse::<u64>()🤨 what's this string roundtrip for
without looking at the source this is commenting on,
ruma::UIntdoesn't implementFrom<ruma::Int>, or some other equally absurdFrom/Intotrait isn't satisfied that allows converting from Int to UInt. WhyMilliSecondsSinceUnixEpochis even aUIntunder the hood is beyond me, because unix timestamps can be negative. But whatever.I'd suggest converting the
Intinto au64and callingnew_saturating@ -293,0 +248,4 @@debug!("Fetching and persisting any missing prev events");self.fetch_prevs(room_id, create_event, &incoming_pdu, origin).await.debug_inspect_err(|e| {why's this
debug_inspect_errand notinspect_err?Because it's usually a transient failure (we were unable to ask the origin for missing events) and the fetch will be re-tried by a later PDU handle. That information usually isn't important to operation and there's not much that can be done about it as a user, but it may serve to be useful in a debug scenario.
TL;DR the log isn't useful for non-debugging ops
@ -298,0 +278,4 @@.await;let mut local_users = self.services.state_cache.local_users_in_room(room_id);while let Some(user_id) = local_users.next().await {if power_levels.for_user(&user_id)this could be a call to
user_can_send_message@ -298,0 +298,4 @@&state_lock,).await.inspect(|_| debug!(sender=%user_id, "Successfully sent a dummy event"))nit: this log line could go above the
breakI don't really see a reason to
@ -23,3 +25,3 @@room_id: &'a RoomId,mut value: CanonicalJsonObject,auth_events_known: bool,_auth_events_known: bool,why's there an unused parameter here?
it used to be used, I never checked how many callsites I'd need to refactor to remove it entirely
removed
@ -133,0 +151,4 @@.map_err(|e| err!(Request(BadJson("Invalid PDU {auth_event_id}: {e}"))))?;auth_chain_map.insert(auth_event_id, auth_pdu);}for aid in pdu_event.auth_events() {nit: we aren't rationing letters, this would be more clear as
auth_event_id@ -298,0 +264,4 @@.count().await;if extremities_count >= self.services.server.config.dummy_event_threshold.into() {Should probably throttle such that it only sends after a minute, at most once a minute, as long as there are still extremities
@ -236,3 +231,3 @@}// Skip old events// Skip events sent before we joined (they need to be persisted as backfilledI get the feeling that this would be the correct place to use depth if it was actually trustable, as if it is less than the join, the event will always have happened before or at "the same time as the join". IIRC there isn't a way to make depth go down. Although given this is existing code, might be OK to leave it for now
Yeah, I did initially remove it, but it caused problems where we would then start upgrading events that were backfilled. I never bothered investigating why we even tried to do that, but it seemed like a load-bearing awful check, so I've retained it for now. Probably worth looking into it in the future though. As you mentioned, depth can't be trusted, and comparing the DAG position lexicographically is incredibly expensive
!admin debug rooms-by-extremity-countcommand 6a5c3eb766GET_MISSING_EVENTS_MAX_BATCH_SIZE58dc9738bfuser_can_send_message248a990362With that fallback for the forked depth case, I think this should be good. Testing on my instance now, anyway.
5337293d057ca00e4ab9@ -298,0 +280,4 @@let squash_timings = self.last_extremity_squash.read();squash_timings.get(room_id).copied()};if last_squash.is_some_and(|s| s.elapsed() < Duration::from_mins(1)) {Here you're throttling, I'd kind of prefer to debounce avoid situations where a later event deals with extremities itself. I'd also like to skip if the previous even is itself a dummy event, to fully prevent loops rather than just throttling them.
@ -56,6 +56,7 @@ impl crate::Service for Service {Ok(Arc::new(Self {mutex_federation: RoomMutexMap::new(),federation_handletime: HandleTimeMap::new().into(),last_extremity_squash: SyncRwLock::new(HashMap::new()),This is technically the correct lock for the way you're using it, although in this case it's not so much of a difference from a mutex. additionally, you've technically left a race condition in between releasing the read and acquiring the write lock. you would have to use double-checked locking to take advantage of a rwlock safely in this case.
double checked locking being:
Also a concurrent map would be the ideal tool over a coarse lock, but idrc that much
3b6858e936729cbbd7da729cbbd7dabdd8ad1413@ -312,0 +338,4 @@let mut closing = false;let waker = tokio::time::sleep(Duration::from_mins(2));every 2 minutes is really lax, a room with extremities that need squashing is probably a really active room (like the ping room). I'd say 1 minute at most
@ -92,2 +95,4 @@fn interrupt(&self) { self.server_shutdown.notify_waiters(); }async fn clear_cache(&self) {}this should just be removed if it's going to be a no-op
f9a43abb7fb6bc7dfc165c48b99f475199cde870Last thing for me to do here if I have time is add some random jitter to the debounce
I'll do it now along with resolving remaining review comments
build_local_dag90797fa3cdbuild_local_dage936d18324c16de5570b62e0b53f52