Auto merge of #16456 - davidbarsky:david/tracing-followups, r=Veykril

internal: `tracing` improvements and followups

Hi folks! Building on https://github.com/rust-lang/rust-analyzer/pull/16394, I've got a few small tweaks:
- Removed the accidental `mod.rs` usage that I introduced.
- Removed a panic in `pat_analysis.rs`.
- Recorded the event kind in `handle_event` to better distinguish what _kind_ of event is being handled.
- Did a small refactor of `hprof` to have somewhat more linear control flow, and more importantly, write the recorded fields to the output.

The end result is the following:
<img width="1530" alt="A screenshot of Visual Studio Code on a Mac. `hprof.rs` is open, with " src="https://github.com/rust-lang/rust-analyzer/assets/2067774/bd11dde5-b2da-4774-bc38-bcb4772d1192">

crates/hir-ty/src/diagnostics/match_check/pat_analysis.rs

@@ -460,7 +460,8 @@ impl<'p> TypeCx for MatchCheckCtx<'p> {
         _f: &mut fmt::Formatter<'_>,
         _pat: &rustc_pattern_analysis::pat::DeconstructedPat<'_, Self>,
     ) -> fmt::Result {
-        unimplemented!()
+        // FIXME: implement this, as using `unimplemented!()` causes panics in `tracing`.
+        Ok(())
     }
 
     fn bug(&self, fmt: fmt::Arguments<'_>) -> ! {

crates/rust-analyzer/src/lib.rs

@@ -37,9 +37,14 @@ mod handlers {
     pub(crate) mod request;
 }
 
+pub mod tracing {
+    pub mod config;
+    pub use config::Config;
+    pub mod hprof;
+}
+
 pub mod config;
 pub mod lsp;
-pub mod tracing;
 use self::lsp::ext as lsp_ext;
 
 #[cfg(test)]

crates/rust-analyzer/src/main_loop.rs

@@ -60,6 +60,17 @@ enum Event {
     Flycheck(flycheck::Message),
 }
 
+impl fmt::Display for Event {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        match self {
+            Event::Lsp(_) => write!(f, "Event::Lsp"),
+            Event::Task(_) => write!(f, "Event::Task"),
+            Event::Vfs(_) => write!(f, "Event::Vfs"),
+            Event::Flycheck(_) => write!(f, "Event::Flycheck"),
+        }
+    }
+}
+
 #[derive(Debug)]
 pub(crate) enum Task {
     Response(lsp_server::Response),
@@ -196,7 +207,8 @@ impl GlobalState {
     fn handle_event(&mut self, event: Event) -> anyhow::Result<()> {
         let loop_start = Instant::now();
         // NOTE: don't count blocking select! call as a loop-turn time
-        let _p = tracing::span!(tracing::Level::INFO, "GlobalState::handle_event").entered();
+        let _p = tracing::span!(tracing::Level::INFO, "GlobalState::handle_event", event = %event)
+            .entered();
 
         let event_dbg_msg = format!("{event:?}");
         tracing::debug!("{:?} handle_event({})", loop_start, event_dbg_msg);

crates/rust-analyzer/src/tracing/config.rs

@@ -14,7 +14,7 @@ use tracing_subscriber::{
 };
 use tracing_tree::HierarchicalLayer;
 
-pub mod hprof;
+use crate::tracing::hprof;
 
 pub struct Config<T> {
     pub writer: T,

crates/rust-analyzer/src/tracing/hprof.rs

@@ -32,7 +32,8 @@
 //! ```
 
 use std::{
-    fmt, mem,
+    fmt::Write,
+    mem,
     time::{Duration, Instant},
 };
 
@@ -99,21 +100,37 @@ impl SpanTree {
 struct Data {
     start: Instant,
     children: Vec<Node>,
+    fields: String,
 }
 
 impl Data {
     fn new(attrs: &Attributes<'_>) -> Self {
-        let mut span = Self { start: Instant::now(), children: Vec::new() };
+        let mut data = Self { start: Instant::now(), children: Vec::new(), fields: String::new() };
-        attrs.record(&mut span);
+
-        span
+        let mut visitor = DataVisitor { string: &mut data.fields };
+        attrs.record(&mut visitor);
+        data
     }
+
     fn into_node(self, name: &'static str) -> Node {
-        Node { name, count: 1, duration: self.start.elapsed(), children: self.children }
+        Node {
+            name,
+            fields: self.fields,
+            count: 1,
+            duration: self.start.elapsed(),
+            children: self.children,
+        }
     }
 }
 
-impl Visit for Data {
+pub struct DataVisitor<'a> {
-    fn record_debug(&mut self, _field: &Field, _value: &dyn fmt::Debug) {}
+    string: &'a mut String,
+}
+
+impl<'a> Visit for DataVisitor<'a> {
+    fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) {
+        write!(self.string, "{} = {:?} ", field.name(), value).unwrap();
+    }
 }
 
 impl<S> Layer<S> for SpanTree
@@ -151,6 +168,7 @@ where
 #[derive(Default)]
 struct Node {
     name: &'static str,
+    fields: String,
     count: u32,
     duration: Duration,
     children: Vec<Node>,
@@ -163,16 +181,22 @@ impl Node {
 
     fn go(&self, level: usize, filter: &WriteFilter) {
         if self.duration > filter.longer_than && level < filter.depth {
-            let duration = format!("{:3.2?}", self.duration);
+            let duration = ms(self.duration);
-            let count = if self.count > 1 { self.count.to_string() } else { String::new() };
+            let current_indent = level * 2;
-            eprintln!(
+
-                "{:width$}  {:<9} {:<6} {}",
+            let mut out = String::new();
-                "",
+            let _ = write!(out, "{:current_indent$}   {duration} {:<6}", "", self.name);
-                duration,
+
-                count,
+            if !self.fields.is_empty() {
-                self.name,
+                let _ = write!(out, " @ {}", self.fields);
-                width = level * 2
+            }
-            );
+
+            if self.count > 1 {
+                let _ = write!(out, " ({} calls)", self.count);
+            }
+
+            eprintln!("{}", out);
+
             for child in &self.children {
                 child.go(level + 1, filter)
             }
@@ -236,3 +260,13 @@ impl WriteFilter {
         (WriteFilter { depth, longer_than }, allowed)
     }
 }
+
+#[allow(non_camel_case_types)]
+struct ms(Duration);
+
+impl std::fmt::Display for ms {
+    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+        let n = self.0.as_millis();
+        write!(f, "{n:5}ms")
+    }
+}