Log timings of migrations and index/constraint rebuilds

Author: reivilibre

crates/syn2mas/src/mas_writer/constraint_pausing.rs

@@ -3,8 +3,10 @@
 // SPDX-License-Identifier: AGPL-3.0-only
 // Please see LICENSE in the repository root for full details.
 
+use std::time::Instant;
+
 use sqlx::PgConnection;
-use tracing::debug;
+use tracing::{debug, info};
 
 use super::{Error, IntoDatabase};
 
@@ -114,6 +116,8 @@ pub async fn restore_constraint(
     conn: &mut PgConnection,
     constraint: &ConstraintDescription,
 ) -> Result<(), Error> {
+    let start = Instant::now();
+
     let ConstraintDescription {
         name,
         table_name,
@@ -128,6 +132,11 @@ pub async fn restore_constraint(
         format!("failed to recreate constraint {name} on {table_name} with {definition}")
     })?;
 
+    info!(
+        "constraint {name} rebuilt in {:.1}s",
+        Instant::now().duration_since(start).as_secs_f64()
+    );
+
     Ok(())
 }
 
@@ -136,6 +145,8 @@ pub async fn restore_constraint(
 /// The index must not exist prior to this call.
 #[tracing::instrument(name = "syn2mas.restore_index", skip_all, fields(index.name = index.name))]
 pub async fn restore_index(conn: &mut PgConnection, index: &IndexDescription) -> Result<(), Error> {
+    let start = Instant::now();
+
     let IndexDescription {
         name,
         table_name,
@@ -149,5 +160,10 @@ pub async fn restore_index(conn: &mut PgConnection, index: &IndexDescription) ->
             format!("failed to recreate index {name} on {table_name} with {definition}")
         })?;
 
+    info!(
+        "index {name} rebuilt in {:.1}s",
+        Instant::now().duration_since(start).as_secs_f64()
+    );
+
     Ok(())
 }

crates/syn2mas/src/migration.rs

@@ -29,7 +29,7 @@ use mas_storage::Clock;
 use rand::RngCore;
 use thiserror::Error;
 use thiserror_ext::ContextInto;
-use tracing::{Level, Span};
+use tracing::{info, Level, Span};
 use tracing_indicatif::{span_ext::IndicatifSpanExt, style::ProgressStyle};
 use ulid::Ulid;
 use uuid::Uuid;
@@ -252,6 +252,8 @@ async fn migrate_users(
     server_name: &str,
     rng: &mut impl RngCore,
 ) -> Result<UsersMigrated, Error> {
+    let start = Instant::now();
+
     let span = Span::current();
     span.pb_set_style(&ProgressStyle::default_bar());
     span.pb_set_length(user_count_hint as u64);
@@ -298,6 +300,11 @@ async fn migrate_users(
         .await
         .into_mas("writing passwords")?;
 
+    info!(
+        "users migrated in {:.1}s",
+        Instant::now().duration_since(start).as_secs_f64()
+    );
+
     Ok(UsersMigrated {
         user_localparts_to_uuid,
         synapse_admins,
@@ -313,6 +320,8 @@ async fn migrate_threepids(
     rng: &mut impl RngCore,
     user_localparts_to_uuid: &HashMap<CompactString, Uuid>,
 ) -> Result<(), Error> {
+    let start = Instant::now();
+
     let span = Span::current();
     span.pb_set_style(&ProgressStyle::default_bar());
     span.pb_set_length(count_hint);
@@ -392,6 +401,11 @@ async fn migrate_threepids(
         .await
         .into_mas("writing unsupported threepids")?;
 
+    info!(
+        "third-party IDs migrated in {:.1}s",
+        Instant::now().duration_since(start).as_secs_f64()
+    );
+
     Ok(())
 }
 
@@ -409,6 +423,8 @@ async fn migrate_external_ids(
     user_localparts_to_uuid: &HashMap<CompactString, Uuid>,
     provider_id_mapping: &HashMap<String, Uuid>,
 ) -> Result<(), Error> {
+    let start = Instant::now();
+
     let span = Span::current();
     span.pb_set_style(&ProgressStyle::default_bar());
     span.pb_set_length(count_hint);
@@ -470,7 +486,12 @@ async fn migrate_external_ids(
     write_buffer
         .finish(mas)
         .await
-        .into_mas("writing threepids")?;
+        .into_mas("writing upstream links")?;
+
+    info!(
+        "upstream links (external IDs) migrated in {:.1}s",
+        Instant::now().duration_since(start).as_secs_f64()
+    );
 
     Ok(())
 }
@@ -495,6 +516,8 @@ async fn migrate_devices(
     devices: &mut HashMap<(Uuid, CompactString), Uuid>,
     synapse_admins: &HashSet<Uuid>,
 ) -> Result<(), Error> {
+    let start = Instant::now();
+
     let span = Span::current();
     span.pb_set_style(&ProgressStyle::default_bar());
     span.pb_set_length(count_hint);
@@ -579,6 +602,11 @@ async fn migrate_devices(
         .await
         .into_mas("writing compat sessions")?;
 
+    info!(
+        "devices migrated in {:.1}s",
+        Instant::now().duration_since(start).as_secs_f64()
+    );
+
     Ok(())
 }
 
@@ -596,6 +624,8 @@ async fn migrate_unrefreshable_access_tokens(
     user_localparts_to_uuid: &HashMap<CompactString, Uuid>,
     devices: &mut HashMap<(Uuid, CompactString), Uuid>,
 ) -> Result<(), Error> {
+    let start = Instant::now();
+
     let span = Span::current();
     span.pb_set_style(&ProgressStyle::default_bar());
     span.pb_set_length(count_hint);
@@ -697,6 +727,11 @@ async fn migrate_unrefreshable_access_tokens(
         .await
         .into_mas("writing deviceless compat sessions")?;
 
+    info!(
+        "non-refreshable access tokens migrated in {:.1}s",
+        Instant::now().duration_since(start).as_secs_f64()
+    );
+
     Ok(())
 }
 
@@ -714,6 +749,8 @@ async fn migrate_refreshable_token_pairs(
     user_localparts_to_uuid: &HashMap<CompactString, Uuid>,
     devices: &mut HashMap<(Uuid, CompactString), Uuid>,
 ) -> Result<(), Error> {
+    let start = Instant::now();
+
     let span = Span::current();
     span.pb_set_style(&ProgressStyle::default_bar());
     span.pb_set_length(count_hint);
@@ -803,6 +840,11 @@ async fn migrate_refreshable_token_pairs(
         .await
         .into_mas("writing compat refresh tokens")?;
 
+    info!(
+        "refreshable token pairs migrated in {:.1}s",
+        Instant::now().duration_since(start).as_secs_f64()
+    );
+
     Ok(())
 }