feat(rome_cli): add tracing metrics collection and printing
MODIFY
Cargo.lock
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]]

MODIFY
crates/rome_cli/Cargo.toml
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 }

MODIFY
crates/rome_cli/src/commands/format.rs
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<Vec<Diagnostic>, Diagnostic> {
if !params.app.can_format(&RomePath::new(params.path)) {
return Err(Diagnostic::error(
@@ -376,10 +377,8 @@ fn format_file(params: FormatFileParams) -> Result<Vec<Diagnostic>, 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)?;

MODIFY
crates/rome_cli/src/lib.rs
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),

ADD
crates/rome_cli/src/metrics.rs
+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<HashMap<CallsiteKey, Mutex<CallsiteEntry>>> = 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<H: std::hash::Hasher>(&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<u64> },
+ /// Spans with the trace level count their total duration as well as
+ /// individual busy and idle times
+ Trace {
+ total: Histogram<u64>,
+ busy: Histogram<u64>,
+ idle: Histogram<u64>,
+ },
+}
+
+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<str>, Histogram<u64>)> {
+ 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<S> Layer<S> 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::<Timings>().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::<Timings>() {
+ // The parent span was busy until now
+ timings.exit(now);
+ }
+ }
+
+ let mut extensions = span.extensions_mut();
+ if let Some(timings) = extensions.get_mut::<Timings>() {
+ // 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::<Timings>() {
+ // 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::<Timings>() {
+ // 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::<Timings>() {
+ 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);
+ }
+ }
+}

MODIFY
crates/rome_formatter/Cargo.toml
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"] }

MODIFY
crates/rome_formatter/src/formatter.rs
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<FormatElement> {
let element = self.format_syntax_node(root)?;

MODIFY
crates/rome_formatter/src/lib.rs
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<Formatted> {
let element = Formatter::new(options).format_root(syntax)?;
Ok(Printer::new(options).print(&element))

MODIFY
crates/rome_formatter/src/printer.rs
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)
}

MODIFY
crates/rslint_parser/Cargo.toml
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" }

MODIFY
crates/rslint_parser/src/parse.rs
crates/rslint_parser/src/parse.rs
@@ -168,6 +168,7 @@ pub fn parse_module(text: &str, file_id: usize) -> Parse<JsModule> {
}
/// 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<JsAnyRoot> {
let (events, errors, tokens) = parse_common(text, file_id, source_type);
let mut tree_sink = LosslessTreeSink::new(text, &tokens);

feat(rome_cli): add tracing metrics collection and printing (#2234)