From 59d635548ad65103a42785f2025e8198b3a4c951 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?David=20Flemstr=C3=B6m?= Date: Tue, 29 Oct 2024 17:08:19 +0100 Subject: [PATCH 1/9] layer: Document intended behavior/API for layers, including counters --- crates/layer/src/lib.rs | 102 +++++++++++++++++++++++++++++++++++++++- 1 file changed, 101 insertions(+), 1 deletion(-) diff --git a/crates/layer/src/lib.rs b/crates/layer/src/lib.rs index 8bf8420..c3905ad 100644 --- a/crates/layer/src/lib.rs +++ b/crates/layer/src/lib.rs @@ -1,5 +1,105 @@ #![deny(clippy::all)] -/// # `tracing-perfetto-sdk-layer`: A tracing layer that reports traces via the C++ Perfetto SDK +//! # `tracing-perfetto-sdk-layer` +//! A suite of tracing layers that reports traces via the C++ Perfetto SDK +//! +//! There are currently two flavors of layers: +//! +//! * [`NativeLayer`]: Writes tracing data using Rust code, but can +//! additionally fetch further tracing data using the Perfetto SDK, e.g. via +//! the `traced` daemon. +//! * [`SdkLayer`]: Writes tracing data using the C++ SDK subroutines. The +//! SDK then decides how/if/when it interacts with other things in the +//! Perfetto ecosystem. +//! +//! You can easily add a layer into your existing `tracing-subscriber` stack: +//! +//! ```no_run +//! use std::{fs, thread, time}; +//! use tracing_subscriber::layer::SubscriberExt as _; +//! use tracing_perfetto_sdk_layer::NativeLayer; +//! +//! let out_file = "native-layer-example.pftrace"; +//! let trace_config = todo!(); +//! let out_file = fs::File::create(out_file)?; +//! let layer = NativeLayer::from_config(trace_config, out_file).build()?; +//! +//! let subscriber = tracing_subscriber::registry().with(layer); +//! +//! tracing::subscriber::with_default(subscriber, || { +//! tracing::info!(foo = "baz", int = 7, "hello trace!"); +//! +//! let span = tracing::info_span!("hi", foo = "bar", int = 3); +//! let guard = span.enter(); +//! thread::sleep(time::Duration::from_secs(1)); +//! drop(guard); +//! }); +//! ``` +//! +//! ## Using counters +//! +//! When logging trace events, such as when calling `tracing::info!()` and +//! similar macros, it is possible to additionally specify counters that will be +//! reported in the trace. +//! +//! Any field within the trace event can be a counter if it starts with the +//! `counter.` prefix and has a numeric value: +//! +//! ```no_run +//! tracing::info!(counter.mem_usage=42, counter.cpu_usage=23.2, "hi!"); +//! ``` +//! +//! It is recommended to specify the unit of the counter as the last +//! `.`-separated part of the field: +//! +//! ```no_run +//! tracing::info!(counter.mem_usage.bytes=42, counter.cpu_usage.percent=23.2, "hi!"); +//! ``` +//! +//! **NOTE**: at the time of writing, counters are only implemented by the +//! [`NativeLayer`]. +//! +//! ## Controlling output destinations +//! +//! For [`NativeLayer`], traces can be written to anything that implements the +//! [`tracing_subscriber::fmt::MakeWriter`] trait. It might be a good idea to +//! use the [`tracing_appender::non_blocking`] output if you want to defer the +//! writing to actual disk to a background thread. +//! +//! For [`SdkLayer`], since the write operation happens in C++ code, a real file +//! with an open file descriptor must be used instead. +//! +//! ## Tokio support +//! +//! If the `tokio` feature is enabled, the layers will be aware of spans coming +//! from the `tokio` runtime vs. normal OS threads. Spans coming from the +//! `tokio` runtime will be reported to a special `tokio-runtime` track. +//! +//! ## Forcing flavors +//! +//! The layers will report spans to Perfetto using either a sync or async +//! flavor: +//! +//! * The sync flavor implies that spans are reported when they are entered and +//! exited. +//! * The async flavor implies that spans are reported using RAII semantics, ie +//! upon construction and until they are dropped. +//! +//! By default, a heuristic is used to determine whether a span is sync or +//! async. A specific flavor can instead be forced using the +//! `.with_force_flavor` method on layer builders. +//! +//! ## In-process vs system mode +//! +//! By default, layers are configured to run in-process mode only. That means +//! that the only data sources that are consulted are the ones embedded in the +//! actual application binary. +//! +//! In addition, (or instead of) in-process mode, the system mode can be +//! activated too. This will (in the case of [`SdkLayer`]) write traces to the +//! system's `traced` daemon, or (in the case of [`NativeLayer`]) poll for +//! system-wide traces from the `traced` daemon and include them in the trace +//! file. + // Internal modules: mod debug_annotations; mod ffi_utils; From 22415ed41bc61c308f1dc13db16f31ae84280276 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?David=20Flemstr=C3=B6m?= Date: Tue, 29 Oct 2024 17:09:02 +0100 Subject: [PATCH 2/9] ids: Add namespace for counter names --- crates/layer/src/ids.rs | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/crates/layer/src/ids.rs b/crates/layer/src/ids.rs index 7062caf..b479f80 100644 --- a/crates/layer/src/ids.rs +++ b/crates/layer/src/ids.rs @@ -15,6 +15,7 @@ const THREAD_NS: u32 = 2; const TOKIO_NS: u32 = 3; #[cfg(feature = "tokio")] const TASK_NS: u32 = 4; +const COUNTER_NS: u32 = 5; #[derive(Clone, Copy, Debug, Default, Eq, Hash, Ord, PartialEq, PartialOrd)] #[repr(transparent)] @@ -44,6 +45,12 @@ impl TrackUuid { TrackUuid(h.finish()) } + pub fn for_counter(counter_name: &str) -> TrackUuid { + let mut h = hash::DefaultHasher::new(); + (TRACK_UUID_NS, COUNTER_NS, counter_name).hash(&mut h); + TrackUuid(h.finish()) + } + pub fn as_raw(self) -> u64 { self.0 } From e0deb3a282fc5b822f647e3891c41aa531277088 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?David=20Flemstr=C3=B6m?= Date: Tue, 29 Oct 2024 17:09:52 +0100 Subject: [PATCH 3/9] debug_annotations: Collect counter fields and store them aside --- crates/layer/src/debug_annotations.rs | 227 ++++++++++++++++++++------ 1 file changed, 173 insertions(+), 54 deletions(-) diff --git a/crates/layer/src/debug_annotations.rs b/crates/layer/src/debug_annotations.rs index 21fb68d..b07629f 100644 --- a/crates/layer/src/debug_annotations.rs +++ b/crates/layer/src/debug_annotations.rs @@ -1,12 +1,19 @@ //! Internal module used to collect span attrs as Perfetto SDK //! `DebugAnnotation`s + +use std::mem; + use schema::debug_annotation; use tracing::field; use tracing_perfetto_sdk_schema as schema; +use tracing_perfetto_sdk_schema::track_event; use tracing_perfetto_sdk_sys::ffi; +const COUNTER_FIELD_PREFIX: &str = "counter."; + #[derive(Default)] pub struct FFIDebugAnnotations { + counters: Vec, strings: Vec, bools: Vec, ints: Vec, @@ -15,9 +22,23 @@ pub struct FFIDebugAnnotations { #[derive(Clone, Debug, Default, PartialEq)] pub struct ProtoDebugAnnotations { + counters: Vec, annotations: Vec, } +#[derive(Clone, Debug, PartialEq)] +pub struct Counter { + pub name: &'static str, + pub unit: Option<&'static str>, + pub value: CounterValue, +} + +#[derive(Clone, Debug, PartialEq)] +pub enum CounterValue { + Float(f64), + Int(i64), +} + impl FFIDebugAnnotations { pub fn as_ffi(&self) -> ffi::DebugAnnotations { ffi::DebugAnnotations { @@ -27,30 +48,49 @@ impl FFIDebugAnnotations { doubles: self.doubles.as_slice(), } } + + pub fn take_counters(&mut self) -> Vec { + mem::take(&mut self.counters) + } } impl field::Visit for FFIDebugAnnotations { fn record_f64(&mut self, field: &field::Field, value: f64) { - self.doubles.push(ffi::DebugDoubleAnnotation { - key: field.name(), - value, - }); + if !populate_counter(&mut self.counters, field, value) { + self.doubles.push(ffi::DebugDoubleAnnotation { + key: field.name(), + value, + }); + } } fn record_i64(&mut self, field: &field::Field, value: i64) { - self.ints.push(ffi::DebugIntAnnotation { - key: field.name(), - value, - }); - } - - fn record_u64(&mut self, field: &field::Field, value: u64) { - if let Ok(v) = i64::try_from(value) { + if !populate_counter(&mut self.counters, field, value) { self.ints.push(ffi::DebugIntAnnotation { key: field.name(), - value: v, + value, }); - } else { + } + } + + fn record_u64(&mut self, field: &field::Field, value: u64) { + if !populate_counter(&mut self.counters, field, value) { + if let Ok(v) = i64::try_from(value) { + self.ints.push(ffi::DebugIntAnnotation { + key: field.name(), + value: v, + }); + } else { + self.strings.push(ffi::DebugStringAnnotation { + key: field.name(), + value: value.to_string(), + }); + } + } + } + + fn record_i128(&mut self, field: &field::Field, value: i128) { + if !populate_counter(&mut self.counters, field, value) { self.strings.push(ffi::DebugStringAnnotation { key: field.name(), value: value.to_string(), @@ -58,18 +98,13 @@ impl field::Visit for FFIDebugAnnotations { } } - fn record_i128(&mut self, field: &field::Field, value: i128) { - self.strings.push(ffi::DebugStringAnnotation { - key: field.name(), - value: value.to_string(), - }); - } - fn record_u128(&mut self, field: &field::Field, value: u128) { - self.strings.push(ffi::DebugStringAnnotation { - key: field.name(), - value: value.to_string(), - }); + if !populate_counter(&mut self.counters, field, value) { + self.strings.push(ffi::DebugStringAnnotation { + key: field.name(), + value: value.to_string(), + }); + } } fn record_bool(&mut self, field: &field::Field, value: bool) { @@ -106,6 +141,10 @@ impl ProtoDebugAnnotations { self.annotations } + pub fn take_counters(&mut self) -> Vec { + mem::take(&mut self.counters) + } + fn name_field(field: &field::Field) -> Option { Some(debug_annotation::NameField::Name(field.name().to_string())) } @@ -113,29 +152,45 @@ impl ProtoDebugAnnotations { impl field::Visit for ProtoDebugAnnotations { fn record_f64(&mut self, field: &field::Field, value: f64) { - self.annotations.push(schema::DebugAnnotation { - name_field: Self::name_field(field), - value: Some(debug_annotation::Value::DoubleValue(value)), - ..Default::default() - }); + if !populate_counter(&mut self.counters, field, value) { + self.annotations.push(schema::DebugAnnotation { + name_field: Self::name_field(field), + value: Some(debug_annotation::Value::DoubleValue(value)), + ..Default::default() + }); + } } fn record_i64(&mut self, field: &field::Field, value: i64) { - self.annotations.push(schema::DebugAnnotation { - name_field: Self::name_field(field), - value: Some(debug_annotation::Value::IntValue(value)), - ..Default::default() - }); - } - - fn record_u64(&mut self, field: &field::Field, value: u64) { - if let Ok(v) = i64::try_from(value) { + if !populate_counter(&mut self.counters, field, value) { self.annotations.push(schema::DebugAnnotation { name_field: Self::name_field(field), - value: Some(debug_annotation::Value::IntValue(v)), + value: Some(debug_annotation::Value::IntValue(value)), ..Default::default() }); - } else { + } + } + + fn record_u64(&mut self, field: &field::Field, value: u64) { + if !populate_counter(&mut self.counters, field, value) { + if let Ok(v) = i64::try_from(value) { + self.annotations.push(schema::DebugAnnotation { + name_field: Self::name_field(field), + value: Some(debug_annotation::Value::IntValue(v)), + ..Default::default() + }); + } else { + self.annotations.push(schema::DebugAnnotation { + name_field: Self::name_field(field), + value: Some(debug_annotation::Value::StringValue(value.to_string())), + ..Default::default() + }); + } + } + } + + fn record_i128(&mut self, field: &field::Field, value: i128) { + if !populate_counter(&mut self.counters, field, value) { self.annotations.push(schema::DebugAnnotation { name_field: Self::name_field(field), value: Some(debug_annotation::Value::StringValue(value.to_string())), @@ -144,20 +199,14 @@ impl field::Visit for ProtoDebugAnnotations { } } - fn record_i128(&mut self, field: &field::Field, value: i128) { - self.annotations.push(schema::DebugAnnotation { - name_field: Self::name_field(field), - value: Some(debug_annotation::Value::StringValue(value.to_string())), - ..Default::default() - }); - } - fn record_u128(&mut self, field: &field::Field, value: u128) { - self.annotations.push(schema::DebugAnnotation { - name_field: Self::name_field(field), - value: Some(debug_annotation::Value::StringValue(value.to_string())), - ..Default::default() - }); + if !populate_counter(&mut self.counters, field, value) { + self.annotations.push(schema::DebugAnnotation { + name_field: Self::name_field(field), + value: Some(debug_annotation::Value::StringValue(value.to_string())), + ..Default::default() + }); + } } fn record_bool(&mut self, field: &field::Field, value: bool) { @@ -192,3 +241,73 @@ impl field::Visit for ProtoDebugAnnotations { }); } } + +impl CounterValue { + pub fn to_proto(self) -> track_event::CounterValueField { + match self { + CounterValue::Float(v) => track_event::CounterValueField::DoubleCounterValue(v), + CounterValue::Int(v) => track_event::CounterValueField::CounterValue(v), + } + } +} + +impl From for CounterValue { + fn from(value: f64) -> Self { + CounterValue::Float(value) + } +} + +impl From for CounterValue { + fn from(value: i64) -> Self { + CounterValue::Int(value) + } +} + +impl From for CounterValue { + fn from(value: u64) -> Self { + if let Ok(v) = i64::try_from(value) { + CounterValue::Int(v) + } else { + CounterValue::Float(value as f64) + } + } +} + +impl From for CounterValue { + fn from(value: i128) -> Self { + if let Ok(v) = i64::try_from(value) { + CounterValue::Int(v) + } else { + CounterValue::Float(value as f64) + } + } +} + +impl From for CounterValue { + fn from(value: u128) -> Self { + if let Ok(v) = i64::try_from(value) { + CounterValue::Int(v) + } else { + CounterValue::Float(value as f64) + } + } +} + +fn populate_counter( + dest_counters: &mut Vec, + field: &field::Field, + value: impl Into, +) -> bool { + if let Some(name) = field.name().strip_prefix(COUNTER_FIELD_PREFIX) { + let (name, unit) = name + .rsplit_once('.') + .map(|(n, u)| (n, Some(u))) + .unwrap_or_else(|| (name, None)); + + let value = value.into(); + dest_counters.push(Counter { name, value, unit }); + true + } else { + false + } +} From ced63b8c88fc0d0af3d0149bd943f0c7d78aeb26 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?David=20Flemstr=C3=B6m?= Date: Tue, 29 Oct 2024 17:10:04 +0100 Subject: [PATCH 4/9] native_layer: Report collected counters --- crates/layer/src/native_layer.rs | 126 ++++++++++++++++++++++++++++++- 1 file changed, 123 insertions(+), 3 deletions(-) diff --git a/crates/layer/src/native_layer.rs b/crates/layer/src/native_layer.rs index 51bd867..efa8f82 100644 --- a/crates/layer/src/native_layer.rs +++ b/crates/layer/src/native_layer.rs @@ -7,7 +7,9 @@ use prost::encoding; use tokio::task; use tracing::span; use tracing_perfetto_sdk_schema as schema; -use tracing_perfetto_sdk_schema::{trace_packet, track_descriptor, track_event}; +use tracing_perfetto_sdk_schema::{ + counter_descriptor, trace_packet, track_descriptor, track_event, +}; use tracing_perfetto_sdk_sys::ffi; use tracing_subscriber::{fmt, layer, registry}; @@ -46,6 +48,12 @@ struct Inner { force_flavor: Option, process_track_uuid: ids::TrackUuid, process_descriptor_sent: atomic::AtomicBool, + // Mutex is held very briefly for member check and to insert a string if it is missing. + // We probably don't need a fancy data structure like `HashSet` or similar because this is + // expected to contain a small (<20 entries) set of short (<20 chars) strings, and they are + // all static (meaning high CPU cache coherence), so a linear scan + equals check is probably + // faster than hashing strings etc. + counters_sent: sync::Mutex>, #[cfg(feature = "tokio")] tokio_descriptor_sent: atomic::AtomicBool, #[cfg(feature = "tokio")] @@ -100,6 +108,7 @@ where let pid = process::id(); let process_track_uuid = ids::TrackUuid::for_process(pid); let process_descriptor_sent = atomic::AtomicBool::new(false); + let counters_sent = sync::Mutex::new(Vec::new()); #[cfg(feature = "tokio")] let tokio_descriptor_sent = atomic::AtomicBool::new(false); #[cfg(feature = "tokio")] @@ -113,6 +122,7 @@ where force_flavor, process_track_uuid, process_descriptor_sent, + counters_sent, #[cfg(feature = "tokio")] tokio_descriptor_sent, #[cfg(feature = "tokio")] @@ -294,6 +304,112 @@ where } } + fn report_counters(&self, meta: &tracing::Metadata, counters: Vec) { + if !counters.is_empty() { + self.ensure_counters_known(meta, &counters); + for counter in counters { + self.write_counter_event(meta, counter); + } + } + } + + fn ensure_counters_known( + &self, + meta: &tracing::Metadata, + counters: &[debug_annotations::Counter], + ) { + // This might seem wasteful, but we want to minimize the time that we hold the + // `counters_sent` mutex, and we can report the counters after we have released + // the lock. Also remember that `Vec::new()` does not allocate until the first + // push! + let mut new_counters = Vec::new(); + + // Skip counters entirely if Mutex is poisoned -- can't afford to panic here + if let Ok(mut counters_sent) = self.inner.counters_sent.lock() { + for counter in counters { + if !counters_sent.contains(&counter.name) { + new_counters.push(counter); + counters_sent.push(counter.name); + } + } + } + + for counter in new_counters { + self.write_counter_track_descriptor(meta, counter); + } + } + + fn write_counter_track_descriptor( + &self, + meta: &tracing::Metadata, + counter: &debug_annotations::Counter, + ) { + let (unit, unit_name) = if let Some(unit) = counter.unit { + Self::pick_unit_repr(unit) + } else { + (None, None) + }; + + let packet = schema::TracePacket { + data: Some(trace_packet::Data::TrackDescriptor( + schema::TrackDescriptor { + parent_uuid: Some(self.inner.process_track_uuid.as_raw()), + uuid: Some(ids::TrackUuid::for_counter(counter.name).as_raw()), + counter: Some(schema::CounterDescriptor { + unit_name, + unit, + ..Default::default() + }), + static_or_dynamic_name: Some(track_descriptor::StaticOrDynamicName::Name( + counter.name.to_owned(), + )), + ..Default::default() + }, + )), + ..Default::default() + }; + + self.write_packet(meta, packet); + } + + fn write_counter_event(&self, meta: &tracing::Metadata, counter: debug_annotations::Counter) { + let packet = schema::TracePacket { + timestamp: Some(ffi::trace_time_ns()), + data: Some(trace_packet::Data::TrackEvent(schema::TrackEvent { + r#type: Some(track_event::Type::Counter as i32), + track_uuid: Some(ids::TrackUuid::for_counter(counter.name).as_raw()), + counter_value_field: Some(counter.value.to_proto()), + ..Default::default() + })), + ..Default::default() + }; + self.write_packet(meta, packet); + } + + /// For a named unit, try to find an existing proto definition for that unit + /// and return as first return value, or else fall back to naming the unit + /// by name as the second return value. + fn pick_unit_repr(unit: &str) -> (Option, Option) { + // If there's a defined unit in the proto schema, use that: + Self::parse_unit(unit) + .map(|u| (Some(u as i32), None)) + .unwrap_or_else(|| { + // ...else, send the unit by name: + (None, Some(unit.to_owned())) + }) + } + + /// For a named unit, try to find an existing proto definition for that + /// unit. + fn parse_unit(name: &str) -> Option { + match name { + "time_ns" | "ns" | "nanos" | "nanoseconds" => Some(counter_descriptor::Unit::TimeNs), + "count" | "nr" => Some(counter_descriptor::Unit::Count), + "size_bytes" | "bytes" => Some(counter_descriptor::Unit::SizeBytes), + _ => None, + } + } + fn write_packet(&self, meta: &tracing::Metadata, packet: schema::TracePacket) { // The field tag of `packet` within the `Trace` proto message. const PACKET_FIELD_TAG: u32 = 1; @@ -392,14 +508,15 @@ where { fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: layer::Context<'_, S>) { let span = ctx.span(id).expect("span to be found (this is a bug)"); + let meta = span.metadata(); let (track_uuid, sequence_id, flavor) = self.pick_trace_track_sequence(); span.extensions_mut().insert(track_uuid); span.extensions_mut().insert(sequence_id); - let meta = span.metadata(); let mut debug_annotations = debug_annotations::ProtoDebugAnnotations::default(); attrs.record(&mut debug_annotations); + self.report_counters(meta, debug_annotations.take_counters()); span.extensions_mut().insert(debug_annotations.clone()); if flavor == flavor::Flavor::Async { @@ -409,12 +526,14 @@ where fn on_record(&self, id: &tracing::Id, values: &span::Record<'_>, ctx: layer::Context<'_, S>) { let span = ctx.span(id).expect("span to be found (this is a bug)"); + let meta = span.metadata(); let mut extensions = span.extensions_mut(); if let Some(debug_annotations) = extensions.get_mut::() { values.record(debug_annotations); + self.report_counters(meta, debug_annotations.take_counters()); } else { let mut debug_annotations = debug_annotations::ProtoDebugAnnotations::default(); values.record(&mut debug_annotations); @@ -423,10 +542,11 @@ where } fn on_event(&self, event: &tracing::Event<'_>, _ctx: layer::Context<'_, S>) { + let meta = event.metadata(); let mut debug_annotations = debug_annotations::ProtoDebugAnnotations::default(); event.record(&mut debug_annotations); + self.report_counters(meta, debug_annotations.take_counters()); - let meta = event.metadata(); let (track_uuid, sequence_id, _) = self.pick_trace_track_sequence(); let packet = schema::TracePacket { From 337f0390a5f6d647ecef8b5ab12db8f807c87eb0 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?David=20Flemstr=C3=B6m?= Date: Tue, 29 Oct 2024 17:10:15 +0100 Subject: [PATCH 5/9] kitchen_sink: Add basic assert that counter track is being collected --- crates/layer/tests/kitchen_sink.rs | 27 ++++++++++++++++++++++++++- 1 file changed, 26 insertions(+), 1 deletion(-) diff --git a/crates/layer/tests/kitchen_sink.rs b/crates/layer/tests/kitchen_sink.rs index d77e949..fa9351b 100644 --- a/crates/layer/tests/kitchen_sink.rs +++ b/crates/layer/tests/kitchen_sink.rs @@ -6,6 +6,7 @@ use tokio::{runtime, time}; use tracing::{info, span}; use tracing_perfetto_sdk_layer as layer; use tracing_perfetto_sdk_schema as schema; +use tracing_perfetto_sdk_schema::track_descriptor; use tracing_subscriber::fmt; use tracing_subscriber::fmt::format; @@ -61,7 +62,7 @@ data_sources: let demo_span = span!(tracing::Level::TRACE, "demo_span"); let enter = demo_span.enter(); - info!("in span"); + info!(counter.foo_counter.ms = 42, "in span"); sync_fn(1); sync_fn(2); let handle = runtime::Handle::current(); @@ -133,9 +134,33 @@ data_sources: assert_eq!(process_td.uuid, tokio_td.parent_uuid); + let counter_td = trace + .packet + .iter() + .find_map(|p| { + let td = as_track_descriptor(p)?; + if td_name(td) == "foo_counter" && td.counter.is_some() { + Some(td) + } else { + None + } + }) + .expect("to find a track descriptor for the foo_counter counter"); + + let counter_def = counter_td.counter.as_ref().unwrap(); + assert_eq!(counter_def.unit_name.as_ref().unwrap(), "ms"); + Ok(()) } +fn td_name(track_descriptor: &schema::TrackDescriptor) -> &str { + match track_descriptor.static_or_dynamic_name { + Some(track_descriptor::StaticOrDynamicName::Name(ref str)) => str, + Some(track_descriptor::StaticOrDynamicName::StaticName(ref str)) => str, + None => "", + } +} + fn as_track_descriptor(packet: &schema::TracePacket) -> Option<&schema::TrackDescriptor> { match packet.data { Some(trace_packet::Data::TrackDescriptor(ref td)) => Some(td), From 61150a0ad3de6980e823dc30d2ee62524a988527 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?David=20Flemstr=C3=B6m?= Date: Tue, 29 Oct 2024 17:13:54 +0100 Subject: [PATCH 6/9] kitchen_sink: Add assert that a counter event was received --- crates/layer/tests/kitchen_sink.rs | 24 +++++++++++++++++++++++- 1 file changed, 23 insertions(+), 1 deletion(-) diff --git a/crates/layer/tests/kitchen_sink.rs b/crates/layer/tests/kitchen_sink.rs index fa9351b..2efa04c 100644 --- a/crates/layer/tests/kitchen_sink.rs +++ b/crates/layer/tests/kitchen_sink.rs @@ -6,7 +6,7 @@ use tokio::{runtime, time}; use tracing::{info, span}; use tracing_perfetto_sdk_layer as layer; use tracing_perfetto_sdk_schema as schema; -use tracing_perfetto_sdk_schema::track_descriptor; +use tracing_perfetto_sdk_schema::{track_descriptor, track_event}; use tracing_subscriber::fmt; use tracing_subscriber::fmt::format; @@ -150,6 +150,21 @@ data_sources: let counter_def = counter_td.counter.as_ref().unwrap(); assert_eq!(counter_def.unit_name.as_ref().unwrap(), "ms"); + let counter_value_event = trace + .packet + .iter() + .find_map(|p| { + let te = as_track_event(p)?; + if let Some(ref counter_value) = te.counter_value_field { + Some(counter_value) + } else { + None + } + }) + .expect("to find a track event for a counter value"); + + assert_eq!(counter_value_event, &track_event::CounterValueField::CounterValue(42)); + Ok(()) } @@ -168,6 +183,13 @@ fn as_track_descriptor(packet: &schema::TracePacket) -> Option<&schema::TrackDes } } +fn as_track_event(packet: &schema::TracePacket) -> Option<&schema::TrackEvent> { + match packet.data { + Some(trace_packet::Data::TrackEvent(ref te)) => Some(te), + _ => None, + } +} + #[tracing::instrument] fn sync_fn(i: i32) { thread::sleep(time::Duration::from_millis(100)); From 32b8e4739e48eeb723a4005a9c5b85d18344d905 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?David=20Flemstr=C3=B6m?= Date: Tue, 29 Oct 2024 17:14:05 +0100 Subject: [PATCH 7/9] debug_annotations: Remove unused method --- crates/layer/src/debug_annotations.rs | 4 ---- 1 file changed, 4 deletions(-) diff --git a/crates/layer/src/debug_annotations.rs b/crates/layer/src/debug_annotations.rs index b07629f..005e99f 100644 --- a/crates/layer/src/debug_annotations.rs +++ b/crates/layer/src/debug_annotations.rs @@ -48,10 +48,6 @@ impl FFIDebugAnnotations { doubles: self.doubles.as_slice(), } } - - pub fn take_counters(&mut self) -> Vec { - mem::take(&mut self.counters) - } } impl field::Visit for FFIDebugAnnotations { From 7760cc3784b6f1532d644afe9bf5d3a1edd21eeb Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?David=20Flemstr=C3=B6m?= Date: Tue, 29 Oct 2024 17:14:24 +0100 Subject: [PATCH 8/9] crates: cargo fmt --- crates/layer/tests/kitchen_sink.rs | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/crates/layer/tests/kitchen_sink.rs b/crates/layer/tests/kitchen_sink.rs index 2efa04c..c035c28 100644 --- a/crates/layer/tests/kitchen_sink.rs +++ b/crates/layer/tests/kitchen_sink.rs @@ -163,7 +163,10 @@ data_sources: }) .expect("to find a track event for a counter value"); - assert_eq!(counter_value_event, &track_event::CounterValueField::CounterValue(42)); + assert_eq!( + counter_value_event, + &track_event::CounterValueField::CounterValue(42) + ); Ok(()) } From 92179627cd2aec4ee71b8b9fdef9661295687c28 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?David=20Flemstr=C3=B6m?= Date: Tue, 29 Oct 2024 17:15:39 +0100 Subject: [PATCH 9/9] layer: Fix example usage doctest compiler errors --- crates/layer/src/lib.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/crates/layer/src/lib.rs b/crates/layer/src/lib.rs index c3905ad..f66fcad 100644 --- a/crates/layer/src/lib.rs +++ b/crates/layer/src/lib.rs @@ -20,8 +20,8 @@ //! //! let out_file = "native-layer-example.pftrace"; //! let trace_config = todo!(); -//! let out_file = fs::File::create(out_file)?; -//! let layer = NativeLayer::from_config(trace_config, out_file).build()?; +//! let out_file = fs::File::create(out_file).unwrap(); +//! let layer = NativeLayer::from_config(trace_config, out_file).build().unwrap(); //! //! let subscriber = tracing_subscriber::registry().with(layer); //!