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

@@ -11,7 +11,7 @@
 //! This module does not implement any of the safety checks that should be run
 //! *before* the migration.
 
-use std::{collections::HashMap, pin::pin};
+use std::{collections::HashMap, pin::pin, time::Instant};
 
 use chrono::{DateTime, Utc};
 use compact_str::CompactString;
@@ -20,7 +20,7 @@ use mas_storage::Clock;
 use rand::RngCore;
 use thiserror::Error;
 use thiserror_ext::ContextInto;
-use tracing::{Level, Span};
+use tracing::{Level, Span, info};
 use tracing_indicatif::{span_ext::IndicatifSpanExt, style::ProgressStyle};
 use ulid::Ulid;
 use uuid::Uuid;
@@ -230,6 +230,8 @@ async fn migrate_users(
     mut state: MigrationState,
     rng: &mut impl RngCore,
 ) -> Result<(MasWriter, MigrationState), Error> {
+    let start = Instant::now();
+
     let span = Span::current();
     span.pb_set_style(&ProgressStyle::default_bar());
     span.pb_set_length(count_hint as u64);
@@ -299,6 +301,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((mas, state))
 }
 
@@ -310,6 +317,8 @@ async fn migrate_threepids(
     rng: &mut impl RngCore,
     state: MigrationState,
 ) -> Result<(MasWriter, MigrationState), Error> {
+    let start = Instant::now();
+
     let span = Span::current();
     span.pb_set_style(&ProgressStyle::default_bar());
     span.pb_set_length(count_hint as u64);
@@ -385,6 +394,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((mas, state))
 }
 
@@ -400,6 +414,7 @@ async fn migrate_external_ids(
     rng: &mut impl RngCore,
     state: MigrationState,
 ) -> Result<(MasWriter, MigrationState), Error> {
+    let start = Instant::now();
     let span = Span::current();
     span.pb_set_style(&ProgressStyle::default_bar());
     span.pb_set_length(count_hint as u64);
@@ -461,7 +476,12 @@ async fn migrate_external_ids(
     write_buffer
         .finish(&mut 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((mas, state))
 }
@@ -483,6 +503,8 @@ async fn migrate_devices(
     rng: &mut impl RngCore,
     mut state: MigrationState,
 ) -> Result<(MasWriter, MigrationState), Error> {
+    let start = Instant::now();
+
     let span = Span::current();
     span.pb_set_style(&ProgressStyle::default_bar());
     span.pb_set_length(count_hint as u64);
@@ -572,6 +594,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((mas, state))
 }
 
@@ -587,6 +614,8 @@ async fn migrate_unrefreshable_access_tokens(
     rng: &mut impl RngCore,
     mut state: MigrationState,
 ) -> Result<(MasWriter, MigrationState), Error> {
+    let start = Instant::now();
+
     let span = Span::current();
     span.pb_set_style(&ProgressStyle::default_bar());
     span.pb_set_length(count_hint as u64);
@@ -691,6 +720,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((mas, state))
 }
 
@@ -706,6 +740,8 @@ async fn migrate_refreshable_token_pairs(
     rng: &mut impl RngCore,
     mut state: MigrationState,
 ) -> Result<(MasWriter, MigrationState), Error> {
+    let start = Instant::now();
+
     let span = Span::current();
     span.pb_set_style(&ProgressStyle::default_bar());
     span.pb_set_length(count_hint as u64);
@@ -798,6 +834,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((mas, state))
 }