From 8f8517c2168f82908d72a406ad4488c80cb25568 Mon Sep 17 00:00:00 2001 From: l3ops Date: Fri, 18 Mar 2022 12:10:09 +0100 Subject: [PATCH] feat(rome_cli): add tracing metrics collection and printing (#2234) --- Cargo.lock | 23 ++ crates/rome_cli/Cargo.toml | 5 + crates/rome_cli/src/commands/format.rs | 7 +- crates/rome_cli/src/lib.rs | 13 +- crates/rome_cli/src/metrics.rs | 384 +++++++++++++++++++++++++ crates/rome_formatter/Cargo.toml | 1 + crates/rome_formatter/src/formatter.rs | 1 + crates/rome_formatter/src/lib.rs | 1 + crates/rome_formatter/src/printer.rs | 1 + crates/rslint_parser/Cargo.toml | 1 + crates/rslint_parser/src/parse.rs | 1 + 11 files changed, 433 insertions(+), 5 deletions(-) create mode 100644 crates/rome_cli/src/metrics.rs diff --git a/Cargo.lock b/Cargo.lock index 03d154045cd..da0d3ef6427 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -147,6 +147,12 @@ version = "1.7.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "439989e6b8c38d1b6570a384ef1e49c8848128f5a97f3914baef02920842712f" +[[package]] +name = "byteorder" +version = "1.4.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "14c189c53d098945499cdfa7ecc63567cf3886b3332b312a5b4585d8d3a6a610" + [[package]] name = "bytes" version = "1.1.0" @@ -624,6 +630,16 @@ version = "0.11.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ab5ef0d4909ef3724cc8cce6ccc8572c5c817592e9285f5464f8e86f8bd3726e" +[[package]] +name = "hdrhistogram" +version = "7.5.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "31672b7011be2c4f7456c4ddbcb40e7e9a4a9fad8efe49a6ebaf5f307d0109c0" +dependencies = [ + "byteorder", + "num-traits", +] + [[package]] name = "heck" version = "0.3.3" @@ -1316,7 +1332,10 @@ dependencies = [ name = "rome_cli" version = "0.0.0" dependencies = [ + "hdrhistogram", + "lazy_static", "memmap2", + "parking_lot 0.12.0", "pico-args", "rayon", "rome_core", @@ -1324,6 +1343,8 @@ dependencies = [ "rome_path", "rslint_errors", "rslint_parser", + "tracing", + "tracing-subscriber", ] [[package]] @@ -1353,6 +1374,7 @@ dependencies = [ "similar-asserts", "tests_macros", "thiserror", + "tracing", ] [[package]] @@ -1456,6 +1478,7 @@ dependencies = [ "rslint_lexer", "smallvec", "tests_macros", + "tracing", ] [[package]] diff --git a/crates/rome_cli/Cargo.toml b/crates/rome_cli/Cargo.toml index 61baa5fc5d6..e6316add29a 100644 --- a/crates/rome_cli/Cargo.toml +++ b/crates/rome_cli/Cargo.toml @@ -14,3 +14,8 @@ rome_path = { path = "../rome_path", version = "0.0.0" } pico-args = "0.4.2" rayon = "1.5.1" memmap2 = "0.3.0" +tracing = "0.1.31" +tracing-subscriber = "0.3.6" +parking_lot = "0.12.0" +lazy_static = "1.4.0" +hdrhistogram = { version = "7.5.0", default-features = false } diff --git a/crates/rome_cli/src/commands/format.rs b/crates/rome_cli/src/commands/format.rs index 1b53725f950..4d70e62d11c 100644 --- a/crates/rome_cli/src/commands/format.rs +++ b/crates/rome_cli/src/commands/format.rs @@ -365,6 +365,7 @@ struct FormatFileParams<'a> { /// This function performs the actual formatting: it reads the file from disk /// (or map it into memory it), parse and format it; then, it either writes the /// result back or compares it with the original content and emit a diagnostic +#[tracing::instrument(level = "trace", skip_all, fields(path = ?params.path))] fn format_file(params: FormatFileParams) -> Result, Diagnostic> { if !params.app.can_format(&RomePath::new(params.path)) { return Err(Diagnostic::error( @@ -376,10 +377,8 @@ fn format_file(params: FormatFileParams) -> Result, Diagnostic> let source_type = SourceType::try_from(params.path).unwrap_or_else(|_| SourceType::js_module()); - let mut file = fs::File::options() - .read(true) - .write(true) - .open(params.path) + let mut file = tracing::debug_span!("open") + .in_scope(|| fs::File::options().read(true).write(true).open(params.path)) .with_file_id(params.file_id)?; let input = FileBuffer::read(&mut file, !params.is_check).with_file_id(params.file_id)?; diff --git a/crates/rome_cli/src/lib.rs b/crates/rome_cli/src/lib.rs index aa8bfc393bc..8e16171572a 100644 --- a/crates/rome_cli/src/lib.rs +++ b/crates/rome_cli/src/lib.rs @@ -2,6 +2,7 @@ use pico_args::Arguments; use rome_core::App; mod commands; +mod metrics; /// Global context for an execution of the CLI pub struct CliSession { @@ -22,13 +23,23 @@ impl CliSession { /// Main function to run Rome CLI pub fn run_cli(mut session: CliSession) { + let has_metrics = session.args.contains("--show-metrics"); + if has_metrics { + crate::metrics::init_metrics(); + } + let has_help = session.args.contains("--help"); let subcommand = session.args.subcommand(); match subcommand.as_ref().map(Option::as_deref) { Ok(Some(cmd)) if has_help => crate::commands::help::help(Some(cmd)), - Ok(Some("format")) => crate::commands::format::format(session), + Ok(Some("format")) => { + crate::commands::format::format(session); + if has_metrics { + crate::metrics::print_metrics(); + } + } Ok(None | Some("help")) => crate::commands::help::help(None), diff --git a/crates/rome_cli/src/metrics.rs b/crates/rome_cli/src/metrics.rs new file mode 100644 index 00000000000..ed88da9a53e --- /dev/null +++ b/crates/rome_cli/src/metrics.rs @@ -0,0 +1,384 @@ +use std::{ + borrow::Cow, + collections::HashMap, + hash::Hash, + ptr, + time::{Duration, Instant}, +}; + +use hdrhistogram::Histogram; +use parking_lot::{Mutex, RwLock}; +use tracing::{span, subscriber::Interest, Level, Metadata, Subscriber}; +use tracing_subscriber::{ + layer::Context, + prelude::*, + registry::{LookupSpan, SpanRef}, + Layer, +}; + +/// Implementation of a tracing [Layer] that collects timing information for spans into [Histogram]s +struct MetricsLayer; + +lazy_static::lazy_static! { + /// Global storage for metrics data + static ref METRICS: RwLock>> = RwLock::default(); +} + +/// Static pointer to the metadata of a callsite, used as a unique identifier +/// for collecting spans created from there in the global metrics map +struct CallsiteKey(&'static Metadata<'static>); + +impl PartialEq for CallsiteKey { + fn eq(&self, other: &Self) -> bool { + ptr::eq(self.0, other.0) + } +} + +impl Eq for CallsiteKey {} + +impl Hash for CallsiteKey { + fn hash(&self, state: &mut H) { + ptr::hash(self.0, state); + } +} + +/// Single entry in the global callsite storage, containing handles to the +/// histograms associated with this callsite +enum CallsiteEntry { + /// Spans with the debug level only count their total duration + Debug { total: Histogram }, + /// Spans with the trace level count their total duration as well as + /// individual busy and idle times + Trace { + total: Histogram, + busy: Histogram, + idle: Histogram, + }, +} + +impl CallsiteEntry { + fn from_level(level: &Level) -> Self { + /// Number of significant figures retained by the histogram + const SIGNIFICANT_FIGURES: u8 = 3; + + match level { + &Level::TRACE => Self::Trace { + // SAFETY: Histogram::new only returns an error if the value of + // SIGNIFICANT_FIGURES is invalid, 3 is statically known to work + total: Histogram::new(SIGNIFICANT_FIGURES).unwrap(), + busy: Histogram::new(SIGNIFICANT_FIGURES).unwrap(), + idle: Histogram::new(SIGNIFICANT_FIGURES).unwrap(), + }, + _ => Self::Debug { + total: Histogram::new(SIGNIFICANT_FIGURES).unwrap(), + }, + } + } + + fn into_histograms(self, name: &str) -> Vec<(Cow, Histogram)> { + match self { + CallsiteEntry::Debug { total } => vec![(Cow::Borrowed(name), total)], + CallsiteEntry::Trace { total, busy, idle } => vec![ + (Cow::Borrowed(name), total), + (Cow::Owned(format!("{name}.busy")), busy), + (Cow::Owned(format!("{name}.idle")), idle), + ], + } + } +} + +/// Extension data attached to tracing spans to keep track of their idle and busy time +/// +/// Most of the associated code is based on the similar logic found in `tracing-subscriber` +/// for printing span timings to the console: +/// https://github.com/tokio-rs/tracing/blob/6f23c128fced6409008838a3223d76d7332d79e9/tracing-subscriber/src/fmt/fmt_subscriber.rs#L973 +struct Timings { + idle: u64, + busy: u64, + last: Instant, +} + +impl Timings { + fn new() -> Self { + Self { + idle: 0, + busy: 0, + last: Instant::now(), + } + } + + /// Count the time between the last update and now as idle + fn enter(&mut self, now: Instant) { + self.idle += (now - self.last).as_nanos() as u64; + self.last = now; + } + + /// Count the time between the last update and now as busy + fn exit(&mut self, now: Instant) { + self.busy += (now - self.last).as_nanos() as u64; + self.last = now; + } + + /// Exit the timing for this span, and record it into a callsite entry + fn record(mut self, now: Instant, entry: &mut CallsiteEntry) { + self.exit(now); + + match entry { + CallsiteEntry::Debug { total } => { + total.record(self.busy + self.idle).unwrap(); + } + CallsiteEntry::Trace { total, busy, idle } => { + busy.record(self.busy).unwrap(); + idle.record(self.idle).unwrap(); + total.record(self.busy + self.idle).unwrap(); + } + } + } +} + +fn read_span<'ctx, S>(ctx: &'ctx Context<'_, S>, id: &span::Id) -> SpanRef<'ctx, S> +where + S: Subscriber + for<'a> LookupSpan<'a>, +{ + ctx.span(id) + .expect("Span not found, it should have been stored in the registry") +} + +impl Layer for MetricsLayer +where + S: Subscriber + for<'a> LookupSpan<'a>, +{ + /// Only express interest in span callsites, disabling collection of events, + /// and create new histogram for the spans created by this callsite + fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { + if !metadata.is_span() { + return Interest::never(); + } + + let entry = CallsiteEntry::from_level(metadata.level()); + + METRICS + .write() + .insert(CallsiteKey(metadata), Mutex::new(entry)); + + Interest::always() + } + + /// When a new span is created, attach the timing data extension to it + fn on_new_span(&self, _attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, S>) { + let span = read_span(&ctx, id); + let mut extensions = span.extensions_mut(); + + if extensions.get_mut::().is_none() { + extensions.insert(Timings::new()); + } + } + + /// When a span is entered, start counting idle time for the parent span if + /// it exists and busy time for the entered span itself + fn on_enter(&self, id: &span::Id, ctx: Context<'_, S>) { + let span = read_span(&ctx, id); + + let now = Instant::now(); + if let Some(parent) = span.parent() { + let mut extensions = parent.extensions_mut(); + if let Some(timings) = extensions.get_mut::() { + // The parent span was busy until now + timings.exit(now); + } + } + + let mut extensions = span.extensions_mut(); + if let Some(timings) = extensions.get_mut::() { + // The child span was idle until now + timings.enter(now); + } + } + + /// When a span is exited, stop it from counting busy time and start + /// counting the parent as busy instead + fn on_exit(&self, id: &span::Id, ctx: Context<'_, S>) { + let span = read_span(&ctx, id); + + let now = Instant::now(); + let mut extensions = span.extensions_mut(); + if let Some(timings) = extensions.get_mut::() { + // Child span was busy until now + timings.exit(now); + } + + // Re-enter parent + if let Some(parent) = span.parent() { + let mut extensions = parent.extensions_mut(); + if let Some(timings) = extensions.get_mut::() { + // Parent span was idle until now + timings.enter(now); + } + } + } + + /// When a span is closed, extract its timing information and write it to + /// the associated histograms + fn on_close(&self, id: span::Id, ctx: Context<'_, S>) { + let span = read_span(&ctx, &id); + let mut extensions = span.extensions_mut(); + if let Some(timing) = extensions.remove::() { + let now = Instant::now(); + + // Acquire a read lock on the metrics storage, access the metrics entry + // associated with this call site and acquire a write lock on it + let metrics = METRICS.read(); + let entry = metrics + .get(&CallsiteKey(span.metadata())) + .expect("callsite not found, it should have been registered in register_callsite"); + + let mut entry = entry.lock(); + timing.record(now, &mut entry); + } + } +} + +/// Initializes metrics recording +pub fn init_metrics() { + // Create and injects the metrics recording layer with the tracing library + tracing_subscriber::registry().with(MetricsLayer).init(); +} + +/// Flush and print the recorded metrics to the console +pub fn print_metrics() { + let mut histograms: Vec<_> = METRICS + .write() + .drain() + .flat_map(|(key, entry)| entry.into_inner().into_histograms(key.0.name())) + .collect(); + + histograms.sort_unstable_by(|(a, _), (b, _)| a.cmp(b)); + + for (key, histogram) in histograms { + // Print the header line for the histogram with its name, mean sample + // duration and standard deviation + println!( + "{}: mean = {:.1?}, stdev = {:.1?}", + key, + Duration::from_nanos(histogram.mean().round() as u64), + Duration::from_nanos(histogram.stdev().round() as u64), + ); + + // For each quantile bucket in the histogram print out the associated + // duration, a bar corresponding to the percentage of the total number + // of samples falling within this bucket and the percentile + // corresponding to this bucket + let total = histogram.len() as f64; + for v in histogram.iter_quantiles(1) { + let duration = Duration::from_nanos(v.value_iterated_to()); + + let count = v.count_since_last_iteration() as f64; + let bar_length = (count * 40.0 / total).ceil() as usize; + + println!( + "{: >7.1?} | {:40} | {:5.1}%", + duration, + "*".repeat(bar_length), + v.quantile_iterated_to() * 100.0, + ); + } + + // Print an empty line after each histogram + println!(); + } +} + +#[cfg(test)] +mod tests { + use std::{thread, time::Duration}; + + use tracing::Level; + use tracing_subscriber::prelude::*; + + use super::{CallsiteEntry, CallsiteKey, MetricsLayer, Timings, METRICS}; + + #[test] + fn test_timing() { + let mut entry = CallsiteEntry::from_level(&Level::TRACE); + + for i in 1..=5 { + let mut timing = Timings::new(); + + let start = timing.last; + timing.enter(start + Duration::from_nanos(i)); + + timing.record(start + Duration::from_nanos(i * 2), &mut entry); + } + + let histograms = entry.into_histograms("test"); + for (name, histogram) in histograms { + let scale = match name.as_ref() { + "test" => 2.0, + "test.idle" | "test.busy" => 1.0, + _ => unreachable!(), + }; + + let sample_count = 5; + assert_eq!(histogram.len(), sample_count); + + let mean = 3.0 * scale; + assert_eq!(histogram.mean(), mean); + + let sum = (1..=5).fold(0.0, |sum, i| { + let sample = i as f64 * scale; + sum + (sample - mean).powi(2) + }); + + let stddev = (sum / sample_count as f64).sqrt(); + assert_eq!(histogram.stdev(), stddev); + + let s = scale as u64 - 1; + let expected_buckets = [ + (0, s, 0.0), + (1, 2 * s + 1, 0.2), + (1, 3 * s + 2, 0.4), + (1, 4 * s + 3, 0.6), + (1, 5 * s + 4, 0.8), + (1, 6 * s + 5, 1.0), + ]; + + for (bucket, expected) in histogram.iter_linear(scale as u64).zip(&expected_buckets) { + let (count, value, quantile) = *expected; + + assert_eq!(bucket.count_since_last_iteration(), count); + assert_eq!(bucket.value_iterated_to(), value); + assert_eq!(bucket.quantile_iterated_to(), quantile); + } + } + } + + #[test] + fn test_layer() { + let _guard = tracing_subscriber::registry() + .with(MetricsLayer) + .set_default(); + + let key = { + let span = tracing::trace_span!("test_layer"); + span.in_scope(|| { + thread::sleep(Duration::from_millis(1)); + }); + + span.metadata().expect("span is disabled") + }; + + let entry = { + let mut metrics = METRICS.write(); + metrics.remove(&CallsiteKey(key)) + }; + + let entry = entry.expect("callsite does not exist in metrics storage"); + + let entry = entry.into_inner(); + let histograms = entry.into_histograms(key.name()); + + for (_, histogram) in histograms { + assert_eq!(histogram.len(), 1); + } + } +} diff --git a/crates/rome_formatter/Cargo.toml b/crates/rome_formatter/Cargo.toml index 9c3bce84a4d..86462f13c82 100644 --- a/crates/rome_formatter/Cargo.toml +++ b/crates/rome_formatter/Cargo.toml @@ -13,6 +13,7 @@ rome_path = { version = "0.0.0", path = "../rome_path" } rome_core = { version = "0.0.0", path = "../rome_core" } cfg-if = "1.0.0" thiserror = "1.0.30" +tracing = "0.1.31" [dev-dependencies] serde = { version = "1", features = ["derive"] } diff --git a/crates/rome_formatter/src/formatter.rs b/crates/rome_formatter/src/formatter.rs index 8b2cc81ea13..6bf9e470a43 100644 --- a/crates/rome_formatter/src/formatter.rs +++ b/crates/rome_formatter/src/formatter.rs @@ -68,6 +68,7 @@ impl Formatter { } /// Formats a CST + #[tracing::instrument(level = "debug", skip_all)] pub(crate) fn format_root(self, root: &SyntaxNode) -> FormatResult { let element = self.format_syntax_node(root)?; diff --git a/crates/rome_formatter/src/lib.rs b/crates/rome_formatter/src/lib.rs index 0f65683e976..edad3640de3 100644 --- a/crates/rome_formatter/src/lib.rs +++ b/crates/rome_formatter/src/lib.rs @@ -261,6 +261,7 @@ impl Formatted { /// Formats a JavaScript (and its super languages) file based on its features. /// /// It returns a [Formatted] result, which the user can use to override a file. +#[tracing::instrument(level = "trace", skip_all)] pub fn format(options: FormatOptions, syntax: &SyntaxNode) -> FormatResult { let element = Formatter::new(options).format_root(syntax)?; Ok(Printer::new(options).print(&element)) diff --git a/crates/rome_formatter/src/printer.rs b/crates/rome_formatter/src/printer.rs index becd15d4f33..81b5a1a4f91 100644 --- a/crates/rome_formatter/src/printer.rs +++ b/crates/rome_formatter/src/printer.rs @@ -101,6 +101,7 @@ impl<'a> Printer<'a> { } /// Prints the passed in element as well as all its content + #[tracing::instrument(level = "debug", skip_all)] pub fn print(self, element: &'a FormatElement) -> Formatted { self.print_with_indent(element, 0) } diff --git a/crates/rslint_parser/Cargo.toml b/crates/rslint_parser/Cargo.toml index c9b264cb6f2..fab1a963702 100644 --- a/crates/rslint_parser/Cargo.toml +++ b/crates/rslint_parser/Cargo.toml @@ -17,6 +17,7 @@ bitflags = "1.3.2" indexmap = "1.8.0" cfg-if = "1.0.0" smallvec = { version = "1.8.0", features = ["union", "const_new"] } +tracing = "0.1.31" [dev-dependencies] tests_macros = { path = "../tests_macros" } diff --git a/crates/rslint_parser/src/parse.rs b/crates/rslint_parser/src/parse.rs index 36fadcfa386..1232a186ecf 100644 --- a/crates/rslint_parser/src/parse.rs +++ b/crates/rslint_parser/src/parse.rs @@ -168,6 +168,7 @@ pub fn parse_module(text: &str, file_id: usize) -> Parse { } /// Parses the provided string as a EcmaScript program using the provided syntax features. +#[tracing::instrument(level = "debug", skip_all, fields(file_id = file_id))] pub fn parse(text: &str, file_id: usize, source_type: SourceType) -> Parse { let (events, errors, tokens) = parse_common(text, file_id, source_type); let mut tree_sink = LosslessTreeSink::new(text, &tokens);