Debug-mode clients report slow and large transitions (#40943)

thomasballinger · Convex, Inc. · commit a70eeb0876f8 · 2025-09-12T23:57:37.000Z
GitOrigin-RevId: b932a0408c54b712c4e81e574e3ee108a784e6c7
diff --git a/crates/sync/src/metrics.rs b/crates/sync/src/metrics.rs
@@ -348,9 +348,38 @@ impl TryFrom<JsonValue> for ClientMark {
     }
 }
 
+pub fn log_client_transition(partition_id: u64, transition_transit_time: f64, message_length: f64) {
+    log_distribution_with_labels(
+        &SYNC_TRANSITION_TRANSIT_TIME_SECONDS,
+        transition_transit_time / 1000.0,
+        vec![StaticMetricLabel::new(
+            "partition_id",
+            partition_id.to_string(),
+        )],
+    );
+    log_distribution_with_labels(
+        &SYNC_TRANSITION_MESSAGE_LENGTH_BYTES,
+        message_length,
+        vec![StaticMetricLabel::new(
+            "partition_id",
+            partition_id.to_string(),
+        )],
+    );
+}
+
 #[derive(Clone, Debug)]
 pub enum TypedClientEvent {
-    ClientConnect { marks: Vec<ClientMark> },
+    ClientConnect {
+        marks: Vec<ClientMark>,
+    },
+    ClientReceivedTransition {
+        /// Time from the server sending the transition to the client fully
+        /// receiving it (after finishing downloading it), corrected by
+        /// an estimated clock skew observed when the client sends a
+        /// smaller message in the other direction.
+        transition_transit_time: f64,
+        message_length: f64,
+    },
 }
 
 impl TryFrom<ClientEvent> for TypedClientEvent {
@@ -371,6 +400,14 @@ impl TryFrom<ClientEvent> for TypedClientEvent {
                     marks: parsed_marks,
                 })
             },
+            "ClientReceivedTransition" => {
+                let event_data: ClientReceivedTransitionEvent =
+                    serde_json::from_value(value.event)?;
+                Ok(TypedClientEvent::ClientReceivedTransition {
+                    transition_transit_time: event_data.transition_transit_time,
+                    message_length: event_data.message_length,
+                })
+            },
             _ => Err(anyhow::anyhow!("Unknown ClientEvent type")),
         }
     }
@@ -391,6 +428,23 @@ struct ClientMarkJson {
     start_time: f64,
 }
 
+#[derive(Deserialize)]
+#[serde(rename_all = "camelCase")]
+struct ClientReceivedTransitionEvent {
+    transition_transit_time: f64,
+    message_length: f64,
+}
+
+register_convex_histogram!(
+    SYNC_TRANSITION_TRANSIT_TIME_SECONDS,
+    "Time for transition to transit from client (corrected by an estimated clock skew)",
+    &["partition_id"]
+);
+register_convex_histogram!(
+    SYNC_TRANSITION_MESSAGE_LENGTH_BYTES,
+    "Length of transition message from client",
+    &["partition_id"]
+);
 register_convex_histogram!(
     SYNC_QUERY_INVALIDATION_LAG_SECONDS,
     "Time between an invalidating write and a query being rerun",
diff --git a/crates/sync/src/worker.rs b/crates/sync/src/worker.rs
@@ -741,6 +741,14 @@ impl<RT: Runtime> SyncWorker<RT> {
                         TypedClientEvent::ClientConnect { marks } => {
                             metrics::log_client_connect_timings(self.partition_id, marks)
                         },
+                        TypedClientEvent::ClientReceivedTransition {
+                            transition_transit_time,
+                            message_length,
+                        } => metrics::log_client_transition(
+                            self.partition_id,
+                            transition_transit_time,
+                            message_length,
+                        ),
                     },
                     Err(_) => (),
                 }
diff --git a/npm-packages/convex/src/browser/sync/client.ts b/npm-packages/convex/src/browser/sync/client.ts
@@ -497,6 +497,7 @@ export class BaseConvexClient {
       webSocketConstructor,
       this.logger,
       this.markConnectionStateDirty,
+      this.debug,
     );
     this.mark("convexClientConstructed");
 
diff --git a/npm-packages/convex/src/browser/sync/web_socket_manager.ts b/npm-packages/convex/src/browser/sync/web_socket_manager.ts
@@ -4,6 +4,7 @@ import {
   encodeClientMessage,
   parseServerMessage,
   ServerMessage,
+  Transition,
 } from "./protocol.js";
 
 const CLOSE_NORMAL = 1000;
@@ -199,6 +200,7 @@ export class WebSocketManager {
     webSocketConstructor: typeof WebSocket,
     logger: Logger,
     private readonly markConnectionStateDirty: () => void,
+    private readonly debug: boolean,
   ) {
     this.webSocketConstructor = webSocketConstructor;
     this.socket = { state: "disconnected" };
@@ -312,40 +314,11 @@ export class WebSocketManager {
       const messageLength = message.data.length;
       const serverMessage = parseServerMessage(JSON.parse(message.data));
       this._logVerbose(`received ws message with type ${serverMessage.type}`);
-      if (
-        serverMessage.type === "Transition" &&
-        serverMessage.clientClockSkew !== undefined &&
-        serverMessage.serverTs !== undefined
-      ) {
-        const transitionTransitTime =
-          monotonicMillis() - // client time now
-          // clientClockSkew = (server time + upstream latency) - client time
-          // clientClockSkew is "how many milliseconds behind (slow) is the client clock"
-          // but the latency of the Connect message inflates this, making it appear further behind
-          serverMessage.clientClockSkew -
-          serverMessage.serverTs / 1_000_000; // server time when transition was sent
-        const prettyTransitionTime = `${Math.round(transitionTransitTime)}ms`;
-        const prettyMessageMB = `${Math.round(messageLength / 10_000) / 100}MB`;
-        const bytesPerSecond = messageLength / (transitionTransitTime / 1000);
-        const prettyBytesPerSecond = `${Math.round(bytesPerSecond / 10_000) / 100}MB per second`;
-        this._logVerbose(
-          `received ${prettyMessageMB} transition in ${prettyTransitionTime} at ${prettyBytesPerSecond}`,
-        );
-
-        // Warnings that will show up for *all users*, so these are not very aggressive goals.
-        if (transitionTransitTime > 10_000 && messageLength > 10_000_000) {
-          this.logger.log(
-            `received query results totalling more than 10MB (${prettyMessageMB}) which took more than 10s (${prettyTransitionTime}) to arrive`,
-          );
-        } else if (messageLength > 20_000_000) {
-          this.logger.log(
-            `received query results totalling more that 20MB (${prettyMessageMB}) which will take a long time to download on slower connections`,
-          );
-        } else if (transitionTransitTime > 20_000) {
-          this.logger.log(
-            `received query results totalling ${prettyMessageMB} which took more than 20s to arrive (${prettyTransitionTime})`,
-          );
-        }
+      if (serverMessage.type === "Transition") {
+        this.reportLargeTransition({
+          messageLength,
+          transition: serverMessage,
+        });
       }
       const response = this.onMessage(serverMessage);
       if (response.hasSyncedPastLastReconnect) {
@@ -686,4 +659,58 @@ export class WebSocketManager {
     const jitter = actualBackoff * (Math.random() - 0.5);
     return actualBackoff + jitter;
   }
+
+  private reportLargeTransition({
+    transition,
+    messageLength,
+  }: {
+    transition: Transition;
+    messageLength: number;
+  }) {
+    if (
+      transition.clientClockSkew === undefined ||
+      transition.serverTs === undefined
+    ) {
+      return;
+    }
+
+    const transitionTransitTime =
+      monotonicMillis() - // client time now
+      // clientClockSkew = (server time + upstream latency) - client time
+      // clientClockSkew is "how many milliseconds behind (slow) is the client clock"
+      // but the latency of the Connect message inflates this, making it appear further behind
+      transition.clientClockSkew -
+      transition.serverTs / 1_000_000; // server time when transition was sent
+    const prettyTransitionTime = `${Math.round(transitionTransitTime)}ms`;
+    const prettyMessageMB = `${Math.round(messageLength / 10_000) / 100}MB`;
+    const bytesPerSecond = messageLength / (transitionTransitTime / 1000);
+    const prettyBytesPerSecond = `${Math.round(bytesPerSecond / 10_000) / 100}MB per second`;
+    this._logVerbose(
+      `received ${prettyMessageMB} transition in ${prettyTransitionTime} at ${prettyBytesPerSecond}`,
+    );
+
+    // Warnings that will show up for *all users*, so these are not very aggressive goals.
+    if (transitionTransitTime > 10_000 && messageLength > 10_000_000) {
+      this.logger.log(
+        `received query results totalling more than 10MB (${prettyMessageMB}) which took more than 10s (${prettyTransitionTime}) to arrive`,
+      );
+    } else if (messageLength > 20_000_000) {
+      this.logger.log(
+        `received query results totalling more that 20MB (${prettyMessageMB}) which will take a long time to download on slower connections`,
+      );
+    } else if (transitionTransitTime > 20_000) {
+      this.logger.log(
+        `received query results totalling ${prettyMessageMB} which took more than 20s to arrive (${prettyTransitionTime})`,
+      );
+    }
+    if (this.debug) {
+      if (transitionTransitTime > 10_000 || messageLength > 10_000_000) {
+        this.sendMessage({
+          type: "Event",
+          eventType: "ClientReceivedTransition",
+          event: { transitionTransitTime, messageLength },
+        });
+      }
+    }
+  }
 }
