From 17d2e8d9101b547e6cc3b19d278b2f925e2d972f Mon Sep 17 00:00:00 2001 From: David Barsky Date: Tue, 30 Jan 2024 13:37:27 -0500 Subject: [PATCH 1/4] internal: remove `tracing/mod.rs` --- crates/rust-analyzer/src/lib.rs | 7 ++++++- crates/rust-analyzer/src/tracing/{mod.rs => config.rs} | 2 +- 2 files changed, 7 insertions(+), 2 deletions(-) rename crates/rust-analyzer/src/tracing/{mod.rs => config.rs} (99%) diff --git a/crates/rust-analyzer/src/lib.rs b/crates/rust-analyzer/src/lib.rs index b77e1dca29..c22834ee10 100644 --- a/crates/rust-analyzer/src/lib.rs +++ b/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)] diff --git a/crates/rust-analyzer/src/tracing/mod.rs b/crates/rust-analyzer/src/tracing/config.rs similarity index 99% rename from crates/rust-analyzer/src/tracing/mod.rs rename to crates/rust-analyzer/src/tracing/config.rs index 0e681c3709..fcdbd1e6d9 100644 --- a/crates/rust-analyzer/src/tracing/mod.rs +++ b/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 { pub writer: T, From 251b14f2c58202d11c03c98ad72133beb28570ca Mon Sep 17 00:00:00 2001 From: David Barsky Date: Tue, 30 Jan 2024 18:07:29 -0500 Subject: [PATCH 2/4] internal: don't panic in `debug_pat` --- crates/hir-ty/src/diagnostics/match_check/pat_analysis.rs | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/crates/hir-ty/src/diagnostics/match_check/pat_analysis.rs b/crates/hir-ty/src/diagnostics/match_check/pat_analysis.rs index e2d8c97cd9..0b595042cd 100644 --- a/crates/hir-ty/src/diagnostics/match_check/pat_analysis.rs +++ b/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<'_>) -> ! { From 579e98c4c5235def0f190f2c2a56590d51709975 Mon Sep 17 00:00:00 2001 From: David Barsky Date: Tue, 30 Jan 2024 18:08:34 -0500 Subject: [PATCH 3/4] internal: record Event kind in `handle_event` --- crates/rust-analyzer/src/main_loop.rs | 14 +++++++++++++- 1 file changed, 13 insertions(+), 1 deletion(-) diff --git a/crates/rust-analyzer/src/main_loop.rs b/crates/rust-analyzer/src/main_loop.rs index 3c86414d02..f3ead6d04f 100644 --- a/crates/rust-analyzer/src/main_loop.rs +++ b/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); From 44494e235a0558c531173fe25ede4f164ea2e4ef Mon Sep 17 00:00:00 2001 From: David Barsky Date: Tue, 30 Jan 2024 18:13:29 -0500 Subject: [PATCH 4/4] internal: teach hprof to record `tracing` fields --- crates/rust-analyzer/src/tracing/hprof.rs | 68 +++++++++++++++++------ 1 file changed, 51 insertions(+), 17 deletions(-) diff --git a/crates/rust-analyzer/src/tracing/hprof.rs b/crates/rust-analyzer/src/tracing/hprof.rs index f37262a17a..c99b551df8 100644 --- a/crates/rust-analyzer/src/tracing/hprof.rs +++ b/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, + fields: String, } impl Data { fn new(attrs: &Attributes<'_>) -> Self { - let mut span = Self { start: Instant::now(), children: Vec::new() }; - attrs.record(&mut span); - span + let mut data = Self { start: Instant::now(), children: Vec::new(), fields: String::new() }; + + 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 { - fn record_debug(&mut self, _field: &Field, _value: &dyn fmt::Debug) {} +pub struct DataVisitor<'a> { + 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 Layer for SpanTree @@ -151,6 +168,7 @@ where #[derive(Default)] struct Node { name: &'static str, + fields: String, count: u32, duration: Duration, children: Vec, @@ -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 count = if self.count > 1 { self.count.to_string() } else { String::new() }; - eprintln!( - "{:width$} {:<9} {:<6} {}", - "", - duration, - count, - self.name, - width = level * 2 - ); + let duration = ms(self.duration); + let current_indent = level * 2; + + let mut out = String::new(); + let _ = write!(out, "{:current_indent$} {duration} {:<6}", "", self.name); + + if !self.fields.is_empty() { + let _ = write!(out, " @ {}", self.fields); + } + + 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") + } +}