From 0b3345f59208cb8873e496b95c9bbdf20d665bd6 Mon Sep 17 00:00:00 2001 From: Benjamin Bouvier Date: Tue, 2 Sep 2025 17:59:15 +0200 Subject: [PATCH] feat(sdk): add more timers to sync processing --- crates/matrix-sdk-base/src/client.rs | 2 ++ .../src/response_processors/account_data/global.rs | 5 +++++ crates/matrix-sdk-base/src/response_processors/changes.rs | 5 +++++ .../src/response_processors/e2ee/tracked_users.rs | 3 +++ .../src/response_processors/room/display_name.rs | 4 ++++ .../src/response_processors/room/msc4186/mod.rs | 5 +++++ crates/matrix-sdk-base/src/response_processors/timeline.rs | 4 +++- crates/matrix-sdk-base/src/sliding_sync.rs | 4 +++- crates/matrix-sdk-crypto/src/machine/mod.rs | 4 +++- crates/matrix-sdk/src/sliding_sync/client.rs | 6 +++++- crates/matrix-sdk/src/sync.rs | 3 +++ 11 files changed, 41 insertions(+), 4 deletions(-) diff --git a/crates/matrix-sdk-base/src/client.rs b/crates/matrix-sdk-base/src/client.rs index 250ed4e58..38a8e5f01 100644 --- a/crates/matrix-sdk-base/src/client.rs +++ b/crates/matrix-sdk-base/src/client.rs @@ -24,6 +24,7 @@ use std::{ use eyeball::{SharedObservable, Subscriber}; use eyeball_im::{Vector, VectorDiff}; use futures_util::Stream; +use matrix_sdk_common::timer; #[cfg(feature = "e2e-encryption")] use matrix_sdk_crypto::{ CollectStrategy, DecryptionSettings, EncryptionSettings, OlmError, OlmMachine, @@ -1060,6 +1061,7 @@ impl BaseClient { &self, global_account_data_processor: &processors::account_data::Global, ) -> Result { + let _timer = timer!(Level::TRACE, "get_push_rules"); if let Some(event) = global_account_data_processor .push_rules() .and_then(|ev| ev.deserialize_as_unchecked::().ok()) diff --git a/crates/matrix-sdk-base/src/response_processors/account_data/global.rs b/crates/matrix-sdk-base/src/response_processors/account_data/global.rs index e0be9ff67..2450a55e9 100644 --- a/crates/matrix-sdk-base/src/response_processors/account_data/global.rs +++ b/crates/matrix-sdk-base/src/response_processors/account_data/global.rs @@ -17,6 +17,7 @@ use std::{ mem, }; +use matrix_sdk_common::timer; use ruma::{ RoomId, events::{ @@ -43,6 +44,8 @@ pub struct Global { impl Global { /// Creates a new processor for global account data. fn process(events: &[Raw]) -> Self { + let _timer = timer!(tracing::Level::TRACE, "Global::process (global account data)"); + let mut raw_by_type = BTreeMap::new(); let mut parsed_events = Vec::new(); @@ -125,6 +128,8 @@ impl Global { /// Applies the processed data to the state changes and the state store. pub async fn apply(mut self, context: &mut Context, state_store: &BaseStateStore) { + let _timer = timer!(tracing::Level::TRACE, "Global::apply (global account data)"); + // Fill in the content of `changes.account_data`. mem::swap(&mut context.state_changes.account_data, &mut self.raw_by_type); diff --git a/crates/matrix-sdk-base/src/response_processors/changes.rs b/crates/matrix-sdk-base/src/response_processors/changes.rs index 176c86cda..f6bc0162b 100644 --- a/crates/matrix-sdk-base/src/response_processors/changes.rs +++ b/crates/matrix-sdk-base/src/response_processors/changes.rs @@ -13,6 +13,7 @@ // limitations under the License. use eyeball::SharedObservable; +use matrix_sdk_common::timer; use ruma::{ events::{GlobalAccountDataEventType, ignored_user_list::IgnoredUserListEvent}, serde::Raw, @@ -29,6 +30,8 @@ use crate::{ /// only! The changes aren't applied on the in-memory rooms. #[instrument(skip_all)] pub async fn save_only(context: Context, state_store: &BaseStateStore) -> Result<()> { + let _timer = timer!(tracing::Level::TRACE, "_method"); + save_changes(&context, state_store, None).await?; broadcast_room_info_notable_updates(&context, state_store); @@ -44,6 +47,8 @@ pub async fn save_and_apply( ignore_user_list_changes: &SharedObservable>, sync_token: Option, ) -> Result<()> { + let _timer = timer!(tracing::Level::TRACE, "_method"); + trace!("ready to submit changes to store"); let previous_ignored_user_list = diff --git a/crates/matrix-sdk-base/src/response_processors/e2ee/tracked_users.rs b/crates/matrix-sdk-base/src/response_processors/e2ee/tracked_users.rs index 9ba0b5366..4749f215a 100644 --- a/crates/matrix-sdk-base/src/response_processors/e2ee/tracked_users.rs +++ b/crates/matrix-sdk-base/src/response_processors/e2ee/tracked_users.rs @@ -14,6 +14,7 @@ use std::collections::BTreeSet; +use matrix_sdk_common::timer; use matrix_sdk_crypto::OlmMachine; use ruma::{OwnedUserId, RoomId}; @@ -45,6 +46,8 @@ pub async fn update_or_set_if_room_is_newly_encrypted( room_id: &RoomId, state_store: &BaseStateStore, ) -> Result<()> { + let _timer = timer!(tracing::Level::TRACE, "update_or_set_if_room_is_newly_encrypted"); + if new_room_encryption_state.is_encrypted() && let Some(olm) = olm_machine { diff --git a/crates/matrix-sdk-base/src/response_processors/room/display_name.rs b/crates/matrix-sdk-base/src/response_processors/room/display_name.rs index 608d44457..c62810dca 100644 --- a/crates/matrix-sdk-base/src/response_processors/room/display_name.rs +++ b/crates/matrix-sdk-base/src/response_processors/room/display_name.rs @@ -12,6 +12,8 @@ // See the License for the specific language governing permissions and // limitations under the License. +use matrix_sdk_common::timer; + use super::super::Context; use crate::{ RoomInfoNotableUpdateReasons, room::UpdatedRoomDisplayName, store::BaseStateStore, @@ -23,6 +25,8 @@ pub async fn update_for_rooms( room_updates: &RoomUpdates, state_store: &BaseStateStore, ) { + let _timer = timer!(tracing::Level::TRACE, "display_name::update_for_rooms"); + for room in room_updates.iter_all_room_ids().filter_map(|room_id| state_store.room(room_id)) { // Compute the display name. If it's different, let's register the `RoomInfo` in // the `StateChanges`. diff --git a/crates/matrix-sdk-base/src/response_processors/room/msc4186/mod.rs b/crates/matrix-sdk-base/src/response_processors/room/msc4186/mod.rs index 800e47e8d..881ed3da3 100644 --- a/crates/matrix-sdk-base/src/response_processors/room/msc4186/mod.rs +++ b/crates/matrix-sdk-base/src/response_processors/room/msc4186/mod.rs @@ -20,6 +20,7 @@ use std::collections::BTreeSet; #[cfg(feature = "e2e-encryption")] use matrix_sdk_common::deserialized_responses::TimelineEvent; +use matrix_sdk_common::timer; use ruma::{ JsOption, OwnedRoomId, RoomId, UserId, api::client::sync::sync_events::{ @@ -67,6 +68,8 @@ pub async fn update_any_room( #[cfg(feature = "e2e-encryption")] e2ee: e2ee::E2EE<'_>, notification: notification::Notification<'_>, ) -> Result> { + let _timer = timer!(tracing::Level::TRACE, "update_any_room"); + let RoomCreationData { room_id, room_info_notable_update_sender, @@ -438,6 +441,8 @@ pub(crate) async fn cache_latest_events( store::ambiguity_map::is_display_name_ambiguous, }; + let _timer = timer!(tracing::Level::TRACE, "cache_latest_events"); + let mut encrypted_events = Vec::with_capacity(room.latest_encrypted_events.read().unwrap().capacity()); diff --git a/crates/matrix-sdk-base/src/response_processors/timeline.rs b/crates/matrix-sdk-base/src/response_processors/timeline.rs index 11a9a2b32..ecf0c8595 100644 --- a/crates/matrix-sdk-base/src/response_processors/timeline.rs +++ b/crates/matrix-sdk-base/src/response_processors/timeline.rs @@ -12,7 +12,7 @@ // See the License for the specific language governing permissions and // limitations under the License. -use matrix_sdk_common::deserialized_responses::TimelineEvent; +use matrix_sdk_common::{deserialized_responses::TimelineEvent, timer}; #[cfg(feature = "e2e-encryption")] use ruma::events::SyncMessageLikeEvent; use ruma::{ @@ -44,6 +44,8 @@ pub async fn build<'notification, 'e2ee>( mut notification: notification::Notification<'notification>, #[cfg(feature = "e2e-encryption")] e2ee: e2ee::E2EE<'e2ee>, ) -> Result { + let _timer = timer!(tracing::Level::TRACE, "build a timeline from sync"); + let mut timeline = Timeline::new(timeline_inputs.limited, timeline_inputs.prev_batch); let mut push_condition_room_ctx = get_push_room_context(context, room, room_info).await?; let room_id = room.room_id(); diff --git a/crates/matrix-sdk-base/src/sliding_sync.rs b/crates/matrix-sdk-base/src/sliding_sync.rs index 520dcecbd..f91978eaa 100644 --- a/crates/matrix-sdk-base/src/sliding_sync.rs +++ b/crates/matrix-sdk-base/src/sliding_sync.rs @@ -16,7 +16,7 @@ #[cfg(feature = "e2e-encryption")] use matrix_sdk_common::deserialized_responses::ProcessedToDeviceEvent; -use matrix_sdk_common::deserialized_responses::TimelineEvent; +use matrix_sdk_common::{deserialized_responses::TimelineEvent, timer}; use ruma::{OwnedRoomId, api::client::sync::sync_events::v5 as http}; use tracing::{instrument, trace}; @@ -124,6 +124,8 @@ impl BaseClient { return Ok(SyncResponse::default()); } + let _timer = timer!(tracing::Level::TRACE, "_method"); + let mut context = processors::Context::default(); let state_store = self.state_store.clone(); diff --git a/crates/matrix-sdk-crypto/src/machine/mod.rs b/crates/matrix-sdk-crypto/src/machine/mod.rs index 38ecf3ee1..3fd522267 100644 --- a/crates/matrix-sdk-crypto/src/machine/mod.rs +++ b/crates/matrix-sdk-crypto/src/machine/mod.rs @@ -31,7 +31,7 @@ use matrix_sdk_common::{ UnsignedEventLocation, VerificationLevel, VerificationState, }, locks::RwLock as StdRwLock, - BoxFuture, + timer, BoxFuture, }; #[cfg(feature = "experimental-encrypted-state-events")] use ruma::events::{AnyStateEventContent, StateEventContent}; @@ -2203,6 +2203,8 @@ impl OlmMachine { decrypt_unsigned: bool, decryption_settings: &DecryptionSettings, ) -> MegolmResult { + let _timer = timer!(tracing::Level::TRACE, "_method"); + let event = event.deserialize()?; Span::current() diff --git a/crates/matrix-sdk/src/sliding_sync/client.rs b/crates/matrix-sdk/src/sliding_sync/client.rs index 176b89804..0d4c46704 100644 --- a/crates/matrix-sdk/src/sliding_sync/client.rs +++ b/crates/matrix-sdk/src/sliding_sync/client.rs @@ -1,7 +1,7 @@ use std::collections::BTreeSet; use matrix_sdk_base::{ - sync::SyncResponse, RequestedRequiredStates, ThreadSubscriptionCatchupToken, + sync::SyncResponse, timer, RequestedRequiredStates, ThreadSubscriptionCatchupToken, }; use matrix_sdk_common::deserialized_responses::ProcessedToDeviceEvent; use ruma::api::{ @@ -240,6 +240,8 @@ impl SlidingSyncResponseProcessor { /// /// This will only fill the in-memory caches, not save the info on disk. async fn update_in_memory_caches(client: &Client, response: &SyncResponse) -> Result<()> { + let _timer = timer!(tracing::Level::TRACE, "update_in_memory_caches"); + for room_id in response.rooms.joined.keys() { let Some(room) = client.get_room(room_id) else { error!(?room_id, "Cannot post process a room in sliding sync because it is missing"); @@ -258,6 +260,8 @@ async fn handle_receipts_extension( response: &http::Response, sync_response: &mut SyncResponse, ) -> Result<()> { + let _timer = timer!(tracing::Level::TRACE, "handle_receipts_extension"); + // We need to compute read receipts for each joined room that has received an // update, or from each room that has received a receipt ephemeral event. let room_ids = BTreeSet::from_iter( diff --git a/crates/matrix-sdk/src/sync.rs b/crates/matrix-sdk/src/sync.rs index 0b42e0d3f..06d30a86c 100644 --- a/crates/matrix-sdk/src/sync.rs +++ b/crates/matrix-sdk/src/sync.rs @@ -28,6 +28,7 @@ use matrix_sdk_base::{ }, sleep::sleep, sync::SyncResponse as BaseSyncResponse, + timer, }; use matrix_sdk_common::deserialized_responses::ProcessedToDeviceEvent; use ruma::{ @@ -172,6 +173,8 @@ impl Client { &self, response: &BaseSyncResponse, ) -> Result<()> { + let _timer = timer!(tracing::Level::TRACE, "_method"); + let BaseSyncResponse { rooms, presence, account_data, to_device, notifications } = response; let now = Instant::now();