Log how long it takes to handle each RPC message

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 {
+                    let result = future.await;
-                        tracing::error!(%error, "error handling message");
+                    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)