diff --git a/.gitignore b/.gitignore index 0b8a86d613b8..43db8709c514 100644 --- a/.gitignore +++ b/.gitignore @@ -237,4 +237,5 @@ diff_output *.trace # rspack trace file -trace.json \ No newline at end of file +trace.json +*.pftrace \ No newline at end of file diff --git a/Cargo.lock b/Cargo.lock index a96dc09bd925..837e303d1f26 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2631,6 +2631,17 @@ dependencies = [ "autocfg", ] +[[package]] +name = "micromegas-perfetto" +version = "0.9.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "cf00fa025e680c9ac4fef886b4448d3cd6eaa6afa09946ff8fcb67f15c73f73c" +dependencies = [ + "anyhow", + "prost", + "xxhash-rust", +] + [[package]] name = "miette" version = "7.5.0" @@ -3490,6 +3501,29 @@ dependencies = [ "unicode-ident", ] +[[package]] +name = "prost" +version = "0.13.5" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "2796faa41db3ec313a31f7624d9286acf277b52de526150b7e69f3debf891ee5" +dependencies = [ + "bytes", + "prost-derive", +] + +[[package]] +name = "prost-derive" +version = "0.13.5" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8a56d757972c98b346a9b766e3f02746cde6dd1cd1d1d563472929fdd74bec4d" +dependencies = [ + "anyhow", + "itertools 0.14.0", + "proc-macro2", + "quote", + "syn 2.0.95", +] + [[package]] name = "psm" version = "0.1.24" @@ -5468,17 +5502,18 @@ dependencies = [ name = "rspack_tracing" version = "0.2.0" dependencies = [ - "rspack_tracing_chrome", - "tracing", + "rspack_tracing_perfetto", "tracing-subscriber", ] [[package]] -name = "rspack_tracing_chrome" +name = "rspack_tracing_perfetto" version = "0.2.0" dependencies = [ - "serde_json", - "tracing-core", + "bytes", + "micromegas-perfetto", + "prost", + "tracing", "tracing-subscriber", ] @@ -7840,6 +7875,16 @@ dependencies = [ "tracing-core", ] +[[package]] +name = "tracing-serde" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "704b1aeb7be0d0a84fc9828cae51dab5970fee5088f83d1dd7ee6f6246fc6ff1" +dependencies = [ + "serde", + "tracing-core", +] + [[package]] name = "tracing-subscriber" version = "0.3.19" @@ -7850,12 +7895,15 @@ dependencies = [ "nu-ansi-term", "once_cell", "regex", + "serde", + "serde_json", "sharded-slab", "smallvec", "thread_local", "tracing", "tracing-core", "tracing-log", + "tracing-serde", ] [[package]] diff --git a/Cargo.toml b/Cargo.toml index 90d7aebd64e3..ee8527c48e57 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -197,7 +197,7 @@ rspack_storage = { version = "0.2.0", path = "crates/rsp rspack_swc_plugin_import = { version = "0.2.0", path = "crates/swc_plugin_import" } rspack_testing = { version = "0.2.0", path = "crates/rspack_testing" } rspack_tracing = { version = "0.2.0", path = "crates/rspack_tracing" } -rspack_tracing_chrome = { version = "0.2.0", path = "crates/rspack_tracing_chrome" } +rspack_tracing_perfetto = { version = "0.2.0", path = "crates/rspack_tracing_perfetto" } rspack_util = { version = "0.2.0", path = "crates/rspack_util" } [workspace.metadata.release] diff --git a/crates/node_binding/binding.d.ts b/crates/node_binding/binding.d.ts index 54ad8008e021..d0af6602a1cb 100644 --- a/crates/node_binding/binding.d.ts +++ b/crates/node_binding/binding.d.ts @@ -2557,6 +2557,17 @@ export interface RawToOptions { absoluteFilename?: string } +export interface RawTraceEvent { + name: string + trackName?: string + processName?: string + args?: Record + uuid: number + ts: bigint + ph: string + categories?: Array +} + export interface RawTrustedTypes { policyName?: string onPolicyCreationFailure?: string @@ -2574,7 +2585,7 @@ export interface RealDependencyLocation { * Author Donny/강동윤 * Copyright (c) */ -export declare function registerGlobalTrace(filter: string, layer: "chrome" | "logger" , output: string): void +export declare function registerGlobalTrace(filter: string, layer: "logger" | "perfetto" , output: string): void export declare enum RegisterJsTapKind { CompilerThisCompilation = 0, @@ -2719,6 +2730,8 @@ export interface SourcePosition { */ export declare function startAsyncRuntime(): void +export declare function syncTraceEvent(events: Array): void + export interface SyntheticDependencyLocation { name: string } diff --git a/crates/node_binding/src/lib.rs b/crates/node_binding/src/lib.rs index b1e4ed42c835..8b7538d7be94 100644 --- a/crates/node_binding/src/lib.rs +++ b/crates/node_binding/src/lib.rs @@ -17,7 +17,10 @@ use rspack_core::{ use rspack_error::Diagnostic; use rspack_fs::IntermediateFileSystem; -use crate::fs_node::{NodeFileSystem, ThreadsafeNodeFS}; +use crate::{ + fs_node::{NodeFileSystem, ThreadsafeNodeFS}, + trace_event::RawTraceEvent, +}; mod allocator; mod asset; @@ -63,6 +66,7 @@ mod runtime; mod source; mod stats; mod swc; +mod trace_event; mod utils; pub use asset::*; @@ -100,7 +104,7 @@ use resolver_factory::*; pub use resource_data::*; pub use rsdoctor::*; use rspack_macros::rspack_version; -use rspack_tracing::{ChromeTracer, StdoutTracer, Tracer}; +use rspack_tracing::{PerfettoTracer, StdoutTracer, TraceEvent, Tracer}; pub use rstest::*; pub use runtime::*; use rustc_hash::FxHashMap; @@ -435,7 +439,6 @@ fn print_error_diagnostic(e: rspack_error::Error, colored: bool) -> String { thread_local! { static GLOBAL_TRACE_STATE: RefCell = const { RefCell::new(TraceState::Off) }; } - /** * Some code is modified based on * https://github.com/swc-project/swc/blob/d1d0607158ab40463d1b123fed52cc526eba8385/bindings/binding_core_node/src/util.rs#L29-L58 @@ -446,17 +449,17 @@ thread_local! { #[napi] pub fn register_global_trace( filter: String, - #[napi(ts_arg_type = "\"chrome\" | \"logger\" ")] layer: String, + #[napi(ts_arg_type = " \"logger\" | \"perfetto\" ")] layer: String, output: String, ) -> anyhow::Result<()> { GLOBAL_TRACE_STATE.with(|state| { let mut state = state.borrow_mut(); if let TraceState::Off = *state { let mut tracer: Box = match layer.as_str() { - "chrome" => Box::new(ChromeTracer::default()), "logger" => Box::new(StdoutTracer), + "perfetto"=> Box::new(PerfettoTracer::default()), _ => anyhow::bail!( - "Unexpected layer: {}, supported layers: 'chrome', 'logger', 'console' ", + "Unexpected layer: {}, supported layers:'logger', 'perfetto' ", layer ), }; @@ -490,6 +493,33 @@ pub fn cleanup_global_trace() { *state = TraceState::Off; }); } +// sync Node.js event to Rust side +#[napi] +pub fn sync_trace_event(events: Vec) { + use std::borrow::BorrowMut; + GLOBAL_TRACE_STATE.with(|state| { + let mut state = state.borrow_mut(); + if let TraceState::On(tracer) = &mut **state.borrow_mut() { + tracer.sync_trace( + events + .into_iter() + .map(|event| TraceEvent { + name: event.name, + track_name: event.track_name, + process_name: event.process_name, + args: event + .args + .map(|args| args.into_iter().map(|(k, v)| (k, v.to_string())).collect()), + uuid: event.uuid, + ts: event.ts.get_u64().1, + ph: event.ph, + categories: event.categories, + }) + .collect(), + ); + } + }); +} fn node_init(mut _exports: Object, env: Env) -> Result<()> { rspack_core::set_thread_local_allocator(Box::new(allocator::NapiAllocatorImpl::new(env))); diff --git a/crates/node_binding/src/trace_event.rs b/crates/node_binding/src/trace_event.rs new file mode 100644 index 000000000000..cec810b6d4bf --- /dev/null +++ b/crates/node_binding/src/trace_event.rs @@ -0,0 +1,25 @@ +use std::collections::HashMap; + +use napi::bindgen_prelude::BigInt; +use napi_derive::napi; + +#[napi(object)] +#[derive(Debug)] +pub struct RawTraceEvent { + // event name + pub name: String, + // separate track name + pub track_name: Option, + // separate group sliced name + pub process_name: Option, + // extra debug arguments + pub args: Option>, + // track_uuid + pub uuid: u32, + // timestamp in microseconds + pub ts: BigInt, + // chrome trace event ph + pub ph: String, + // category + pub categories: Option>, +} diff --git a/crates/rspack_core/src/normal_module.rs b/crates/rspack_core/src/normal_module.rs index 2c53ebcadd92..481de426d350 100644 --- a/crates/rspack_core/src/normal_module.rs +++ b/crates/rspack_core/src/normal_module.rs @@ -281,7 +281,7 @@ impl NormalModule { #[tracing::instrument( "NormalModule:build_hash", skip_all,fields( - id2 = self.resource_data.resource.as_str() + resource = self.resource_data.resource.as_str() ) )] fn init_build_hash( @@ -367,9 +367,10 @@ impl Module for NormalModule { } #[tracing::instrument("NormalModule:build", skip_all, fields( + perfetto.track_name = format!("Module Build"), + perfetto.process_name = format!("Rspack Build Detail"), module.resource = self.resource_resolved_data().resource.as_str(), module.identifier = self.identifier().as_str(), - id2 = self.resource_data.resource.as_str(), module.loaders = ?self.loaders.iter().map(|l| l.identifier().as_str()).collect::>()) )] async fn build( @@ -413,10 +414,7 @@ impl Module for NormalModule { }, build_context.fs.clone(), ) - .instrument(info_span!( - "NormalModule:run_loaders", - id2 = self.resource_data.resource.as_str(), - )) + .instrument(info_span!("NormalModule:run_loaders",)) .await; let (mut loader_result, ds) = match loader_result { Ok(r) => r.split_into_parts(), diff --git a/crates/rspack_loader_lightningcss/src/lib.rs b/crates/rspack_loader_lightningcss/src/lib.rs index 588c80668d94..2ec758b22a82 100644 --- a/crates/rspack_loader_lightningcss/src/lib.rs +++ b/crates/rspack_loader_lightningcss/src/lib.rs @@ -267,6 +267,11 @@ impl Identifiable for LightningCssLoader { #[cacheable_dyn] #[async_trait::async_trait] impl Loader for LightningCssLoader { + #[tracing::instrument("loader:lightningcss", skip_all, fields( + perfetto.track_name = "loader:lightningcss", + perfetto.process_name = "Loader Analysis", + resource =loader_context.resource(), + ))] async fn run(&self, loader_context: &mut LoaderContext) -> Result<()> { // for better diagnostic, as async_trait macro don't show beautiful error message self.loader_impl(loader_context).await diff --git a/crates/rspack_loader_runner/src/runner.rs b/crates/rspack_loader_runner/src/runner.rs index 9aaac31d291b..9813e9bfd1d7 100644 --- a/crates/rspack_loader_runner/src/runner.rs +++ b/crates/rspack_loader_runner/src/runner.rs @@ -28,7 +28,7 @@ impl LoaderContext { #[tracing::instrument("LoaderRunner:process_resource", skip_all, - fields(id2 = loader_context.resource_data.resource) + fields(resource= loader_context.resource_data.resource) )] async fn process_resource( loader_context: &mut LoaderContext, @@ -134,7 +134,7 @@ pub async fn run_loaders( cx.state.transition(State::ProcessResource); continue; } - let span = info_span!("run_loader:pitch:yield_to_js", id2 = resource); + let span = info_span!("run_loader:pitch:yield_to_js", resource); if cx.start_yielding().instrument(span).await? { if cx.content.is_some() { cx.state.transition(State::Normal); @@ -150,7 +150,7 @@ pub async fn run_loaders( cx.current_loader().set_pitch_executed(); let loader = cx.current_loader().loader().clone(); - let span = info_span!("run_loader:pitch", id2 = resource); + let span = info_span!("run_loader:pitch", resource); loader.pitch(&mut cx).instrument(span).await?; if cx.content.is_some() { cx.state.transition(State::Normal); @@ -159,7 +159,7 @@ pub async fn run_loaders( } } State::ProcessResource => { - let span = info_span!("run_loader:process_resource", id2 = resource); + let span = info_span!("run_loader:process_resource", resource); process_resource(&mut cx, fs.clone()) .instrument(span) .await?; @@ -176,7 +176,7 @@ pub async fn run_loaders( cx.state.transition(State::Finished); continue; } - let span = info_span!("run_loader:yield_to_js", id2 = resource); + let span = info_span!("run_loader:yield_to_js", resource); if cx.start_yielding().instrument(span).await? { continue; } @@ -189,7 +189,7 @@ pub async fn run_loaders( cx.current_loader().set_normal_executed(); let loader = cx.current_loader().loader().clone(); - let span = info_span!("run_loader:normal", id2 = resource); + let span = info_span!("run_loader:normal", resource); loader.run(&mut cx).instrument(span).await?; if !cx.current_loader().finish_called() { // If nothing is returned from this loader, diff --git a/crates/rspack_loader_swc/src/lib.rs b/crates/rspack_loader_swc/src/lib.rs index fae2f7428561..ba6989d2a74d 100644 --- a/crates/rspack_loader_swc/src/lib.rs +++ b/crates/rspack_loader_swc/src/lib.rs @@ -116,7 +116,9 @@ pub const SWC_LOADER_IDENTIFIER: &str = "builtin:swc-loader"; #[async_trait::async_trait] impl Loader for SwcLoader { #[tracing::instrument("loader:builtin-swc", skip_all, fields( - id2 =loader_context.resource(), + perfetto.track_name = "loader:builtin-swc", + perfetto.process_name = "Loader Analysis", + resource =loader_context.resource(), ))] async fn run(&self, loader_context: &mut LoaderContext) -> Result<()> { #[allow(unused_mut)] diff --git a/crates/rspack_macros/src/plugin.rs b/crates/rspack_macros/src/plugin.rs index 558ace6fe31d..10a96dac9493 100644 --- a/crates/rspack_macros/src/plugin.rs +++ b/crates/rspack_macros/src/plugin.rs @@ -182,12 +182,16 @@ pub fn expand_fn(args: HookArgs, input: syn::ItemFn) -> proc_macro::TokenStream let inner_ident = plugin_inner_ident(&name); let tracing_name = syn::LitStr::new(&format!("{}:{}", &name, &fn_ident), name.span()); + let plugin_name = syn::LitStr::new(&format!("{}", &name), name.span()); let tracing_annotation = tracing .map(|bool_lit| bool_lit.value) .unwrap_or(true) .then(|| { quote! { - #[::rspack_hook::__macro_helper::tracing::instrument(name = #tracing_name, skip_all)] + #[::rspack_hook::__macro_helper::tracing::instrument(name = #tracing_name, skip_all,fields( + perfetto.track_name = #plugin_name, + perfetto.process_name = "Plugin Analysis" + ))] } }); diff --git a/crates/rspack_plugin_javascript/src/parser_and_generator/mod.rs b/crates/rspack_plugin_javascript/src/parser_and_generator/mod.rs index 6314a9c35280..30110ae69b4f 100644 --- a/crates/rspack_plugin_javascript/src/parser_and_generator/mod.rs +++ b/crates/rspack_plugin_javascript/src/parser_and_generator/mod.rs @@ -119,8 +119,7 @@ impl ParserAndGenerator for JavaScriptParserAndGenerator { } #[tracing::instrument("JavaScriptParser:parse", skip_all,fields( - resource = parse_context.resource_data.resource.as_str(), - id2 = parse_context.resource_data.resource.as_str(), + resource = parse_context.resource_data.resource.as_str() ))] async fn parse<'a>( &mut self, diff --git a/crates/rspack_tracing/Cargo.toml b/crates/rspack_tracing/Cargo.toml index 44c910a56533..b3bfb17ded63 100644 --- a/crates/rspack_tracing/Cargo.toml +++ b/crates/rspack_tracing/Cargo.toml @@ -9,6 +9,5 @@ version = "0.2.0" # See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html [features] [dependencies] -rspack_tracing_chrome = { workspace = true } -tracing = { workspace = true } -tracing-subscriber = { workspace = true, features = ["env-filter"] } +rspack_tracing_perfetto = { workspace = true } +tracing-subscriber = { workspace = true, features = ["env-filter", "json"] } diff --git a/crates/rspack_tracing/src/chrome.rs b/crates/rspack_tracing/src/chrome.rs deleted file mode 100644 index 317bc4bc566e..000000000000 --- a/crates/rspack_tracing/src/chrome.rs +++ /dev/null @@ -1,47 +0,0 @@ -use rspack_tracing_chrome::{ChromeLayerBuilder, FlushGuard, TraceStyle}; -use tracing_subscriber::layer::{Filter, Layer}; - -use crate::{ - tracer::{Layered, Tracer}, - TraceWriter, -}; - -#[derive(Default)] -pub struct ChromeTracer { - guard: Option, -} - -impl Tracer for ChromeTracer { - fn setup(&mut self, output: &str) -> Option { - let trace_writer = TraceWriter::from(output.to_owned()); - let (chrome_layer, guard) = ChromeLayerBuilder::new() - .trace_style(TraceStyle::Async) - .include_args(true) - .category_fn(Box::new(|_| "rspack".to_string())) - .writer(move || trace_writer.writer()) - .build(); - self.guard = Some(guard); - - Some(vec![chrome_layer.with_filter(FilterEvent {}).boxed()].boxed()) - } - - fn teardown(&mut self) { - if let Some(guard) = self.guard.take() { - guard.flush(); - } - } -} - -// skip event because it's not useful for performance analysis -struct FilterEvent; - -impl Filter for FilterEvent { - fn enabled( - &self, - _meta: &tracing::Metadata<'_>, - _cx: &tracing_subscriber::layer::Context<'_, S>, - ) -> bool { - // filter out swc related tracing because it's too much noisy for info level now - true - } -} diff --git a/crates/rspack_tracing/src/lib.rs b/crates/rspack_tracing/src/lib.rs index 05e23f8d3b38..e85233b111c5 100644 --- a/crates/rspack_tracing/src/lib.rs +++ b/crates/rspack_tracing/src/lib.rs @@ -1,12 +1,12 @@ -mod chrome; +mod perfetto; mod stdout; mod tracer; use std::{fs, io, path::PathBuf}; -pub use chrome::ChromeTracer; +pub use perfetto::PerfettoTracer; pub use stdout::StdoutTracer; -pub use tracer::Tracer; +pub use tracer::{TraceEvent, Tracer}; use tracing_subscriber::fmt::writer::BoxMakeWriter; pub(crate) enum TraceWriter { Stdout, @@ -34,14 +34,4 @@ impl TraceWriter { } } } - - pub fn writer(&self) -> Box { - match self { - TraceWriter::Stdout => Box::new(io::stdout()), - TraceWriter::Stderr => Box::new(io::stderr()), - TraceWriter::File { path } => { - Box::new(fs::File::create(path).expect("Failed to create trace file")) - } - } - } } diff --git a/crates/rspack_tracing/src/perfetto.rs b/crates/rspack_tracing/src/perfetto.rs new file mode 100644 index 000000000000..85906e7c90ee --- /dev/null +++ b/crates/rspack_tracing/src/perfetto.rs @@ -0,0 +1,170 @@ +use std::{collections::HashMap, io::Write}; + +use rspack_tracing_perfetto::{ + idl, + idl::TrackDescriptor, + idl_helpers::{ + create_event, create_scope_sliced_packet, create_track_descriptor, unique_uuid, + DebugAnnotations, + }, + prost::Message, + BytesMut, PerfettoLayer, +}; +static JAVASCRIPT_ANALYSIS_TRACK: &str = "JavaScript Analysis"; +use crate::{tracer::Layered, Tracer}; +#[derive(Default)] +pub struct PerfettoTracer { + track_state: HashMap, + event_id_map: HashMap, + writer: Option, +} +// convert hashmap to perfetto debug annotations +// the values are always json string +fn to_debug_annotation(map: Option>) -> DebugAnnotations { + let mut annotations = DebugAnnotations::default(); + if let Some(map) = map { + for (key, value) in map { + let annotation = idl::DebugAnnotation { + name_field: Some(idl::debug_annotation::NameField::Name(key)), + value: Some(idl::debug_annotation::Value::LegacyJsonValue(value)), + ..Default::default() + }; + + annotations.annotations.push(annotation); + } + } + annotations +} +impl PerfettoTracer { + // write the log and the related track descriptor to the writer + fn write_log(&mut self, log: &mut idl::Trace, track_descriptor: Option) { + let mut buf = BytesMut::new(); + if let Some(task_descriptor) = track_descriptor { + let packet = idl::TracePacket { + data: Some(idl::trace_packet::Data::TrackDescriptor(task_descriptor)), + ..Default::default() + }; + + log.packet.insert(0, packet); + } + + let Ok(_) = log.encode(&mut buf) else { + return; + }; + { + let _ = self + .writer + .as_ref() + .expect("should set writer first") + .write_all(&buf); + }; + } +} +impl Tracer for PerfettoTracer { + fn setup(&mut self, output: &str) -> Option { + let trace_file = std::fs::File::create(output) + .unwrap_or_else(|e| panic!("failed to create trace file: {output} due to {e}")); + self.writer = trace_file.try_clone().ok(); + let layer = PerfettoLayer::new(trace_file).with_debug_annotations(true); + Some(Box::new(layer)) + } + + fn teardown(&mut self) {} + fn sync_trace(&mut self, events: Vec) { + for event in events { + // handle async begin event + if event.ph == "b" { + // create a new scope sliced packet if it's not created before + let (javascript_scoped_descriptor, parent_uuid) = create_scope_sliced_packet( + event + .process_name + .unwrap_or(JAVASCRIPT_ANALYSIS_TRACK.to_string()), + ); + let mut packet = idl::TracePacket::default(); + // specify the track name for track event using track_descriptor + let span_track_descriptor = + create_track_descriptor(unique_uuid(), Some(parent_uuid), event.track_name); + let final_uuid = span_track_descriptor.uuid(); + let debug_annotations = to_debug_annotation(event.args); + let mut track_event = create_event( + final_uuid, + Some(&event.name), + None, + debug_annotations, + Some(idl::track_event::Type::SliceBegin), + ); + track_event.categories = event.categories.unwrap_or_default(); + packet.data = Some(idl::trace_packet::Data::TrackEvent(track_event)); + packet.timestamp = Some(event.ts); + + packet.optional_trusted_packet_sequence_id = + Some(idl::trace_packet::OptionalTrustedPacketSequenceId::TrustedPacketSequenceId(2 as _)); + self.track_state.insert( + event.uuid, + ( + span_track_descriptor, + idl::Trace { + packet: javascript_scoped_descriptor + .into_iter() + .chain(std::iter::once(packet)) + .collect(), + }, + ), + ); + // handle async end event + } else if event.ph == "e" { + if let Some((desc, mut trace)) = self.track_state.remove(&event.uuid) { + let mut packet = idl::TracePacket::default(); + let uuid = desc.uuid(); + let debug_annotations = to_debug_annotation(event.args); + let mut track_event = create_event( + uuid, + Some(&event.name), + None, + debug_annotations, + Some(idl::track_event::Type::SliceEnd), + ); + track_event.categories = event.categories.unwrap_or_default(); + packet.data = Some(idl::trace_packet::Data::TrackEvent(track_event)); + packet.timestamp = Some(event.ts); + packet.optional_trusted_packet_sequence_id = Some( + idl::trace_packet::OptionalTrustedPacketSequenceId::TrustedPacketSequenceId(0 as _), + ); + trace.packet.push(packet); + self.write_log(&mut trace, Some(desc)); + } else { + continue; + } + } else if event.ph == "P" || event.ph == "X" { + let uuid = self + .event_id_map + .entry(event.uuid) + .or_insert_with(unique_uuid); + let event_track_descriptor = create_track_descriptor(*uuid, None, event.track_name); + let final_uuid = event_track_descriptor.uuid(); + let mut packet = idl::TracePacket::default(); + let debug_annotations = to_debug_annotation(event.args); + let mut track_event = create_event( + final_uuid, + Some(&event.name), + None, + debug_annotations, + Some(idl::track_event::Type::Instant), + ); + track_event.categories = event.categories.unwrap_or_default(); + packet.data = Some(idl::trace_packet::Data::TrackEvent(track_event)); + packet.timestamp = Some(event.ts); + + packet.optional_trusted_packet_sequence_id = + Some(idl::trace_packet::OptionalTrustedPacketSequenceId::TrustedPacketSequenceId(2 as _)); + + let mut trace = idl::Trace { + packet: vec![packet], + }; + self.write_log(&mut trace, Some(event_track_descriptor)); + } else { + // drop not supported events + } + } + } +} diff --git a/crates/rspack_tracing/src/stdout.rs b/crates/rspack_tracing/src/stdout.rs index 19c17987c825..3c9b78ea91a6 100644 --- a/crates/rspack_tracing/src/stdout.rs +++ b/crates/rspack_tracing/src/stdout.rs @@ -13,7 +13,7 @@ impl Tracer for StdoutTracer { let trace_writer = TraceWriter::from(output.to_owned()); Some( fmt::layer() - .pretty() + .json() // Use JSON format for structured logging for easier parsing and debugging .with_file(true) // To keep track of the closing point of spans .with_span_events(FmtSpan::CLOSE) diff --git a/crates/rspack_tracing/src/tracer.rs b/crates/rspack_tracing/src/tracer.rs index aac899f34eb4..1ca3e47e1e22 100644 --- a/crates/rspack_tracing/src/tracer.rs +++ b/crates/rspack_tracing/src/tracer.rs @@ -1,8 +1,32 @@ +use std::collections::HashMap; + use tracing_subscriber::{Layer, Registry}; +#[derive(Debug)] +pub struct TraceEvent { + // event name + pub name: String, + // separate track name + pub track_name: Option, + // separate process name + pub process_name: Option, + // extra debug arguments + pub args: Option>, + // track_uuid + pub uuid: u32, + // timestamp in microseconds + pub ts: u64, + // ph + pub ph: String, + // category + pub categories: Option>, +} pub type Layered = Box + Send + Sync>; pub trait Tracer { fn setup(&mut self, output: &str) -> Option; + fn sync_trace(&mut self, _events: Vec) { + // noop + } fn teardown(&mut self); } diff --git a/crates/rspack_tracing_chrome/LICENSE b/crates/rspack_tracing_chrome/LICENSE deleted file mode 100644 index 46310101ad8a..000000000000 --- a/crates/rspack_tracing_chrome/LICENSE +++ /dev/null @@ -1,22 +0,0 @@ -MIT License - -Copyright (c) 2022-present Bytedance, Inc. and its affiliates. - - -Permission is hereby granted, free of charge, to any person obtaining a copy -of this software and associated documentation files (the "Software"), to deal -in the Software without restriction, including without limitation the rights -to use, copy, modify, merge, publish, distribute, sublicense, and/or sell -copies of the Software, and to permit persons to whom the Software is -furnished to do so, subject to the following conditions: - -The above copyright notice and this permission notice shall be included in all -copies or substantial portions of the Software. - -THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR -IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, -FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE -AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER -LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, -OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE -SOFTWARE. diff --git a/crates/rspack_tracing_chrome/README.md b/crates/rspack_tracing_chrome/README.md deleted file mode 100644 index 8b8cb8407c55..000000000000 --- a/crates/rspack_tracing_chrome/README.md +++ /dev/null @@ -1,7 +0,0 @@ -# rspack_tracing_chrome - -This is a fork of [tracing-chrome](https://github.com/thoren-d/tracing-chrome) to add better support for perfetto to Rspack like: - -* support merge Rust & JS tracing -* support use `id2` to different span in same track for perfetto, related to https://github.com/thoren-d/tracing-chrome/issues/24 -* ... \ No newline at end of file diff --git a/crates/rspack_tracing_chrome/src/lib.rs b/crates/rspack_tracing_chrome/src/lib.rs deleted file mode 100644 index 9d9f90c1c6a3..000000000000 --- a/crates/rspack_tracing_chrome/src/lib.rs +++ /dev/null @@ -1,654 +0,0 @@ -#![allow(clippy::unwrap_used)] -// fork of https://github.com/thoren-d/tracing-chrome/blob/7e2625ab4aeeef2f0ef9bde9d6258dd181c04472/src/lib.rs#L3 to add better perfetto support for rspack -use std::{ - cell::{Cell, RefCell}, - io::{BufWriter, Write}, - marker::PhantomData, - path::Path, - sync::{ - atomic::{AtomicUsize, Ordering}, - mpsc, - mpsc::Sender, - Arc, Mutex, - }, - thread::JoinHandle, -}; - -use serde_json::{json, Value as JsonValue}; -use tracing_core::{field::Field, span, Event, Subscriber}; -use tracing_subscriber::{ - layer::Context, - registry::{LookupSpan, SpanRef}, - Layer, -}; - -thread_local! { - static OUT: RefCell>> = const { RefCell::new(None) }; - static TID: RefCell> = const { RefCell::new(None) }; -} - -type NameFn = Box) -> String + Send + Sync>; -type Object = serde_json::Map; - -/// A [`Layer`](tracing_subscriber::Layer) that writes a Chrome trace file. -pub struct ChromeLayer -where - S: Subscriber + for<'span> LookupSpan<'span> + Send + Sync, -{ - out: Arc>>, - start: std::time::Instant, - max_tid: AtomicUsize, - include_args: bool, - include_locations: bool, - trace_style: TraceStyle, - name_fn: Option>, - cat_fn: Option>, - _inner: PhantomData, -} - -/// A builder for [`ChromeLayer`](crate::ChromeLayer). -#[derive(Default)] -pub struct ChromeLayerBuilder -where - S: Subscriber + for<'span> LookupSpan<'span> + Send + Sync, -{ - out_writer: Option Box + Send>>, - name_fn: Option>, - cat_fn: Option>, - include_args: bool, - include_locations: bool, - trace_style: TraceStyle, - _inner: PhantomData, -} - -/// Decides how traces will be recorded. -#[derive(Default)] -pub enum TraceStyle { - /// Traces will be recorded as a group of threads. - /// In this style, spans should be entered and exited on the same thread. - #[default] - Threaded, - - /// Traces will recorded as a group of asynchronous operations. - Async, -} - -impl ChromeLayerBuilder -where - S: Subscriber + for<'span> LookupSpan<'span> + Send + Sync, -{ - pub fn new() -> Self { - ChromeLayerBuilder { - out_writer: None, - name_fn: None, - cat_fn: None, - include_args: false, - include_locations: true, - trace_style: TraceStyle::Threaded, - _inner: PhantomData, - } - } - - /// Set the file to which to output the trace. - /// - /// Defaults to `./trace-{unix epoch in micros}.json`. - /// - /// # Panics - /// - /// If `file` could not be opened/created. To handle errors, - /// open a file and pass it to [`writer`](crate::ChromeLayerBuilder::writer) instead. - pub fn file + Send + 'static>(self, file: P) -> Self { - self.writer(|| Box::new(std::fs::File::create(file).expect("Failed to create trace file."))) - } - - /// Supply an arbitrary writer to which to write trace contents. - /// - /// # Examples - /// - /// ```rust - /// # use rspack_tracing_chrome::ChromeLayerBuilder; - /// # use tracing_subscriber::prelude::*; - /// let (layer, guard) = ChromeLayerBuilder::new() - /// .writer(|| Box::new(std::io::sink())) - /// .build(); - /// # tracing_subscriber::registry().with(layer).init(); - /// ``` - pub fn writer Box + Send + 'static>(mut self, writer: W) -> Self { - self.out_writer = Some(Box::new(writer)); - self - } - - /// Include arguments in each trace entry. - /// - /// Defaults to `false`. - /// - /// Includes the arguments used when creating a span/event - /// in the "args" section of the trace entry. - pub fn include_args(mut self, include: bool) -> Self { - self.include_args = include; - self - } - - /// Include file+line with each trace entry. - /// - /// Defaults to `true`. - /// - /// This can add quite a bit of data to the output so turning - /// it off might be helpful when collecting larger traces. - pub fn include_locations(mut self, include: bool) -> Self { - self.include_locations = include; - self - } - - /// Sets the style used when recording trace events. - /// - /// See [`TraceStyle`](crate::TraceStyle) for details. - pub fn trace_style(mut self, style: TraceStyle) -> Self { - self.trace_style = style; - self - } - - /// Allows supplying a function that derives a name from - /// an Event or Span. The result is used as the "name" field - /// on trace entries. - /// - /// # Example - /// ``` - /// use rspack_tracing_chrome::{ChromeLayerBuilder, EventOrSpan}; - /// use tracing_subscriber::{prelude::*, registry::Registry}; - /// - /// let (chrome_layer, _guard) = ChromeLayerBuilder::new() - /// .name_fn(Box::new(|event_or_span| match event_or_span { - /// EventOrSpan::Event(ev) => ev.metadata().name().into(), - /// EventOrSpan::Span(_s) => "span".into(), - /// })) - /// .build(); - /// tracing_subscriber::registry().with(chrome_layer).init() - /// ``` - pub fn name_fn(mut self, name_fn: NameFn) -> Self { - self.name_fn = Some(name_fn); - self - } - - /// Allows supplying a function that derives a category from - /// an Event or Span. The result is used as the "cat" field on - /// trace entries. - /// - /// # Example - /// ``` - /// use rspack_tracing_chrome::{ChromeLayerBuilder, EventOrSpan}; - /// use tracing_subscriber::{prelude::*, registry::Registry}; - /// - /// let (chrome_layer, _guard) = ChromeLayerBuilder::new() - /// .category_fn(Box::new(|_| "my_module".into())) - /// .build(); - /// tracing_subscriber::registry().with(chrome_layer).init() - /// ``` - pub fn category_fn(mut self, cat_fn: NameFn) -> Self { - self.cat_fn = Some(cat_fn); - self - } - - /// Creates a [`ChromeLayer`](crate::ChromeLayer) and associated [`FlushGuard`](crate::FlushGuard). - /// - /// # Panics - /// - /// If no file or writer was specified and the default trace file could not be opened/created. - pub fn build(self) -> (ChromeLayer, FlushGuard) { - ChromeLayer::new(self) - } -} - -/// This guard will signal the thread writing the trace file to stop and join it when dropped. -pub struct FlushGuard { - sender: Sender, - handle: Cell>>, -} - -impl FlushGuard { - /// Signals the trace writing thread to flush to disk. - pub fn flush(&self) { - if let Some(handle) = self.handle.take() { - let _ignored = self.sender.send(Message::Flush); - self.handle.set(Some(handle)); - } - } - - /// Finishes the current trace and starts a new one. - /// - /// If a [`Write`](std::io::Write) implementation is supplied, - /// the new trace is written to it. Otherwise, the new trace - /// goes to `./trace-{unix epoc in micros}.json`. - pub fn start_new(&self, writer: Option>) { - if let Some(handle) = self.handle.take() { - let _ignored = self.sender.send(Message::StartNew(writer)); - self.handle.set(Some(handle)); - } - } -} - -impl Drop for FlushGuard { - fn drop(&mut self) { - if let Some(handle) = self.handle.take() { - let _ignored = self.sender.send(Message::Drop); - if handle.join().is_err() { - eprintln!("tracing_chrome: Trace writing thread panicked."); - } - } - } -} - -struct Callsite { - tid: usize, - name: String, - target: String, - file: Option<&'static str>, - line: Option, - args: Option>, -} - -enum Message { - Enter(f64, Callsite, Option), - Event(f64, Callsite), - Exit(f64, Callsite, Option), - NewThread(usize, String), - Flush, - Drop, - StartNew(Option>), -} - -/// Represents either an [`Event`](tracing_core::Event) or [`SpanRef`](tracing_subscriber::registry::SpanRef). -pub enum EventOrSpan<'a, 'b, S> -where - S: Subscriber + for<'span> LookupSpan<'span> + Send + Sync, -{ - Event(&'a Event<'b>), - Span(&'a SpanRef<'b, S>), -} - -fn create_default_writer() -> Box { - Box::new( - std::fs::File::create(format!( - "./trace-{}.json", - std::time::SystemTime::UNIX_EPOCH - .elapsed() - .unwrap() - .as_micros() - )) - .expect("Failed to create trace file."), - ) -} - -impl ChromeLayer -where - S: Subscriber + for<'span> LookupSpan<'span> + Send + Sync, -{ - fn new(mut builder: ChromeLayerBuilder) -> (ChromeLayer, FlushGuard) { - let (tx, rx) = mpsc::channel(); - OUT.with(|val| val.replace(Some(tx.clone()))); - - let out_writer = builder.out_writer; - - let handle = std::thread::spawn(move || { - let out_writer = out_writer.map_or_else(|| create_default_writer() as _, |f| f()); - let mut write = BufWriter::new(out_writer); - write.write_all(b"[\n").unwrap(); - - // Add metadata event to set track title for perfetto track - let entry_list = [ - json!({ - "ph": "M", - "pid": 1, - "name": "process_name", - "args": { - "name": "Build Overview", - }, - }), - json!({ - "ph": "M", - "pid": 2, - "name": "process_name", - "args": { - "name": "Build Detail", - }, - }), - json!({ - "ph": "M", - "pid": 3, - "name": "process_name", - "args": { - "name": "CPU Profile", - }, - }), - ]; - for entry in entry_list.iter() { - serde_json::to_writer(&mut write, entry).unwrap(); - write.write_all(b",\n").unwrap(); - } - let mut has_started = false; - let mut thread_names: Vec<(usize, String)> = Vec::new(); - for msg in rx { - if let Message::Flush = &msg { - write.flush().unwrap(); - continue; - } else if let Message::Drop = &msg { - break; - } else if let Message::StartNew(writer) = msg { - // Finish off current file - write.write_all(b"\n]").unwrap(); - write.flush().unwrap(); - - // Get or create new writer - let out_writer = writer.unwrap_or_else(|| create_default_writer()); - write = BufWriter::new(out_writer); - write.write_all(b"[\n").unwrap(); - has_started = false; - - // Write saved thread names - for (tid, name) in thread_names.iter() { - let entry = json!({ - "ph": "M", - "pid": 1, // fake pid for separate perfetto overview track - "name": "thread_name", - "tid": *tid, - "args": { - "name": name, - }, - }); - - if has_started { - write.write_all(b",\n").unwrap(); - } - serde_json::to_writer(&mut write, &entry).unwrap(); - has_started = true; - } - continue; - } - - let (ph, ts, callsite, id) = match &msg { - Message::Enter(ts, callsite, None) => ("B", Some(ts), Some(callsite), None), - Message::Enter(ts, callsite, Some(root_id)) => { - ("b", Some(ts), Some(callsite), Some(root_id)) - } - Message::Event(ts, callsite) => ("i", Some(ts), Some(callsite), None), - Message::Exit(ts, callsite, None) => ("E", Some(ts), Some(callsite), None), - Message::Exit(ts, callsite, Some(root_id)) => { - ("e", Some(ts), Some(callsite), Some(root_id)) - } - Message::NewThread(_tid, _name) => ("M", None, None, None), - Message::Flush | Message::Drop | Message::StartNew(_) => { - panic!("Was supposed to break by now.") - } - }; - let mut entry = json!({ - "ph": ph, - "pid": 1, - }); - - if let Message::NewThread(tid, name) = msg { - thread_names.push((tid, name.clone())); - entry["name"] = "thread_name".into(); - entry["tid"] = tid.into(); - entry["args"] = json!({ "name": name }); - } else { - let ts = ts.unwrap(); - let callsite: &Callsite = callsite.unwrap(); - entry["ts"] = (*ts).into(); - entry["name"] = callsite.name.clone().into(); - entry["cat"] = callsite.target.clone().into(); - entry["tid"] = callsite.tid.into(); - entry["id2"] = json!({}); - - if let Some(&id) = id { - entry["id2"]["global"] = id.into(); - } - - if ph == "i" { - entry["s"] = "t".into(); - } - - if let (Some(file), Some(line)) = (callsite.file, callsite.line) { - entry[".file"] = file.into(); - entry[".line"] = line.into(); - } - - if let Some(call_args) = &callsite.args { - if !call_args.is_empty() { - // use id2 for perfetto to split span - if let Some(id2) = call_args.get("id2") { - entry["pid"] = json!(2); // fake pid for separate perfetto detail track - entry["id2"]["local"] = id2.clone(); - if let Some(obj) = entry["id2"].as_object_mut() { - obj.remove("global"); - } - } - entry["args"] = (**call_args).clone().into(); - } - } - } - - if has_started { - write.write_all(b",\n").unwrap(); - } - serde_json::to_writer(&mut write, &entry).unwrap(); - has_started = true; - } - // we need to merge tracing with js side, so don't end it early - // write.write_all(b"\n]").unwrap(); - write.flush().unwrap(); - }); - - let guard = FlushGuard { - sender: tx.clone(), - handle: Cell::new(Some(handle)), - }; - let layer = ChromeLayer { - out: Arc::new(Mutex::new(tx)), - start: std::time::Instant::now(), - max_tid: AtomicUsize::new(0), - name_fn: builder.name_fn.take(), - cat_fn: builder.cat_fn.take(), - include_args: builder.include_args, - include_locations: builder.include_locations, - trace_style: builder.trace_style, - _inner: PhantomData, - }; - - (layer, guard) - } - - fn get_tid(&self) -> (usize, bool) { - TID.with(|value| { - let tid = *value.borrow(); - match tid { - Some(tid) => (tid, false), - None => { - let tid = self.max_tid.fetch_add(1, Ordering::SeqCst); - value.replace(Some(tid)); - (tid, true) - } - } - }) - } - - fn get_callsite(&self, data: EventOrSpan) -> Callsite { - let (tid, new_thread) = self.get_tid(); - let name = self.name_fn.as_ref().map(|name_fn| name_fn(&data)); - let target = self.cat_fn.as_ref().map(|cat_fn| cat_fn(&data)); - let meta = match data { - EventOrSpan::Event(e) => e.metadata(), - EventOrSpan::Span(s) => s.metadata(), - }; - let args = match data { - EventOrSpan::Event(e) => { - if self.include_args { - let mut args = Object::new(); - e.record(&mut JsonVisitor { object: &mut args }); - Some(Arc::new(args)) - } else { - None - } - } - EventOrSpan::Span(s) => s - .extensions() - .get::() - .map(|e| &e.args) - .cloned(), - }; - let name = name.unwrap_or_else(|| meta.name().into()); - let target = target.unwrap_or_else(|| meta.target().into()); - let (file, line) = if self.include_locations { - (meta.file(), meta.line()) - } else { - (None, None) - }; - - if new_thread { - let name = match std::thread::current().name() { - Some(name) => name.to_owned(), - None => tid.to_string(), - }; - self.send_message(Message::NewThread(tid, name)); - } - - Callsite { - tid, - name, - target, - file, - line, - args, - } - } - - fn get_root_id(span: SpanRef) -> u64 { - span - .scope() - .from_root() - .take(1) - .next() - .unwrap_or(span) - .id() - .into_u64() - } - - fn enter_span(&self, span: SpanRef, ts: f64) { - let callsite = self.get_callsite(EventOrSpan::Span(&span)); - let root_id = match self.trace_style { - TraceStyle::Async => Some(ChromeLayer::get_root_id(span)), - _ => None, - }; - self.send_message(Message::Enter(ts, callsite, root_id)); - } - - fn exit_span(&self, span: SpanRef, ts: f64) { - let callsite = self.get_callsite(EventOrSpan::Span(&span)); - let root_id = match self.trace_style { - TraceStyle::Async => Some(ChromeLayer::get_root_id(span)), - _ => None, - }; - self.send_message(Message::Exit(ts, callsite, root_id)); - } - - fn get_ts(&self) -> f64 { - self.start.elapsed().as_nanos() as f64 / 1000.0 - } - - fn send_message(&self, message: Message) { - OUT.with(move |val| { - if val.borrow().is_some() { - let _ignored = val.borrow().as_ref().unwrap().send(message); - } else { - let out = self.out.lock().unwrap().clone(); - let _ignored = out.send(message); - val.replace(Some(out)); - } - }); - } -} - -impl Layer for ChromeLayer -where - S: Subscriber + for<'span> LookupSpan<'span> + Send + Sync, -{ - fn on_enter(&self, id: &span::Id, ctx: Context<'_, S>) { - if let TraceStyle::Async = self.trace_style { - return; - } - - let ts = self.get_ts(); - self.enter_span(ctx.span(id).expect("Span not found."), ts); - } - - fn on_record(&self, id: &span::Id, values: &span::Record<'_>, ctx: Context<'_, S>) { - if self.include_args { - let span = ctx.span(id).unwrap(); - let mut exts = span.extensions_mut(); - - let args = exts.get_mut::(); - - if let Some(args) = args { - let args = Arc::make_mut(&mut args.args); - values.record(&mut JsonVisitor { object: args }); - } - } - } - - fn on_event(&self, event: &Event<'_>, _ctx: Context<'_, S>) { - let ts = self.get_ts(); - let callsite = self.get_callsite(EventOrSpan::Event(event)); - self.send_message(Message::Event(ts, callsite)); - } - - fn on_exit(&self, id: &span::Id, ctx: Context<'_, S>) { - if let TraceStyle::Async = self.trace_style { - return; - } - let ts = self.get_ts(); - self.exit_span(ctx.span(id).expect("Span not found."), ts); - } - - fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, S>) { - if self.include_args { - let mut args = Object::new(); - attrs.record(&mut JsonVisitor { object: &mut args }); - ctx.span(id).unwrap().extensions_mut().insert(ArgsWrapper { - args: Arc::new(args), - }); - } - if let TraceStyle::Threaded = self.trace_style { - return; - } - - let ts = self.get_ts(); - self.enter_span(ctx.span(id).expect("Span not found."), ts); - } - - fn on_close(&self, id: span::Id, ctx: Context<'_, S>) { - if let TraceStyle::Threaded = self.trace_style { - return; - } - - let ts = self.get_ts(); - self.exit_span(ctx.span(&id).expect("Span not found."), ts); - } -} - -struct JsonVisitor<'a> { - object: &'a mut Object, -} - -impl<'a> tracing_subscriber::field::Visit for JsonVisitor<'a> { - fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) { - self - .object - .insert(field.name().to_owned(), format!("{value:?}").into()); - } - fn record_str(&mut self, field: &Field, value: &str) { - self.object.insert(field.name().to_owned(), value.into()); - } -} - -struct ArgsWrapper { - args: Arc, -} diff --git a/crates/rspack_tracing_chrome/Cargo.toml b/crates/rspack_tracing_perfetto/Cargo.toml similarity index 55% rename from crates/rspack_tracing_chrome/Cargo.toml rename to crates/rspack_tracing_perfetto/Cargo.toml index af7be33bce9d..50a66545a16a 100644 --- a/crates/rspack_tracing_chrome/Cargo.toml +++ b/crates/rspack_tracing_perfetto/Cargo.toml @@ -5,14 +5,15 @@ documentation.workspace = true edition.workspace = true homepage.workspace = true license.workspace = true -name = "rspack_tracing_chrome" +name = "rspack_tracing_perfetto" repository.workspace = true version = "0.2.0" [dependencies] -serde_json = { workspace = true } -tracing-core = "0.1.32" -tracing-subscriber = { workspace = true } - +bytes = { version = "*" } +micromegas-perfetto = { version = "*" } +prost = "0.13" +tracing = { workspace = true } +tracing-subscriber = { workspace = true } [lints] workspace = true diff --git a/crates/rspack_tracing_perfetto/src/idl_helpers.rs b/crates/rspack_tracing_perfetto/src/idl_helpers.rs new file mode 100644 index 000000000000..868a00e1bef7 --- /dev/null +++ b/crates/rspack_tracing_perfetto/src/idl_helpers.rs @@ -0,0 +1,102 @@ +use std::{ + collections::HashMap, + sync::{ + atomic::{AtomicU64, Ordering}, + LazyLock, Mutex, + }, +}; + +use micromegas_perfetto::protos::{self as idl, TracePacket}; + +static CUSTOM_SCOPE_NAMES: LazyLock>> = + LazyLock::new(|| Mutex::new(HashMap::new())); + +#[derive(Default)] +pub struct DebugAnnotations { + pub annotations: Vec, +} + +static GLOBAL_COUNTER: AtomicU64 = AtomicU64::new(1); + +pub fn unique_uuid() -> u64 { + GLOBAL_COUNTER.fetch_add(1, Ordering::SeqCst) +} + +pub fn create_track_descriptor( + uuid: u64, + parent_uuid: Option, + name: Option>, +) -> idl::TrackDescriptor { + let desc = idl::TrackDescriptor { + uuid: Some(uuid), + parent_uuid, + static_or_dynamic_name: name + .map(|s| s.as_ref().to_string()) + .map(idl::track_descriptor::StaticOrDynamicName::Name), + ..Default::default() + }; + desc +} + +pub fn create_event( + track_uuid: u64, + name: Option<&str>, + location: Option<(&str, u32)>, + debug_annotations: DebugAnnotations, + r#type: Option, +) -> idl::TrackEvent { + let mut event = idl::TrackEvent { + track_uuid: Some(track_uuid), + categories: vec![], + ..Default::default() + }; + if let Some(name) = name { + event.name_field = Some(idl::track_event::NameField::Name(name.to_string())); + } + if let Some(t) = r#type { + event.set_type(t); + } + if !debug_annotations.annotations.is_empty() { + event.debug_annotations = debug_annotations.annotations; + } + if let Some((file, line)) = location { + let source_location = idl::SourceLocation { + file_name: Some(file.to_owned()), + line_number: Some(line), + ..Default::default() + }; + let location = idl::track_event::SourceLocationField::SourceLocation(source_location); + event.source_location_field = Some(location); + } + event +} + +// write a custom scope to the trace, more info see https://perfetto.dev/docs/reference/synthetic-track-event#custom-scoped-slices +// it will only create a packet if the scope name is not already registered +pub fn create_scope_sliced_packet(scope_name: String) -> (Option, u64) { + // allocate a new uuid for the scope name if it is not already registered + if let Some(uuid) = CUSTOM_SCOPE_NAMES + .lock() + .expect("lock failed") + .get(&scope_name) + { + return (None, *uuid); + } + let uuid = unique_uuid(); + CUSTOM_SCOPE_NAMES + .lock() + .expect("lock failed") + .insert(scope_name.clone(), uuid); + + let track_descriptor = create_track_descriptor( + uuid, // uuid + None, // parent_uuid + Some(&scope_name), // name + ); + let packet = idl::TracePacket { + data: Some(idl::trace_packet::Data::TrackDescriptor(track_descriptor)), + ..Default::default() + }; + + (Some(packet), uuid) +} diff --git a/crates/rspack_tracing_perfetto/src/lib.rs b/crates/rspack_tracing_perfetto/src/lib.rs new file mode 100644 index 000000000000..d46d97700661 --- /dev/null +++ b/crates/rspack_tracing_perfetto/src/lib.rs @@ -0,0 +1,471 @@ +// Modified base on https://github.com/csmoe/tracing-perfetto +// 1. use micromegas_perfetto to avoid manually updating the perfetto proto file +// 2. use Custom-scoped slices to mangae custom scope +#![forbid(unsafe_code)] +use std::io::Write; + +pub use bytes::BytesMut; +use idl_helpers::{create_event, create_track_descriptor, unique_uuid, DebugAnnotations}; +pub use micromegas_perfetto::protos::{self as idl}; +pub use prost; +use prost::Message; +use tracing::{ + field::{Field, Visit}, + span, Event, Id, Subscriber, +}; +use tracing_subscriber::{fmt::MakeWriter, layer::Context, registry::LookupSpan, Layer}; + +use crate::idl_helpers::create_scope_sliced_packet; + +pub mod idl_helpers; +static DEFAULT_PROCESS_NAME: &str = "Rspack Build Overall"; +static DEFAULT_THREAD_NAME: &str = "Main Phase"; + +pub struct PerfettoSpanState { + pub track_descriptor: Option, // optional track descriptor for this span, defaults to thread if not found + pub trace: idl::Trace, // The Protobuf trace messages that we accumulate for this span. +} + +/// A `Layer` that records span as perfetto's +/// `TYPE_SLICE_BEGIN`/`TYPE_SLICE_END`, and event as `TYPE_INSTANT`. +/// +/// `PerfettoLayer` will output the records as encoded [protobuf messages](https://github.com/google/perfetto). +pub struct PerfettoLayer std::io::Stdout> { + sequence_id: SequenceId, + writer: W, + config: Config, + start: std::time::Instant, +} + +impl PerfettoLayer { + pub fn get_ts(&self) -> u64 { + self.start.elapsed().as_nanos() as u64 + } +} + +/// Writes encoded records into provided instance. +/// +/// This is implemented for types implements [`MakeWriter`]. +pub trait PerfettoWriter { + fn write_log(&self, buf: BytesMut) -> std::io::Result<()>; + fn flush(&self) -> std::io::Result<()>; +} + +impl MakeWriter<'writer> + 'static> PerfettoWriter for W { + fn write_log(&self, buf: BytesMut) -> std::io::Result<()> { + self.make_writer().write_all(&buf) + } + fn flush(&self) -> std::io::Result<()> { + Ok(()) + } +} + +#[derive(Default)] +struct Config { + debug_annotations: bool, + filter: Option bool>, +} + +impl PerfettoLayer { + pub fn new(writer: W) -> Self { + Self { + sequence_id: SequenceId::new(0), + writer, + config: Config::default(), + start: std::time::Instant::now(), + } + } + + /// Configures whether or not spans/events should be recorded with their metadata and fields. + pub fn with_debug_annotations(mut self, value: bool) -> Self { + self.config.debug_annotations = value; + self + } + // flush tracing to disk + pub fn flush(&self) { + let _ = self.writer.flush(); + } + + fn write_log(&self, mut log: idl::Trace, track_descriptor: Option) { + let mut buf = BytesMut::new(); + let mut packet = idl::TracePacket::default(); + if let Some(track_descriptor) = track_descriptor { + packet.data = Some(idl::trace_packet::Data::TrackDescriptor(track_descriptor)); + } + log.packet.insert(1, packet); + + let Ok(_) = log.encode(&mut buf) else { + return; + }; + _ = self.writer.write_log(buf); + } +} + +struct SequenceId(u64); + +impl SequenceId { + fn new(n: u64) -> Self { + Self(n) + } + + fn get(&self) -> u64 { + self.0 + } +} + +struct TrackNameVisitor<'a> { + user_track_name: &'a mut Option, + user_process_name: &'a mut Option, +} + +impl<'a> Visit for TrackNameVisitor<'a> { + // fn record_u64(&mut self, field: &Field, value: u64) { + // if field.name() == "perfetto_track_id" { + // *self.user_track_id = Some(value); + // } + // } + + fn record_str(&mut self, field: &Field, value: &str) { + if field.name() == "perfetto.track_name" { + *self.user_track_name = Some(value.to_string()); + } + if field.name() == "perfetto.process_name" { + *self.user_process_name = Some(value.to_string()); + } + } + fn record_debug(&mut self, _field: &Field, _value: &dyn std::fmt::Debug) { + // If you want to parse `perfetto_track_id` from a non-u64 typed field, + // you could do that here, e.g. if user sets `perfetto_track_id = "0xABCD"`. + // For now, we'll ignore it. + } + // Optionally implement record_* for other numeric types if needed +} +struct PerfettoVisitor { + perfetto: bool, + filter: fn(&str) -> bool, +} + +impl PerfettoVisitor { + fn new(filter: fn(&str) -> bool) -> PerfettoVisitor { + Self { + filter, + perfetto: false, + } + } +} + +impl Visit for PerfettoVisitor { + fn record_debug(&mut self, field: &Field, _value: &dyn std::fmt::Debug) { + if (self.filter)(field.name()) { + self.perfetto = true; + } + } +} + +impl Layer for PerfettoLayer +where + S: for<'a> LookupSpan<'a>, + W: for<'writer> MakeWriter<'writer> + 'static, +{ + fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, S>) { + let Some(span) = ctx.span(id) else { + return; + }; + + let enabled = self.config.filter.is_none_or(|f| { + let mut visitor = PerfettoVisitor::new(f); + attrs.record(&mut visitor); + visitor.perfetto + }); + + if !enabled { + return; + } + + let mut debug_annotations = DebugAnnotations::default(); + if self.config.debug_annotations { + attrs.record(&mut debug_annotations); + } + + let mut packet: idl::TracePacket = idl::TracePacket::default(); + + // check if parent span has a non default track descriptor + let inherited_track_descriptor = span + .parent() + // If the span has a parent, try retrieving the track descriptor from the parent's state + .and_then(|parent_span| { + parent_span + .extensions() + .get::() + .map(|state| state.track_descriptor.clone()) + }) + .flatten(); + + // retrieve the user set track name and processor name (via `perfetto.track_name` and `perfetto.process_name` field) + let mut user_track_name = None; + let mut user_process_name = None; + let mut visitor = TrackNameVisitor { + user_track_name: &mut user_track_name, + user_process_name: &mut user_process_name, + }; + + attrs.record(&mut visitor); + let (custom_scope_packet, process_uuid) = + create_scope_sliced_packet(user_process_name.unwrap_or(DEFAULT_PROCESS_NAME.to_string())); + + // resolve the optional track descriptor for this span (either inherited from parent or user set, or None) + let span_track_descriptor = user_track_name + .map(|name| { + create_track_descriptor( + unique_uuid(), // uuid + Some(process_uuid), // use process uuid for separate thread name + Some(name), // name + ) + }) + .or(inherited_track_descriptor) + .unwrap_or_else(|| { + create_track_descriptor( + unique_uuid(), // uuid + Some(process_uuid), // parent_uuid + Some(DEFAULT_THREAD_NAME), // name + ) + }); + + let final_uuid = span_track_descriptor.uuid(); + + let event = create_event( + final_uuid, // span track id if exists, otherwise thread track id + Some(span.name()), + span.metadata().file().zip(span.metadata().line()), + debug_annotations, + Some(idl::track_event::Type::SliceBegin), + ); + packet.data = Some(idl::trace_packet::Data::TrackEvent(event)); + packet.timestamp = Some(self.get_ts()); + packet.trusted_pid = Some(std::process::id() as _); + packet.optional_trusted_packet_sequence_id = Some( + idl::trace_packet::OptionalTrustedPacketSequenceId::TrustedPacketSequenceId( + self.sequence_id.get() as _, + ), + ); + + let span_state = PerfettoSpanState { + track_descriptor: Some(span_track_descriptor), + trace: idl::Trace { + packet: custom_scope_packet + .into_iter() + .chain(std::iter::once(packet)) + .collect(), + }, + }; + span.extensions_mut().insert(span_state); + } + + fn on_record(&self, span: &span::Id, values: &span::Record<'_>, ctx: Context<'_, S>) { + let Some(span) = ctx.span(span) else { + return; + }; + + // We don't check the filter here -- we've already checked it when we handled the span on + // `on_new_span`. Iff we successfully attached a track packet to the span, then we'll also + // update the trace packet with the debug data here. + if let Some(extension) = span.extensions_mut().get_mut::() { + if let Some(idl::trace_packet::Data::TrackEvent(ref mut event)) = + &mut extension.trace.packet[0].data + { + let mut debug_annotations = DebugAnnotations::default(); + values.record(&mut debug_annotations); + event + .debug_annotations + .append(&mut debug_annotations.annotations); + } + }; + } + + fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) { + let enabled = self.config.filter.is_none_or(|f| { + let mut visitor = PerfettoVisitor::new(f); + event.record(&mut visitor); + visitor.perfetto + }); + + if !enabled { + return; + } + + let mut user_track_name = None; + let mut user_process_name = None; + let mut visitor = TrackNameVisitor { + user_track_name: &mut user_track_name, + user_process_name: &mut user_process_name, + }; + + event.record(&mut visitor); + let inherited_track_descriptor = event + .parent() + // If the event has a parent span, try retrieving the track descriptor from the parent's state + .and_then(|id| { + let parent_span = ctx.span(id); + parent_span.and_then(|span| { + span + .extensions() + .get::() + .map(|state| state.track_descriptor.clone()) + }) + }) + .flatten(); + let (custom_scope_packet, process_uuid) = + create_scope_sliced_packet(user_process_name.unwrap_or(DEFAULT_PROCESS_NAME.to_string())); + let event_track_descriptor = user_track_name + .map(|name| { + create_track_descriptor( + unique_uuid(), // uuid + Some(process_uuid), // use process uuid for separate thread name + Some(name), // name + ) + }) + .or(inherited_track_descriptor) + .unwrap_or_else(|| { + create_track_descriptor( + unique_uuid(), // uuid + Some(process_uuid), // parent_uuid + Some(DEFAULT_THREAD_NAME), // name + ) + }); + let metadata = event.metadata(); + let location = metadata.file().zip(metadata.line()); + + let mut debug_annotations = DebugAnnotations::default(); + + if self.config.debug_annotations { + event.record(&mut debug_annotations); + } + let uuid = unique_uuid(); + let track_event = create_event( + uuid, + Some(metadata.name()), + location, + debug_annotations, + Some(idl::track_event::Type::Instant), + ); + + let packet = idl::TracePacket { + timestamp: Some(self.get_ts()), + optional_trusted_packet_sequence_id: Some( + idl::trace_packet::OptionalTrustedPacketSequenceId::TrustedPacketSequenceId( + self.sequence_id.get() as _, + ), + ), + data: Some(idl::trace_packet::Data::TrackEvent(track_event)), + ..Default::default() + }; + let trace = idl::Trace { + packet: custom_scope_packet + .into_iter() + .chain(std::iter::once(packet)) + .collect(), + }; + self.write_log(trace, Some(event_track_descriptor)); + } + + fn on_close(&self, id: Id, ctx: Context<'_, S>) { + let Some(span) = ctx.span(&id) else { + return; + }; + + let Some(mut span_state) = span.extensions_mut().remove::() else { + return; + }; + + let debug_annotations = DebugAnnotations::default(); + + let track_uuid = span_state + .track_descriptor + .as_ref() + .map(|d| d.uuid()) + .expect("should have a track descriptor"); + + let mut packet = idl::TracePacket::default(); + let meta = span.metadata(); + let event = create_event( + track_uuid, + Some(meta.name()), + meta.file().zip(meta.line()), + debug_annotations, + Some(idl::track_event::Type::SliceEnd), + ); + packet.data = Some(idl::trace_packet::Data::TrackEvent(event)); + packet.timestamp = Some(self.get_ts()); + packet.trusted_pid = Some(std::process::id() as _); + packet.optional_trusted_packet_sequence_id = Some( + idl::trace_packet::OptionalTrustedPacketSequenceId::TrustedPacketSequenceId( + self.sequence_id.get() as _, + ), + ); + + span_state.trace.packet.push(packet); + self.write_log(span_state.trace, span_state.track_descriptor); + } +} + +macro_rules! impl_record { + ($method:ident, $type:ty, $value_variant:ident) => { + fn $method(&mut self, field: &Field, value: $type) { + let mut annotation = idl::DebugAnnotation::default(); + annotation.name_field = Some(idl::debug_annotation::NameField::Name( + field.name().to_string(), + )); + annotation.value = Some(idl::debug_annotation::Value::$value_variant(value.into())); + self.annotations.push(annotation); + } + }; + ($method:ident, $type:ty, $value_variant:ident, $conversion:expr) => { + fn $method(&mut self, field: &Field, value: $type) { + let mut annotation = idl::DebugAnnotation::default(); + annotation.name_field = Some(idl::debug_annotation::NameField::Name( + field.name().to_string(), + )); + annotation.value = Some(idl::debug_annotation::Value::$value_variant($conversion( + value, + ))); + self.annotations.push(annotation); + } + }; +} + +impl Visit for DebugAnnotations { + impl_record!(record_bool, bool, BoolValue); + impl_record!(record_str, &str, StringValue, String::from); + impl_record!(record_f64, f64, DoubleValue); + impl_record!(record_i64, i64, IntValue); + impl_record!(record_i128, i128, StringValue, |v: i128| v.to_string()); + impl_record!(record_u128, u128, StringValue, |v: u128| v.to_string()); + impl_record!(record_u64, u64, IntValue, |v: u64| v as i64); + + fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) { + let annotation = idl::DebugAnnotation { + name_field: Some(idl::debug_annotation::NameField::Name( + field.name().to_string(), + )), + value: Some(idl::debug_annotation::Value::StringValue(format!( + "{value:?}" + ))), + ..Default::default() + }; + self.annotations.push(annotation); + } + + fn record_error(&mut self, field: &Field, value: &(dyn std::error::Error + 'static)) { + let annotation = idl::DebugAnnotation { + name_field: Some(idl::debug_annotation::NameField::Name( + field.name().to_string(), + )), + value: Some(idl::debug_annotation::Value::StringValue(format!( + "{value}" + ))), + ..Default::default() + }; + + self.annotations.push(annotation); + } +} diff --git a/packages/rspack-cli/src/utils/profile.ts b/packages/rspack-cli/src/utils/profile.ts index 8b839cea1179..cb432846677c 100644 --- a/packages/rspack-cli/src/utils/profile.ts +++ b/packages/rspack-cli/src/utils/profile.ts @@ -9,7 +9,7 @@ import { rspack } from "@rspack/core"; const overviewTraceFilter = "info"; const allTraceFilter = "trace"; -const defaultRustTraceLayer = "chrome"; +const defaultRustTraceLayer = "perfetto"; enum TracePreset { OVERVIEW = "OVERVIEW", // contains overview trace events @@ -33,28 +33,31 @@ export async function applyProfile( ) { const { asyncExitHook } = await import("exit-hook"); - if (traceLayer !== "chrome" && traceLayer !== "logger") { + if (traceLayer !== "logger" && traceLayer !== "perfetto") { throw new Error(`unsupported trace layer: ${traceLayer}`); } - + const timestamp = Date.now(); + const defaultOutputDir = path.resolve( + `.rspack-profile-${timestamp}-${process.pid}` + ); if (!traceOutput) { - const timestamp = Date.now(); - const defaultOutputDir = path.resolve( - `.rspack-profile-${timestamp}-${process.pid}` - ); - const defaultRustTraceChromeOutput = path.join( + const defaultRustTracePerfettoOutput = path.resolve( defaultOutputDir, - "trace.json" + "rspack.pftrace" ); const defaultRustTraceLoggerOutput = "stdout"; const defaultTraceOutput = - traceLayer === "chrome" - ? defaultRustTraceChromeOutput + traceLayer === "perfetto" + ? defaultRustTracePerfettoOutput : defaultRustTraceLoggerOutput; // biome-ignore lint/style/noParameterAssign: setting default value makes sense traceOutput = defaultTraceOutput; + } else if (traceOutput !== "stdout" && traceOutput !== "stderr") { + // if traceOutput is not stdout or stderr, we need to ensure the directory exists + // biome-ignore lint/style/noParameterAssign: setting default value makes sense + traceOutput = path.resolve(defaultOutputDir, traceOutput); } const filter = resolveLayer(filterValue); diff --git a/packages/rspack-cli/tests/build/profile/profile.test.ts b/packages/rspack-cli/tests/build/profile/profile.test.ts index e54b5fe5c52c..454d3f539b6c 100644 --- a/packages/rspack-cli/tests/build/profile/profile.test.ts +++ b/packages/rspack-cli/tests/build/profile/profile.test.ts @@ -2,7 +2,7 @@ import fs from "fs"; import { resolve } from "path"; import { run } from "../../utils/test-utils"; -const defaultTracePath = "./trace.json"; +const defaultTracePath = "./rspack.pftrace"; const customTracePath = "./custom/trace.json"; function findDefaultOutputDirname() { @@ -50,20 +50,32 @@ describe("profile", () => { __dirname, [], {}, - { RSPACK_PROFILE: "rspack,respack_resolver" } + { + NO_COLOR: "1", + RSPACK_PROFILE: "rspack,respack_resolver", + RSPACK_TRACE_OUTPUT: defaultTracePath, + RSPACK_TRACE_LAYER: "logger" + } ); expect(exitCode).toBe(0); const dirname = findDefaultOutputDirname(); - const trace = resolve(dirname, defaultTracePath); - expect(fs.existsSync(trace)).toBeTruthy(); - const out: { cat?: string }[] = JSON.parse(fs.readFileSync(trace, "utf-8")); + const tracePath = resolve(dirname, defaultTracePath); + expect(fs.existsSync(tracePath)).toBeTruthy(); + const content = fs.readFileSync(tracePath, "utf-8"); + const out: any[] = content + .trim() + .split("\n") + .map(line => { + return JSON.parse(line); + }); + expect( out - .filter(line => line.cat) + .filter(line => line.target) .every( line => - line.cat!.startsWith("rspack") || - line.cat!.startsWith("disabled-by-default-v8.cpu_profiler") + line.target.startsWith("rspack") || + line.target.startsWith("rspack_resolver") ) ).toBe(true); }); @@ -74,12 +86,13 @@ describe("profile", () => { [], {}, { - RSPACK_PROFILE: "ALL", + RSPACK_PROFILE: "OVERVIEW", RSPACK_TRACE_OUTPUT: customTracePath } ); expect(exitCode).toBe(0); - expect(fs.existsSync(resolve(__dirname, customTracePath))).toBeTruthy(); + const dirname = findDefaultOutputDirname(); + expect(fs.existsSync(resolve(dirname, customTracePath))).toBeTruthy(); }); it("should be able to use logger trace layer and default output should be stdout", async () => { diff --git a/packages/rspack/etc/core.api.md b/packages/rspack/etc/core.api.md index f3e441b57249..100cc2cfc55b 100644 --- a/packages/rspack/etc/core.api.md +++ b/packages/rspack/etc/core.api.md @@ -2470,7 +2470,7 @@ interface Experiments_2 { CssChunkingPlugin: typeof CssChunkingPlugin; // (undocumented) globalTrace: { - register: (filter: string, layer: "chrome" | "logger", output: string) => Promise; + register: (filter: string, layer: "logger" | "perfetto", output: string) => Promise; cleanup: () => Promise; }; // (undocumented) diff --git a/packages/rspack/src/Compiler.ts b/packages/rspack/src/Compiler.ts index 5d4be20b47d9..3d9359aac832 100644 --- a/packages/rspack/src/Compiler.ts +++ b/packages/rspack/src/Compiler.ts @@ -461,7 +461,6 @@ class Compiler { this.hooks.afterDone.call(stats!); instanceBinding.shutdownAsyncRuntime(); - instanceBinding.cleanupGlobalTrace(); isRuntimeShutdown = true; }; diff --git a/packages/rspack/src/exports.ts b/packages/rspack/src/exports.ts index 3ff9771ae476..ef762f29b90f 100644 --- a/packages/rspack/src/exports.ts +++ b/packages/rspack/src/exports.ts @@ -330,7 +330,11 @@ export type { export type { SubresourceIntegrityPluginOptions } from "./builtin-plugin"; ///// Experiments Stuff ///// -import { cleanupGlobalTrace, registerGlobalTrace } from "@rspack/binding"; +import { + cleanupGlobalTrace, + registerGlobalTrace, + syncTraceEvent +} from "@rspack/binding"; import { JavaScriptTracer } from "./trace"; ///// Experiments SWC ///// @@ -340,7 +344,7 @@ interface Experiments { globalTrace: { register: ( filter: string, - layer: "chrome" | "logger", + layer: "logger" | "perfetto", output: string ) => Promise; cleanup: () => Promise; @@ -365,10 +369,9 @@ export const experiments: Experiments = { JavaScriptTracer.initCpuProfiler(); }, async cleanup() { - // make sure run cleanupGlobalTrace first so we can safely append Node.js trace to it otherwise it will overlap - cleanupGlobalTrace(); - await JavaScriptTracer.cleanupJavaScriptTrace(); + await syncTraceEvent(JavaScriptTracer.events); + cleanupGlobalTrace(); } }, RemoveDuplicateModulesPlugin, diff --git a/packages/rspack/src/loader-runner/index.ts b/packages/rspack/src/loader-runner/index.ts index ec72a9d626e3..bc1f10470b2c 100644 --- a/packages/rspack/src/loader-runner/index.ts +++ b/packages/rspack/src/loader-runner/index.ts @@ -7,7 +7,7 @@ * Copyright (c) JS Foundation and other contributors * https://github.com/webpack/loader-runner/blob/main/LICENSE */ - +const LOADER_PROCESS_NAME = "Loader Analysis"; import querystring from "node:querystring"; import assert from "node:assert"; @@ -265,10 +265,16 @@ export async function runLoaders( const pitch = loaderState === JsLoaderState.Pitching; const { resource } = context; + const uuid = JavaScriptTracer.uuid(); + JavaScriptTracer.startAsync({ - name: `run_js_loaders${pitch ? ":pitch" : ":normal"}`, + name: "run_js_loaders", + processName: LOADER_PROCESS_NAME, + uuid, + ph: "b", args: { - id2: resource + is_pitch: pitch, + resource: resource } }); const splittedResource = resource && parsePathQueryFragment(resource); @@ -333,8 +339,12 @@ export async function runLoaders( ) { JavaScriptTracer.startAsync({ name: "importModule", + processName: LOADER_PROCESS_NAME, + + uuid, args: { - id2: resource + is_pitch: pitch, + resource: resource } }); const options = userOptions ? userOptions : {}; @@ -347,8 +357,11 @@ export async function runLoaders( if (err) { JavaScriptTracer.endAsync({ name: "importModule", + processName: LOADER_PROCESS_NAME, + uuid, args: { - id2: resource + is_pitch: pitch, + resource: resource } }); onError(err); @@ -370,8 +383,11 @@ export async function runLoaders( } JavaScriptTracer.endAsync({ name: "importModule", + processName: LOADER_PROCESS_NAME, + uuid, args: { - id2: resource + is_pitch: pitch, + resource: resource } }); if (res.error) { @@ -958,11 +974,13 @@ export async function runLoaders( const loaderName = extractLoaderName(currentLoaderObject!.request); let result: any; JavaScriptTracer.startAsync({ - name: `js_loader:${pitch ? "pitch:" : ""}${loaderName}`, - cat: "rspack", + name: loaderName, + trackName: loaderName, + processName: LOADER_PROCESS_NAME, + uuid, args: { - id2: resource, - "loader.request": currentLoaderObject?.request + is_pitch: pitch, + resource: resource } }); if (parallelism) { @@ -981,10 +999,13 @@ export async function runLoaders( result = (await runSyncOrAsync(fn, loaderContext, args)) || []; } JavaScriptTracer.endAsync({ - name: `js_loader:${pitch ? "pitch:" : ""}${loaderName}`, + name: loaderName, + trackName: loaderName, + processName: LOADER_PROCESS_NAME, + uuid, args: { - id2: resource, - "loader.request": currentLoaderObject?.request + is_pitch: pitch, + resource: resource } }); return result; @@ -1097,9 +1118,11 @@ export async function runLoaders( }; } JavaScriptTracer.endAsync({ - name: `run_js_loaders${pitch ? ":pitch" : ":normal"}`, + name: "run_js_loaders", + uuid, args: { - id2: resource + is_pitch: pitch, + resource: resource } }); diff --git a/packages/rspack/src/trace/index.ts b/packages/rspack/src/trace/index.ts index 5c817d6ab844..5450aec4524c 100644 --- a/packages/rspack/src/trace/index.ts +++ b/packages/rspack/src/trace/index.ts @@ -1,28 +1,25 @@ -import fs from "node:fs"; - // following chrome trace event format https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview?tab=t.0#heading=h.uxpopqvbjezh export interface ChromeEvent { name: string; - ph?: string; - cat?: string; // cat is used to show different track in perfetto with id - ts?: number; - pid?: number | string; - tid?: number | string; - id?: number | string; // updated to allow string id + trackName?: string; + ph: "b" | "e" | "X" | "P"; + processName?: string; + categories?: string[]; + uuid: number; + ts: bigint; args?: { [key: string]: any; }; - id2?: { - local?: string; - global?: string; - }; } +type MakeOptional = Omit & Partial>; + +type PartialChromeEvent = MakeOptional; // this is a tracer for nodejs // FIXME: currently we only support chrome layer and do nothing for logger layer export class JavaScriptTracer { // baseline time, we use offset time for tracing to align with rust side time - static startTime: number; + static startTime: bigint; static events: ChromeEvent[]; static layer: string; // tracing file path, same as rust tracing-chrome's @@ -30,32 +27,32 @@ export class JavaScriptTracer { // inspector session for CPU Profiler static session: import("node:inspector").Session; // plugin counter for different channel in trace viewer, choose 100 to avoid conflict with known tracks - static counter = 100; + private static counter = 10000; static async initJavaScriptTrace(layer: string, output: string) { const { Session } = await import("node:inspector"); this.session = new Session(); this.layer = layer; this.output = output; this.events = []; - const hrtime = process.hrtime(); - this.startTime = hrtime[0] * 1000000 + Math.round(hrtime[1] / 1000); // use microseconds + this.startTime = process.hrtime.bigint(); // use microseconds + } + static uuid() { + return this.counter++; } - static initCpuProfiler() { - if (this.layer === "chrome") { + if (this.layer) { this.session.connect(); this.session.post("Profiler.enable"); this.session.post("Profiler.start"); } } - /** * * @param isEnd true means we are at the end of tracing,and can append ']' to close the json * @returns */ static async cleanupJavaScriptTrace() { - if (!this.layer.includes("chrome")) { + if (!this.layer) { return; } const profileHandler = ( @@ -69,28 +66,32 @@ export class JavaScriptTracer { cpu_profile = param.profile; } if (cpu_profile) { + const uuid = this.uuid(); // add event contains cpu_profile to show cpu profile in trace viewer (firefox profiler and perfetto) // more info in https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview?tab=t.0#heading=h.yr4qxyxotyw this.pushEvent({ name: "Profile", ph: "P", - id: 1, + trackName: "JavaScript CPU Profiler", + processName: "JavaScript CPU", + uuid, ...this.getCommonEv(), - cat: "disabled-by-default-v8.cpu_profiler", - pid: 3, // separate process id for cpu profile + categories: ["disabled-by-default-v8.cpu_profiler"], args: { data: { startTime: 0 // use offset time to align with other trace data } } }); + this.pushEvent({ name: "ProfileChunk", ph: "P", - id: 1, + trackName: "JavaScript CPU Profiler", + processName: "JavaScript CPU", ...this.getCommonEv(), - cat: "disabled-by-default-v8.cpu_profiler", - pid: 3, + categories: ["disabled-by-default-v8.cpu_profiler"], + uuid, args: { data: { cpuProfile: cpu_profile, @@ -99,20 +100,6 @@ export class JavaScriptTracer { } }); } - const is_empty = fs.statSync(this.output).size === 0; - const fd = fs.openSync(this.output, "a"); - // stream write to file to avoid large string memory issue - let first = is_empty; - for (const event of this.events) { - if (!first) { - fs.writeFileSync(fd, ",\n"); - } - fs.writeFileSync(fd, JSON.stringify(event)); - first = false; - } - // even lots of tracing tools supports json without ending ], we end it for better compat with other tools - fs.writeFileSync(fd, "\n]"); - fs.closeSync(fd); }; return new Promise((resolve, reject) => { this.session.post("Profiler.stop", (err, params) => { @@ -129,51 +116,52 @@ export class JavaScriptTracer { }); }); } - // get elapsed time since start(microseconds same as rust side timestamp) + // get elapsed time since start(nanoseconds same as rust side timestamp) static getTs() { - const hrtime = process.hrtime(); - return hrtime[0] * 1000000 + Math.round(hrtime[1] / 1000) - this.startTime; + const now: bigint = process.hrtime.bigint(); + const elapsed = now - this.startTime; + return elapsed; } // get common chrome event static getCommonEv() { return { - tid: 1, - pid: 2, // fake pid for detailed track ts: this.getTs(), cat: "rspack" }; } static pushEvent(event: ChromeEvent) { - // set id2 as perfetto track id - if (!event.id2 && event.args?.id2) { - event.id2 = { - local: event.args.id2 - }; - } - - this.events.push(event); + const stringifiedArgs = Object.keys(event.args || {}).reduce( + (acc, key) => { + acc[key as string] = JSON.stringify(event.args![key]); + return acc; + }, + {} as Record + ); + this.events.push({ + ...event, + args: stringifiedArgs + }); } // start an chrome async event - static startAsync(events: ChromeEvent) { - if (this.layer !== "chrome") { + static startAsync(events: PartialChromeEvent) { + if (!this.layer) { return; } this.pushEvent({ ...this.getCommonEv(), - ph: "b", - - ...events + ...events, + ph: "b" }); } // end an chrome async event - static endAsync(events: ChromeEvent) { - if (this.layer !== "chrome") { + static endAsync(events: PartialChromeEvent) { + if (!this.layer) { return; } this.pushEvent({ ...this.getCommonEv(), - ph: "e", - ...events + ...events, + ph: "e" }); } } diff --git a/packages/rspack/src/trace/traceHookPlugin.ts b/packages/rspack/src/trace/traceHookPlugin.ts index 7950205d54ed..da4dcb35b86c 100644 --- a/packages/rspack/src/trace/traceHookPlugin.ts +++ b/packages/rspack/src/trace/traceHookPlugin.ts @@ -2,6 +2,8 @@ import { JavaScriptTracer } from "."; // adjust from webpack's ProfilingPlugin https://github.com/webpack/webpack/blob/dec18718be5dfba28f067fb3827dd620a1f33667/lib/debug/ProfilingPlugin.js#L1 import type { Compiler } from "../exports"; const PLUGIN_NAME = "TraceHookPlugin"; +// needs same as rust plugin side +const PLUGIN_PROCESS_NAME = "Plugin Analysis"; type FullTap = Tap & { type: "sync" | "async" | "promise"; fn: Function; @@ -31,6 +33,7 @@ const makeInterceptorFor = return { ...tapInfo, fn: newFn }; } }); + const interceptAllHooksFor = ( instance: any, tracer: typeof JavaScriptTracer, @@ -51,31 +54,32 @@ const makeNewTraceTapFn = ( tracer: typeof JavaScriptTracer, { name: pluginName, type, fn }: { name: string; type: string; fn: Function } ) => { - const name = `${pluginName}:${hookName}`; - const id = pluginName; // used for track switch (type) { case "promise": return (...args: any[]) => { - const id2 = tracer.counter++; + const uuid = tracer.uuid(); tracer.startAsync({ - name, - id, + name: hookName, + trackName: pluginName, + processName: PLUGIN_PROCESS_NAME, + uuid, args: { - id2, compilerName, hookName, pluginName } }); + const promise = /** @type {Promise<(...args: EXPECTED_ANY[]) => EXPECTED_ANY>} */ fn(...args); return promise.then((r: any) => { tracer.endAsync({ - name, - id, + name: hookName, + trackName: pluginName, + processName: PLUGIN_PROCESS_NAME, + uuid, args: { - id2, compilerName, hookName, pluginName @@ -86,12 +90,13 @@ const makeNewTraceTapFn = ( }; case "async": return (...args: any[]) => { - const id2 = tracer.counter++; + const uuid = tracer.uuid(); tracer.startAsync({ - name, - id, + name: hookName, + trackName: pluginName, + processName: PLUGIN_PROCESS_NAME, + uuid, args: { - id2, compilerName, hookName, pluginName @@ -105,10 +110,11 @@ const makeNewTraceTapFn = ( */ (...r: any[]) => { tracer.endAsync({ - name, - id, + name: hookName, + trackName: pluginName, + processName: PLUGIN_PROCESS_NAME, + uuid, args: { - id2, compilerName, hookName, pluginName @@ -120,18 +126,19 @@ const makeNewTraceTapFn = ( }; case "sync": return (...args: any[]) => { - const id2 = tracer.counter++; + const uuid = tracer.uuid(); // Do not instrument ourself due to the CPU // profile needing to be the last event in the trace. - if (name === PLUGIN_NAME) { + if (pluginName === PLUGIN_NAME) { return fn(...args); } tracer.startAsync({ - name, - id, + name: hookName, + trackName: pluginName, + processName: PLUGIN_PROCESS_NAME, + uuid, args: { - id2, compilerName, hookName, pluginName @@ -142,10 +149,11 @@ const makeNewTraceTapFn = ( r = fn(...args); } catch (err) { tracer.endAsync({ - name, - id, + name: hookName, + trackName: pluginName, + processName: PLUGIN_PROCESS_NAME, + uuid, args: { - id2: compilerName, hookName, pluginName } @@ -153,10 +161,11 @@ const makeNewTraceTapFn = ( throw err; } tracer.endAsync({ - name, - id, + name: hookName, + trackName: pluginName, + processName: PLUGIN_PROCESS_NAME, + uuid, args: { - id2, compilerName, hookName, pluginName diff --git a/website/docs/en/contribute/development/tracing.md b/website/docs/en/contribute/development/tracing.md index 23c1b1ac1bab..047dc34c32a5 100644 --- a/website/docs/en/contribute/development/tracing.md +++ b/website/docs/en/contribute/development/tracing.md @@ -11,7 +11,7 @@ Tracing can be enabled in two ways: ```sh # Rspack CLI RSPACK_PROFILE=OVERVIEW rspack build # recommend -RSPACK_PROFILE=ALL rspack build # not recommend, may generate too large trace.json for large projects +RSPACK_PROFILE=ALL rspack build # not recommend, may generate too large rspack.pftrace for large projects # Rsbuild RSPACK_PROFILE=OVERVIEW rsbuild build @@ -20,13 +20,13 @@ RSPACK_PROFILE=ALL rsbuild build - If directly using `@rspack/core`: Enable it through `rspack.experiments.globalTrace.register` and `rspack.experiments.globalTrace.cleanup`. You can check how we implement [`RSPACK_PROFILE` in `@rspack/cli`](https://github.com/web-infra-dev/rspack/blob/9be47217b5179186b0825ca79990ab2808aa1a0f/packages/rspack-cli/src/utils/profile.ts#L219-L224) for more information. -The generated `trace.json` file can be viewed and analyzed in [ui.perfetto.dev](https://ui.perfetto.dev/). +The generated `rspack.pftrace` file can be viewed and analyzed in [ui.perfetto.dev](https://ui.perfetto.dev/). ## Tracing Layer -Rspack supports two types of layers: `chrome` and `logger`: +Rspack supports two types of layers: `perfetto` and `logger`: -- `chrome`: The default value, generates a trace.json file conforming to the [`chrome trace event`](https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview?tab=t.0#heading=h.yr4qxyxotyw) format, which can be exported to perfetto for complex performance analysis +- `perfetto`: The default value, generates a rspack.pftrace file conforming to the [`perfetto proto`](https://perfetto.dev/docs/reference/synthetic-track-event) format, which can be exported to perfetto for complex performance analysis - `logger`: Outputs logs directly to the terminal, suitable for simple log analysis or viewing compilation processes in CI environments You can specify the layer through the `RSPACK_TRACE_LAYER` environment variable: @@ -34,7 +34,7 @@ You can specify the layer through the `RSPACK_TRACE_LAYER` environment variable: ```sh RSPACK_TRACE_LAYER=logger # or -RSPACK_TRACE_LAYER=chrome +RSPACK_TRACE_LAYER=perfetto ``` ## Tracing Output @@ -42,13 +42,13 @@ RSPACK_TRACE_LAYER=chrome You can specify the output location for traces: - The default output for the `logger` layer is `stdout` -- The default output for the `chrome` layer is `trace.json` +- The default output for the `perfetto` layer is `rspack.pftrace` You can customize the output location through the `RSPACK_TRACE_OUTPUT` environment variable: ```sh RSPACK_TRACE_LAYER=logger RSPACK_TRACE_OUTPUT=./log.txt rspack dev -RSPACK_TRACE_LAYER=chrome RSPACK_TRACE_OUTPUT=./perfetto.json rspack dev +RSPACK_TRACE_LAYER=perfetto RSPACK_TRACE_OUTPUT=./perfetto.pftrace rspack dev ``` ## Tracing Filter diff --git a/website/docs/zh/contribute/development/tracing.md b/website/docs/zh/contribute/development/tracing.md index c8800092bd17..534217e9dd6f 100644 --- a/website/docs/zh/contribute/development/tracing.md +++ b/website/docs/zh/contribute/development/tracing.md @@ -11,7 +11,7 @@ ```sh # Rspack CLI RSPACK_PROFILE=OVERVIEW rspack build # 推荐 -RSPACK_PROFILE=ALL rspack build # 不推荐，大项目的 trace.json 体积可能非常大 +RSPACK_PROFILE=ALL rspack build # 不推荐，大项目的 rspack.pftrace 体积可能非常大 # Rsbuild RSPACK_PROFILE=OVERVIEW rsbuild build @@ -20,13 +20,13 @@ RSPACK_PROFILE=ALL rsbuild build - 如果直接使用 `@rspack/core`：可通过 `rspack.experiments.globalTrace.register` 和 `rspack.experiments.globalTrace.cleanup` 开启。你可以查看我们如何在 [`@rspack/cli` 中实现 `RSPACK_PROFILE`](https://github.com/web-infra-dev/rspack/blob/9be47217b5179186b0825ca79990ab2808aa1a0f/packages/rspack-cli/src/utils/profile.ts#L219-L224)获取更多信息。 -生成的 `trace.json` 文件可以在 [ui.perfetto.dev](https://ui.perfetto.dev/) 中查看和分析。 +生成的 `rspack.pftrace` 文件可以在 [ui.perfetto.dev](https://ui.perfetto.dev/) 中查看和分析。 ## Tracing Layer -Rspack 支持 `chrome` 和 `logger` 两种 layer： +Rspack 支持 `perfetto` 和 `logger` 两种 layer： -- `chrome`：默认值，生成符合 [`chrome trace event`](https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview?tab=t.0#heading=h.yr4qxyxotyw) 格式的 trace.json 文件，可导出到 perfetto 进行复杂的性能分析 +- `perfetto`：默认值，生成符合 [`perfetto proto`](https://perfetto.dev/docs/reference/synthetic-track-event) 格式的 rspack.pftrace 文件，可导出到 perfetto 进行复杂的性能分析 - `logger`：直接在终端输出日志，适用于简单的日志分析或在 CI 环境中查看编译流程 可以通过 `RSPACK_TRACE_LAYER` 环境变量指定 layer： @@ -34,7 +34,7 @@ Rspack 支持 `chrome` 和 `logger` 两种 layer： ```sh RSPACK_TRACE_LAYER=logger # 或 -RSPACK_TRACE_LAYER=chrome +RSPACK_TRACE_LAYER=perfetto ``` ## Tracing Output @@ -42,13 +42,13 @@ RSPACK_TRACE_LAYER=chrome 可以指定 trace 的输出位置： - `logger` layer 的默认输出为 `stdout` -- `chrome` layer 的默认输出为 `trace.json` +- `perfetto` layer 的默认输出为 `rspack.pftrace` 通过 `RSPACK_TRACE_OUTPUT` 环境变量可以自定义输出位置： ```sh RSPACK_TRACE_LAYER=logger RSPACK_TRACE_OUTPUT=log.txt rspack dev -RSPACK_TRACE_LAYER=chrome RSPACK_TRACE_OUTPUT=perfetto.json rspack dev +RSPACK_TRACE_LAYER=perfetto RSPACK_TRACE_OUTPUT=perfetto.json rspack dev ``` ## Tracing Filter diff --git a/website/project-words.txt b/website/project-words.txt index 94af4368364f..06bcb9d1addf 100644 --- a/website/project-words.txt +++ b/website/project-words.txt @@ -136,6 +136,7 @@ outputlibraryamdcontainer outputlibraryumdnameddefine outputwasmloading perfetto +pftrace Peschke pmmmwh proxied