Improve collab logging (#2487)

Max Brunsfeld created 2 years ago

This adds some logging to the collab server, to help us identify the
source of the collaboration latency we're seeing in the 0.87 preview
version of zed.

Change summary

Cargo.lock               |  2 +-
crates/collab/Cargo.toml |  2 +-
crates/collab/src/rpc.rs | 12 +++++++++---
3 files changed, 11 insertions(+), 5 deletions(-)

Detailed changes

Cargo.lock

@@ -1230,7 +1230,7 @@ dependencies = [
 
 [[package]]
 name = "collab"
-version = "0.12.1"
+version = "0.12.3"
 dependencies = [
  "anyhow",
  "async-tungstenite",

crates/collab/Cargo.toml

@@ -3,7 +3,7 @@ authors = ["Nathan Sobo <[e-mail]>"]
 default-run = "collab"
 edition = "2021"
 name = "collab"
-version = "0.12.1"
+version = "0.12.3"
 publish = false
 
 [[bin]]

crates/collab/src/rpc.rs

@@ -51,7 +51,7 @@ use std::{
         atomic::{AtomicBool, Ordering::SeqCst},
         Arc,
     },
-    time::Duration,
+    time::{Duration, Instant},
 };
 use tokio::sync::{watch, Semaphore};
 use tower::ServiceBuilder;
@@ -397,10 +397,16 @@ impl Server {
                         "message received"
                     );
                 });
+                let start_time = Instant::now();
                 let future = (handler)(*envelope, session);
                 async move {
-                    if let Err(error) = future.await {
-                        tracing::error!(%error, "error handling message");
+                    let result = future.await;
+                    let duration_ms = start_time.elapsed().as_micros() as f64 / 1000.0;
+                    match result {
+                        Err(error) => {
+                            tracing::error!(%error, ?duration_ms, "error handling message")
+                        }
+                        Ok(()) => tracing::info!(?duration_ms, "finished handling message"),
                     }
                 }
                 .instrument(span)