From 2d1e313d000f4410c5eef695e59f1cdf06879f3f Mon Sep 17 00:00:00 2001 From: Kyle Sabo Date: Mon, 9 Dec 2024 14:08:40 -0800 Subject: [PATCH] cargo fmt (#19) --- benches/etw.rs | 4 +- benches/user_events.rs | 4 +- examples/basic.rs | 52 +- examples/span.rs | 54 +- examples/stress.rs | 34 +- src/_details.rs | 40 +- src/bin/main.rs | 11 +- src/error.rs | 26 +- src/layer/filter.rs | 111 ++-- src/layer/layer_impl.rs | 600 +++++++++++---------- src/layer/mod.rs | 145 ++--- src/layer_builder.rs | 45 +- src/lib.rs | 46 +- src/native/common_schema/etw_cs.rs | 14 +- src/native/common_schema/user_events_cs.rs | 70 +-- src/native/etw.rs | 12 +- src/native/mod.rs | 4 +- src/native/user_events.rs | 72 +-- src/statics.rs | 464 ++++++++-------- 19 files changed, 899 insertions(+), 909 deletions(-) diff --git a/benches/etw.rs b/benches/etw.rs index d140f7c..33911e8 100644 --- a/benches/etw.rs +++ b/benches/etw.rs @@ -11,7 +11,9 @@ use tracing_subscriber::{self, prelude::*}; pub fn etw_benchmark(c: &mut Criterion) { let builder = LayerBuilder::new("etw_bench"); let provider_id = builder.get_provider_id(); - let _subscriber = tracing_subscriber::registry().with(builder.build().unwrap()).init(); + let _subscriber = tracing_subscriber::registry() + .with(builder.build().unwrap()) + .init(); let etw_session = SessionBuilder::new_file_mode( "tokio-tracing-etw-bench", diff --git a/benches/user_events.rs b/benches/user_events.rs index 49cbb3b..944a03a 100644 --- a/benches/user_events.rs +++ b/benches/user_events.rs @@ -8,7 +8,9 @@ use tracing_subscriber::{self, prelude::*}; #[cfg(target_os = "linux")] pub fn user_events_benchmark(c: &mut Criterion) { let builder = LayerBuilder::new("user_events_bench"); - let _subscriber = tracing_subscriber::registry().with(builder.build().unwrap()).init(); + let _subscriber = tracing_subscriber::registry() + .with(builder.build().unwrap()) + .init(); // Disabled provider // { diff --git a/examples/basic.rs b/examples/basic.rs index c9d564b..1fdb937 100644 --- a/examples/basic.rs +++ b/examples/basic.rs @@ -1,24 +1,28 @@ -use tracing::{event, Level}; -use tracing_etw::LayerBuilder; -use tracing_subscriber::{self, fmt::format::FmtSpan, prelude::*}; - -fn main() { - tracing_subscriber::registry() - .with(LayerBuilder::new("ExampleProvBasic").build().unwrap()) // Collects everything - .with(LayerBuilder::new_common_schema_events("ExampleProvBasic_CS").build_with_target("geneva").unwrap()) - .with(tracing_subscriber::fmt::layer().with_span_events(FmtSpan::ACTIVE)) - .init(); - - #[allow(non_snake_case)] - let fieldB = "asdf"; - event!( - Level::INFO, - fieldC = b'x', - fieldB, - fieldA = 7, - "inside {}!", - "main" - ); - - event!(target: "geneva", Level::ERROR, "error event"); -} +use tracing::{event, Level}; +use tracing_etw::LayerBuilder; +use tracing_subscriber::{self, fmt::format::FmtSpan, prelude::*}; + +fn main() { + tracing_subscriber::registry() + .with(LayerBuilder::new("ExampleProvBasic").build().unwrap()) // Collects everything + .with( + LayerBuilder::new_common_schema_events("ExampleProvBasic_CS") + .build_with_target("geneva") + .unwrap(), + ) + .with(tracing_subscriber::fmt::layer().with_span_events(FmtSpan::ACTIVE)) + .init(); + + #[allow(non_snake_case)] + let fieldB = "asdf"; + event!( + Level::INFO, + fieldC = b'x', + fieldB, + fieldA = 7, + "inside {}!", + "main" + ); + + event!(target: "geneva", Level::ERROR, "error event"); +} diff --git a/examples/span.rs b/examples/span.rs index a24e08a..f63d521 100644 --- a/examples/span.rs +++ b/examples/span.rs @@ -1,25 +1,29 @@ -use tracing::{event, span, Level}; -use tracing_etw::LayerBuilder; -use tracing_subscriber::{self, fmt::format::FmtSpan, prelude::*}; - -fn main() { - tracing_subscriber::registry() - .with(LayerBuilder::new_common_schema_events("ExampleProvSpan_CS").build().unwrap()) - .with(tracing_subscriber::fmt::layer().with_span_events(FmtSpan::ACTIVE)) - .init(); - - let span = span!( - Level::INFO, - "span name", - fieldC = b'x', - fieldB = "asdf", - fieldA = 7, - "inside {}!", - "main" - ); - let _ = span.enter(); - - event!(Level::ERROR, "error event"); - - span.record("fieldB", 12345); -} +use tracing::{event, span, Level}; +use tracing_etw::LayerBuilder; +use tracing_subscriber::{self, fmt::format::FmtSpan, prelude::*}; + +fn main() { + tracing_subscriber::registry() + .with( + LayerBuilder::new_common_schema_events("ExampleProvSpan_CS") + .build() + .unwrap(), + ) + .with(tracing_subscriber::fmt::layer().with_span_events(FmtSpan::ACTIVE)) + .init(); + + let span = span!( + Level::INFO, + "span name", + fieldC = b'x', + fieldB = "asdf", + fieldA = 7, + "inside {}!", + "main" + ); + let _ = span.enter(); + + event!(Level::ERROR, "error event"); + + span.record("fieldB", 12345); +} diff --git a/examples/stress.rs b/examples/stress.rs index 14933e2..a275828 100644 --- a/examples/stress.rs +++ b/examples/stress.rs @@ -1,15 +1,19 @@ -use tracing::Level; -use tracing_etw::{etw_event, LayerBuilder}; -use tracing_subscriber::{self, prelude::*}; - -fn main() { - tracing_subscriber::registry() - .with(LayerBuilder::new("ExampleProvEtwEventStress").build().unwrap()) - .init(); - - for i in 0..500000 { - etw_event!(name: "EtwEventName", Level::ERROR, 5, "An event with a name and keyword!"); - - etw_event!(name: "Event2", Level::ERROR, 5, idx=i,a=1,b=2,c=3,d=4,e=5,f=6,g=7,h=8,i=9,j=10,k=11,l=12,m=13,n=14,o=15,p=16,q=17,r=18,s=19,t=20,u=21,v=22,w=23,x=24,y=25,z=26); - } -} +use tracing::Level; +use tracing_etw::{etw_event, LayerBuilder}; +use tracing_subscriber::{self, prelude::*}; + +fn main() { + tracing_subscriber::registry() + .with( + LayerBuilder::new("ExampleProvEtwEventStress") + .build() + .unwrap(), + ) + .init(); + + for i in 0..500000 { + etw_event!(name: "EtwEventName", Level::ERROR, 5, "An event with a name and keyword!"); + + etw_event!(name: "Event2", Level::ERROR, 5, idx=i,a=1,b=2,c=3,d=4,e=5,f=6,g=7,h=8,i=9,j=10,k=11,l=12,m=13,n=14,o=15,p=16,q=17,r=18,s=19,t=20,u=21,v=22,w=23,x=24,y=25,z=26); + } +} diff --git a/src/_details.rs b/src/_details.rs index 13d681a..649c3b2 100644 --- a/src/_details.rs +++ b/src/_details.rs @@ -1,20 +1,20 @@ -// Module for internal structs that need to be publicly accessible, -// but should not be directly used by consumers of the crate. -// -// Implementations for these structs are contained in other files. - -// Public with public fields because the `etw_event!` macro needs to create it at invocation site. -#[doc(hidden)] -#[repr(C)] -pub struct EventMetadata { - pub kw: u64, - pub identity: tracing::callsite::Identifier, - pub event_tag: u32, -} - -// An EventMetadata with a hash, because Identity doesn't implement comparisons but we need a stable ordering. -#[derive(Clone)] -pub(crate) struct ParsedEventMetadata { - pub(crate) identity_hash: u64, - pub(crate) meta: &'static EventMetadata -} +// Module for internal structs that need to be publicly accessible, +// but should not be directly used by consumers of the crate. +// +// Implementations for these structs are contained in other files. + +// Public with public fields because the `etw_event!` macro needs to create it at invocation site. +#[doc(hidden)] +#[repr(C)] +pub struct EventMetadata { + pub kw: u64, + pub identity: tracing::callsite::Identifier, + pub event_tag: u32, +} + +// An EventMetadata with a hash, because Identity doesn't implement comparisons but we need a stable ordering. +#[derive(Clone)] +pub(crate) struct ParsedEventMetadata { + pub(crate) identity_hash: u64, + pub(crate) meta: &'static EventMetadata, +} diff --git a/src/bin/main.rs b/src/bin/main.rs index 8f780b2..8a3dcd3 100644 --- a/src/bin/main.rs +++ b/src/bin/main.rs @@ -15,10 +15,15 @@ fn main() { #[cfg(not(feature = "global_filter"))] let registry = registry.with(LayerBuilder::new("test").build().unwrap()); #[cfg(all(not(feature = "global_filter"), feature = "common_schema"))] - let registry = registry.with(LayerBuilder::new_common_schema_events("test2").build_with_target("geneva").unwrap()); + let registry = registry.with( + LayerBuilder::new_common_schema_events("test2") + .build_with_target("geneva") + .unwrap(), + ); #[cfg(not(feature = "global_filter"))] - let registry = registry.with(tracing_subscriber::fmt::layer().with_span_events(FmtSpan::ACTIVE)); - + let registry = + registry.with(tracing_subscriber::fmt::layer().with_span_events(FmtSpan::ACTIVE)); + #[cfg(feature = "global_filter")] let registry = registry.with(LayerBuilder::new("test").build_global_filter().unwrap()); diff --git a/src/error.rs b/src/error.rs index fb46e1e..656a04c 100644 --- a/src/error.rs +++ b/src/error.rs @@ -1,13 +1,13 @@ -use thiserror::Error; - -#[derive(Error, Debug)] -pub enum EtwError { - #[error("Provider group GUID must not be zeros")] - EmptyProviderGroupGuid, - #[error("Provider group names must be lower case ASCII or numeric digits: {0:?}")] - InvalidProviderGroupCharacters(String), - #[error("Linux provider names must be ASCII alphanumeric: {0:?}")] - InvalidProviderNameCharacters(String), - #[error("Linux provider name and provider group must less than 234 characters combined. Current length: {0:?}")] - TooManyCharacters(usize) -} +use thiserror::Error; + +#[derive(Error, Debug)] +pub enum EtwError { + #[error("Provider group GUID must not be zeros")] + EmptyProviderGroupGuid, + #[error("Provider group names must be lower case ASCII or numeric digits: {0:?}")] + InvalidProviderGroupCharacters(String), + #[error("Linux provider names must be ASCII alphanumeric: {0:?}")] + InvalidProviderNameCharacters(String), + #[error("Linux provider name and provider group must less than 234 characters combined. Current length: {0:?}")] + TooManyCharacters(usize), +} diff --git a/src/layer/filter.rs b/src/layer/filter.rs index 9478670..c5e2f25 100644 --- a/src/layer/filter.rs +++ b/src/layer/filter.rs @@ -1,53 +1,58 @@ -use tracing::Subscriber; -use tracing_subscriber::{layer::Filter, registry::LookupSpan}; - -use crate::{native::{EventWriter, ProviderTypes}, statics::get_event_metadata}; - -use super::*; - -impl Filter for EtwFilter -where - S: Subscriber + for<'a> LookupSpan<'a>, - Mode: ProviderTypes + 'static, - Mode::Provider: EventWriter + 'static, -{ - fn callsite_enabled( - &self, - metadata: &'static tracing::Metadata<'static>, - ) -> tracing::subscriber::Interest { - let etw_meta = get_event_metadata(&metadata.callsite()); - let keyword = if let Some(meta) = etw_meta { - meta.kw - } else { - self.layer.default_keyword - }; - - if Mode::supports_enable_callback() { - if self.layer.provider.enabled(metadata.level(), keyword) { - tracing::subscriber::Interest::always() - } else { - tracing::subscriber::Interest::never() - } - } else { - // Returning "sometimes" means the enabled function will be called every time an event or span is created from the callsite. - // This will let us perform a global "is enabled" check each time. - tracing::subscriber::Interest::sometimes() - } - } - - fn enabled( - &self, - metadata: &tracing::Metadata<'_>, - _cx: &tracing_subscriber::layer::Context<'_, S>, - ) -> bool { - self.layer.is_enabled(&metadata.callsite(), metadata.level()) - } - - fn event_enabled( - &self, - event: &tracing::Event<'_>, - _cx: &tracing_subscriber::layer::Context<'_, S>, - ) -> bool { - self.layer.is_enabled(&event.metadata().callsite(), event.metadata().level()) - } -} +use tracing::Subscriber; +use tracing_subscriber::{layer::Filter, registry::LookupSpan}; + +use crate::{ + native::{EventWriter, ProviderTypes}, + statics::get_event_metadata, +}; + +use super::*; + +impl Filter for EtwFilter +where + S: Subscriber + for<'a> LookupSpan<'a>, + Mode: ProviderTypes + 'static, + Mode::Provider: EventWriter + 'static, +{ + fn callsite_enabled( + &self, + metadata: &'static tracing::Metadata<'static>, + ) -> tracing::subscriber::Interest { + let etw_meta = get_event_metadata(&metadata.callsite()); + let keyword = if let Some(meta) = etw_meta { + meta.kw + } else { + self.layer.default_keyword + }; + + if Mode::supports_enable_callback() { + if self.layer.provider.enabled(metadata.level(), keyword) { + tracing::subscriber::Interest::always() + } else { + tracing::subscriber::Interest::never() + } + } else { + // Returning "sometimes" means the enabled function will be called every time an event or span is created from the callsite. + // This will let us perform a global "is enabled" check each time. + tracing::subscriber::Interest::sometimes() + } + } + + fn enabled( + &self, + metadata: &tracing::Metadata<'_>, + _cx: &tracing_subscriber::layer::Context<'_, S>, + ) -> bool { + self.layer + .is_enabled(&metadata.callsite(), metadata.level()) + } + + fn event_enabled( + &self, + event: &tracing::Event<'_>, + _cx: &tracing_subscriber::layer::Context<'_, S>, + ) -> bool { + self.layer + .is_enabled(&event.metadata().callsite(), event.metadata().level()) + } +} diff --git a/src/layer/layer_impl.rs b/src/layer/layer_impl.rs index 8078f94..c5871df 100644 --- a/src/layer/layer_impl.rs +++ b/src/layer/layer_impl.rs @@ -1,297 +1,303 @@ -use std::time::SystemTime; - -use tracing::Subscriber; -#[allow(unused_imports)] // Many imports are used exclusively by feature-gated code -use tracing_core::{callsite, span}; -use tracing_subscriber::{registry::LookupSpan, Layer}; - -use crate::{native::{EventWriter, ProviderTypes}, statics::*, values::*}; - -use super::*; - -struct SpanData { - fields: Box<[FieldValueIndex]>, - activity_id: [u8; 16], // // if set, byte 0 is 1 and 64-bit span ID in the lower 8 bytes - related_activity_id: [u8; 16], // if set, byte 0 is 1 and 64-bit span ID in the lower 8 bytes - start_time: SystemTime, -} - -impl Layer for EtwLayer -where - S: Subscriber + for<'a> LookupSpan<'a>, - Mode: ProviderTypes + 'static, - Mode::Provider: EventWriter + 'static, -{ - fn on_register_dispatch(&self, _collector: &tracing::Dispatch) { - // Late init when the layer is installed as a subscriber - } - - fn on_layer(&mut self, _subscriber: &mut S) { - // Late init when the layer is attached to a subscriber - } - - #[cfg(any(feature = "global_filter", docsrs))] - fn register_callsite( - &self, - metadata: &'static tracing::Metadata<'static>, - ) -> tracing::subscriber::Interest { - let etw_meta = get_event_metadata(&metadata.callsite()); - let keyword = if let Some(meta) = etw_meta { - meta.kw - } else { - self.layer.default_keyword - }; - - if Mode::supports_enable_callback() { - if self.layer.provider.enabled(metadata.level(), keyword) { - tracing::subscriber::Interest::always() - } else { - tracing::subscriber::Interest::never() - } - } else { - // Returning "sometimes" means the enabled function will be called every time an event or span is created from the callsite. - // This will let us perform a global "is enabled" check each time. - tracing::subscriber::Interest::sometimes() - } - } - - #[cfg(any(feature = "global_filter", docsrs))] - fn enabled( - &self, - metadata: &tracing::Metadata<'_>, - _ctx: tracing_subscriber::layer::Context<'_, S>, - ) -> bool { - self.layer.is_enabled(&metadata.callsite(), metadata.level()) - } - - #[cfg(any(feature = "global_filter", docsrs))] - fn event_enabled( - &self, - event: &tracing::Event<'_>, - _ctx: tracing_subscriber::layer::Context<'_, S>, - ) -> bool { - self.layer.is_enabled(&event.metadata().callsite(), event.metadata().level()) - } - - fn on_event(&self, event: &tracing::Event<'_>, ctx: tracing_subscriber::layer::Context<'_, S>) { - let timestamp = std::time::SystemTime::now(); - - let current_span = ctx - .event_span(event) - .map(|evt| evt.id()) - .map_or(0, |id| (id.into_u64())); - let parent_span = ctx - .event_span(event) - .map_or(0, |evt| evt.parent().map_or(0, |p| p.id().into_u64())); - - let etw_meta = get_event_metadata(&event.metadata().callsite()); - let (name, keyword, tag) = if let Some(meta) = etw_meta { - (event.metadata().name(), meta.kw, meta.event_tag) - } else { - (event.metadata().name(), self.layer.default_keyword, 0) - }; - - self.layer.provider.as_ref().write_record( - timestamp, - current_span, - parent_span, - name, - event.metadata().level(), - keyword, - tag, - event, - ); - } - - fn on_new_span( - &self, - attrs: &span::Attributes<'_>, - id: &span::Id, - ctx: tracing_subscriber::layer::Context<'_, S>, - ) { - let span = if let Some(span) = ctx.span(id) { - span - } else { - return; - }; - - if span.extensions().get::().is_some() { - return; - } - - let metadata = span.metadata(); - - let parent_span_id = if attrs.is_contextual() { - attrs.parent().map_or(0, |id| id.into_u64()) - } else { - 0 - }; - - let n = metadata.fields().len(); - - let mut data = { - let mut v: Vec = Vec::with_capacity(n); - v.resize_with(n, Default::default); - - let mut i = 0; - for field in metadata.fields().iter() { - v[i].field = field.name(); - v[i].value = ValueTypes::None; - v[i].sort_index = i as u8; - i += 1; - } - - let mut indexes: [u8; 32] = [ - 0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, - 23, 24, 25, 26, 27, 28, 29, 30, 31, - ]; - - indexes[0..n].sort_by_key(|idx| v[v[*idx as usize].sort_index as usize].field); - - i = 0; - for f in &mut v { - f.sort_index = indexes[i]; - i += 1; - } - - SpanData { - fields: v.into_boxed_slice(), - activity_id: *GLOBAL_ACTIVITY_SEED, - related_activity_id: *GLOBAL_ACTIVITY_SEED, - start_time: SystemTime::UNIX_EPOCH, - } - }; - - let (_, half) = data.activity_id.split_at_mut(8); - half.copy_from_slice(&id.into_u64().to_le_bytes()); - - data.activity_id[0] = 1; - data.related_activity_id[0] = if parent_span_id != 0 { - let (_, half) = data.related_activity_id.split_at_mut(8); - half.copy_from_slice(&parent_span_id.to_le_bytes()); - 1 - } else { - 0 - }; - - attrs.values().record(&mut ValueVisitor { - fields: &mut data.fields, - }); - - // This will unfortunately box data. It would be ideal if we could avoid this second heap allocation - // by packing everything into a single alloc. - span.extensions_mut().replace(data); - } - - fn on_enter(&self, id: &span::Id, ctx: tracing_subscriber::layer::Context<'_, S>) { - // A span was started - let timestamp = std::time::SystemTime::now(); - - let span = if let Some(span) = ctx.span(id) { - span - } else { - return; - }; - - let metadata = span.metadata(); - - let mut extensions = span.extensions_mut(); - let data = if let Some(data) = extensions.get_mut::() { - data - } else { - // We got a span that was entered without being new'ed? - return; - }; - - let etw_meta = get_event_metadata(&metadata.callsite()); - let (keyword, tag) = if let Some(meta) = etw_meta { - (meta.kw, meta.event_tag) - } else { - (self.layer.default_keyword, 0) - }; - - self.layer.provider.as_ref().span_start( - &span, - timestamp, - &data.activity_id, - &data.related_activity_id, - &data.fields, - metadata.level(), - keyword, - tag, - ); - - data.start_time = timestamp; - } - - fn on_exit(&self, id: &span::Id, ctx: tracing_subscriber::layer::Context<'_, S>) { - // A span was exited - let stop_timestamp = std::time::SystemTime::now(); - - let span = if let Some(span) = ctx.span(id) { - span - } else { - return; - }; - - let metadata = span.metadata(); - - let mut extensions = span.extensions_mut(); - let data = if let Some(data) = extensions.get_mut::() { - data - } else { - // We got a span that was entered without being new'ed? - return; - }; - - let etw_meta = get_event_metadata(&metadata.callsite()); - let (keyword, tag) = if let Some(meta) = etw_meta { - (meta.kw, meta.event_tag) - } else { - (self.layer.default_keyword, 0) - }; - - self.layer.provider.as_ref().span_stop( - &span, - (data.start_time, stop_timestamp), - &data.activity_id, - &data.related_activity_id, - &data.fields, - metadata.level(), - keyword, - tag, - ); - } - - fn on_close(&self, _id: span::Id, _ctx: tracing_subscriber::layer::Context<'_, S>) { - // A span was closed - // Good for knowing when to log a summary event? - } - - fn on_record( - &self, - id: &span::Id, - values: &span::Record<'_>, - ctx: tracing_subscriber::layer::Context<'_, S>, - ) { - // Values were added to the given span - - let span = if let Some(span) = ctx.span(id) { - span - } else { - return; - }; - - let mut extensions = span.extensions_mut(); - let data = if let Some(data) = extensions.get_mut::() { - data - } else { - // We got a span that was entered without being new'ed? - return; - }; - - values.record(&mut ValueVisitor { - fields: &mut data.fields, - }); - } -} +use std::time::SystemTime; + +use tracing::Subscriber; +#[allow(unused_imports)] // Many imports are used exclusively by feature-gated code +use tracing_core::{callsite, span}; +use tracing_subscriber::{registry::LookupSpan, Layer}; + +use crate::{ + native::{EventWriter, ProviderTypes}, + statics::*, + values::*, +}; + +use super::*; + +struct SpanData { + fields: Box<[FieldValueIndex]>, + activity_id: [u8; 16], // // if set, byte 0 is 1 and 64-bit span ID in the lower 8 bytes + related_activity_id: [u8; 16], // if set, byte 0 is 1 and 64-bit span ID in the lower 8 bytes + start_time: SystemTime, +} + +impl Layer for EtwLayer +where + S: Subscriber + for<'a> LookupSpan<'a>, + Mode: ProviderTypes + 'static, + Mode::Provider: EventWriter + 'static, +{ + fn on_register_dispatch(&self, _collector: &tracing::Dispatch) { + // Late init when the layer is installed as a subscriber + } + + fn on_layer(&mut self, _subscriber: &mut S) { + // Late init when the layer is attached to a subscriber + } + + #[cfg(any(feature = "global_filter", docsrs))] + fn register_callsite( + &self, + metadata: &'static tracing::Metadata<'static>, + ) -> tracing::subscriber::Interest { + let etw_meta = get_event_metadata(&metadata.callsite()); + let keyword = if let Some(meta) = etw_meta { + meta.kw + } else { + self.layer.default_keyword + }; + + if Mode::supports_enable_callback() { + if self.layer.provider.enabled(metadata.level(), keyword) { + tracing::subscriber::Interest::always() + } else { + tracing::subscriber::Interest::never() + } + } else { + // Returning "sometimes" means the enabled function will be called every time an event or span is created from the callsite. + // This will let us perform a global "is enabled" check each time. + tracing::subscriber::Interest::sometimes() + } + } + + #[cfg(any(feature = "global_filter", docsrs))] + fn enabled( + &self, + metadata: &tracing::Metadata<'_>, + _ctx: tracing_subscriber::layer::Context<'_, S>, + ) -> bool { + self.layer + .is_enabled(&metadata.callsite(), metadata.level()) + } + + #[cfg(any(feature = "global_filter", docsrs))] + fn event_enabled( + &self, + event: &tracing::Event<'_>, + _ctx: tracing_subscriber::layer::Context<'_, S>, + ) -> bool { + self.layer + .is_enabled(&event.metadata().callsite(), event.metadata().level()) + } + + fn on_event(&self, event: &tracing::Event<'_>, ctx: tracing_subscriber::layer::Context<'_, S>) { + let timestamp = std::time::SystemTime::now(); + + let current_span = ctx + .event_span(event) + .map(|evt| evt.id()) + .map_or(0, |id| (id.into_u64())); + let parent_span = ctx + .event_span(event) + .map_or(0, |evt| evt.parent().map_or(0, |p| p.id().into_u64())); + + let etw_meta = get_event_metadata(&event.metadata().callsite()); + let (name, keyword, tag) = if let Some(meta) = etw_meta { + (event.metadata().name(), meta.kw, meta.event_tag) + } else { + (event.metadata().name(), self.layer.default_keyword, 0) + }; + + self.layer.provider.as_ref().write_record( + timestamp, + current_span, + parent_span, + name, + event.metadata().level(), + keyword, + tag, + event, + ); + } + + fn on_new_span( + &self, + attrs: &span::Attributes<'_>, + id: &span::Id, + ctx: tracing_subscriber::layer::Context<'_, S>, + ) { + let span = if let Some(span) = ctx.span(id) { + span + } else { + return; + }; + + if span.extensions().get::().is_some() { + return; + } + + let metadata = span.metadata(); + + let parent_span_id = if attrs.is_contextual() { + attrs.parent().map_or(0, |id| id.into_u64()) + } else { + 0 + }; + + let n = metadata.fields().len(); + + let mut data = { + let mut v: Vec = Vec::with_capacity(n); + v.resize_with(n, Default::default); + + let mut i = 0; + for field in metadata.fields().iter() { + v[i].field = field.name(); + v[i].value = ValueTypes::None; + v[i].sort_index = i as u8; + i += 1; + } + + let mut indexes: [u8; 32] = [ + 0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, + 23, 24, 25, 26, 27, 28, 29, 30, 31, + ]; + + indexes[0..n].sort_by_key(|idx| v[v[*idx as usize].sort_index as usize].field); + + i = 0; + for f in &mut v { + f.sort_index = indexes[i]; + i += 1; + } + + SpanData { + fields: v.into_boxed_slice(), + activity_id: *GLOBAL_ACTIVITY_SEED, + related_activity_id: *GLOBAL_ACTIVITY_SEED, + start_time: SystemTime::UNIX_EPOCH, + } + }; + + let (_, half) = data.activity_id.split_at_mut(8); + half.copy_from_slice(&id.into_u64().to_le_bytes()); + + data.activity_id[0] = 1; + data.related_activity_id[0] = if parent_span_id != 0 { + let (_, half) = data.related_activity_id.split_at_mut(8); + half.copy_from_slice(&parent_span_id.to_le_bytes()); + 1 + } else { + 0 + }; + + attrs.values().record(&mut ValueVisitor { + fields: &mut data.fields, + }); + + // This will unfortunately box data. It would be ideal if we could avoid this second heap allocation + // by packing everything into a single alloc. + span.extensions_mut().replace(data); + } + + fn on_enter(&self, id: &span::Id, ctx: tracing_subscriber::layer::Context<'_, S>) { + // A span was started + let timestamp = std::time::SystemTime::now(); + + let span = if let Some(span) = ctx.span(id) { + span + } else { + return; + }; + + let metadata = span.metadata(); + + let mut extensions = span.extensions_mut(); + let data = if let Some(data) = extensions.get_mut::() { + data + } else { + // We got a span that was entered without being new'ed? + return; + }; + + let etw_meta = get_event_metadata(&metadata.callsite()); + let (keyword, tag) = if let Some(meta) = etw_meta { + (meta.kw, meta.event_tag) + } else { + (self.layer.default_keyword, 0) + }; + + self.layer.provider.as_ref().span_start( + &span, + timestamp, + &data.activity_id, + &data.related_activity_id, + &data.fields, + metadata.level(), + keyword, + tag, + ); + + data.start_time = timestamp; + } + + fn on_exit(&self, id: &span::Id, ctx: tracing_subscriber::layer::Context<'_, S>) { + // A span was exited + let stop_timestamp = std::time::SystemTime::now(); + + let span = if let Some(span) = ctx.span(id) { + span + } else { + return; + }; + + let metadata = span.metadata(); + + let mut extensions = span.extensions_mut(); + let data = if let Some(data) = extensions.get_mut::() { + data + } else { + // We got a span that was entered without being new'ed? + return; + }; + + let etw_meta = get_event_metadata(&metadata.callsite()); + let (keyword, tag) = if let Some(meta) = etw_meta { + (meta.kw, meta.event_tag) + } else { + (self.layer.default_keyword, 0) + }; + + self.layer.provider.as_ref().span_stop( + &span, + (data.start_time, stop_timestamp), + &data.activity_id, + &data.related_activity_id, + &data.fields, + metadata.level(), + keyword, + tag, + ); + } + + fn on_close(&self, _id: span::Id, _ctx: tracing_subscriber::layer::Context<'_, S>) { + // A span was closed + // Good for knowing when to log a summary event? + } + + fn on_record( + &self, + id: &span::Id, + values: &span::Record<'_>, + ctx: tracing_subscriber::layer::Context<'_, S>, + ) { + // Values were added to the given span + + let span = if let Some(span) = ctx.span(id) { + span + } else { + return; + }; + + let mut extensions = span.extensions_mut(); + let data = if let Some(data) = extensions.get_mut::() { + data + } else { + // We got a span that was entered without being new'ed? + return; + }; + + values.record(&mut ValueVisitor { + fields: &mut data.fields, + }); + } +} diff --git a/src/layer/mod.rs b/src/layer/mod.rs index 5a285d0..b759480 100644 --- a/src/layer/mod.rs +++ b/src/layer/mod.rs @@ -1,71 +1,74 @@ -mod layer_impl; - -#[cfg(any(not(feature = "global_filter"), docsrs))] -mod filter; - -use std::{marker::PhantomData, pin::Pin, sync::Arc}; - -use tracing::Subscriber; -use tracing_core::callsite; -use tracing_subscriber::registry::LookupSpan; - -use crate::{native::{EventWriter, ProviderTypes}, statics::get_event_metadata}; - -pub(crate) struct _EtwLayer -where - Mode::Provider: crate::native::EventWriter + 'static -{ - pub(crate) provider: Pin>, - pub(crate) default_keyword: u64, - pub(crate) _p: PhantomData, -} - -impl Clone for _EtwLayer -where - Mode::Provider: crate::native::EventWriter + 'static -{ - fn clone(&self) -> Self { - _EtwLayer { - provider: self.provider.clone(), - default_keyword: self.default_keyword, - _p: PhantomData - } - } -} - -// This struct needs to be public as it implements the tracing_subscriber::Layer and tracing_subscriber::Layer::Filter traits. -#[doc(hidden)] -pub struct EtwLayer -where - Mode::Provider: EventWriter + 'static -{ - pub(crate) layer: _EtwLayer -} - -// This struct needs to be public as it implements the tracing_subscriber::Layer::Filter trait. -#[doc(hidden)] -#[cfg(any(not(feature = "global_filter"), docsrs))] -pub struct EtwFilter -where - Mode::Provider: EventWriter + 'static -{ - pub(crate) layer: _EtwLayer -} - -impl _EtwLayer -where - S: Subscriber + for<'a> LookupSpan<'a>, - Mode: ProviderTypes + 'static, - Mode::Provider: EventWriter + 'static, -{ - fn is_enabled(&self, callsite: &callsite::Identifier, level: &tracing_core::Level) -> bool { - let etw_meta = get_event_metadata(callsite); - let keyword = if let Some(meta) = etw_meta { - meta.kw - } else { - self.default_keyword - }; - - self.provider.enabled(level, keyword) - } -} +mod layer_impl; + +#[cfg(any(not(feature = "global_filter"), docsrs))] +mod filter; + +use std::{marker::PhantomData, pin::Pin, sync::Arc}; + +use tracing::Subscriber; +use tracing_core::callsite; +use tracing_subscriber::registry::LookupSpan; + +use crate::{ + native::{EventWriter, ProviderTypes}, + statics::get_event_metadata, +}; + +pub(crate) struct _EtwLayer +where + Mode::Provider: crate::native::EventWriter + 'static, +{ + pub(crate) provider: Pin>, + pub(crate) default_keyword: u64, + pub(crate) _p: PhantomData, +} + +impl Clone for _EtwLayer +where + Mode::Provider: crate::native::EventWriter + 'static, +{ + fn clone(&self) -> Self { + _EtwLayer { + provider: self.provider.clone(), + default_keyword: self.default_keyword, + _p: PhantomData, + } + } +} + +// This struct needs to be public as it implements the tracing_subscriber::Layer and tracing_subscriber::Layer::Filter traits. +#[doc(hidden)] +pub struct EtwLayer +where + Mode::Provider: EventWriter + 'static, +{ + pub(crate) layer: _EtwLayer, +} + +// This struct needs to be public as it implements the tracing_subscriber::Layer::Filter trait. +#[doc(hidden)] +#[cfg(any(not(feature = "global_filter"), docsrs))] +pub struct EtwFilter +where + Mode::Provider: EventWriter + 'static, +{ + pub(crate) layer: _EtwLayer, +} + +impl _EtwLayer +where + S: Subscriber + for<'a> LookupSpan<'a>, + Mode: ProviderTypes + 'static, + Mode::Provider: EventWriter + 'static, +{ + fn is_enabled(&self, callsite: &callsite::Identifier, level: &tracing_core::Level) -> bool { + let etw_meta = get_event_metadata(callsite); + let keyword = if let Some(meta) = etw_meta { + meta.kw + } else { + self.default_keyword + }; + + self.provider.enabled(level, keyword) + } +} diff --git a/src/layer_builder.rs b/src/layer_builder.rs index 4626b51..166b4b4 100644 --- a/src/layer_builder.rs +++ b/src/layer_builder.rs @@ -7,9 +7,9 @@ use tracing::metadata::LevelFilter; use tracing::Subscriber; #[allow(unused_imports)] use tracing_subscriber::filter::{combinator::And, FilterExt, Filtered, Targets}; -#[allow(unused_imports)] -use tracing_subscriber::{Layer, layer::Filter}; use tracing_subscriber::registry::LookupSpan; +#[allow(unused_imports)] +use tracing_subscriber::{layer::Filter, Layer}; #[cfg(any(not(feature = "global_filter"), docsrs))] use crate::layer::EtwFilter; @@ -23,18 +23,18 @@ use crate::{error::EtwError, native}; /// additional properties for the provider, such as the keyword to use /// for events (default: 1) or a specific provider GUID (default: a hash of /// the provider name). -/// +/// /// Use [LayerBuilder::new_common_schema_events] to create a layer that /// will log events in the Common Schema 4.0 mapping. Only use this if /// you know that you need events in this format. -/// +/// /// Multiple `tracing_etw` layers can be created at the same time, /// with different provider names/IDs, keywords, or output formats. /// (Target filters)[tracing_subscriber::filter] can then be used to direct /// specific events to specific layers. pub struct LayerBuilder where - Mode: ProviderTypes + Mode: ProviderTypes, { provider_name: String, provider_id: GuidWrapper, @@ -64,9 +64,7 @@ impl LayerBuilder { /// may perform worse. Common Schema events are much slower to generate /// and should not be enabled unless absolutely necessary. #[cfg(any(feature = "common_schema", docsrs))] - pub fn new_common_schema_events( - name: &str, - ) -> LayerBuilder { + pub fn new_common_schema_events(name: &str) -> LayerBuilder { LayerBuilder:: { provider_name: name.to_owned(), provider_id: GuidWrapper::from_name(name), @@ -86,7 +84,7 @@ where /// one generated from the provider name. pub fn with_provider_id(mut self, guid: &G) -> Self where - for<'a> &'a G: Into + for<'a> &'a G: Into, { self.provider_id = guid.into(); self @@ -100,13 +98,13 @@ where } /// Set the keyword used for events that do not explicitly set a keyword. - /// + /// /// Events logged with the [crate::etw_event!] macro specify a keyword for the event. /// Events and spans logged with the [tracing::event!], [tracing::span!], /// or other similar `tracing` macros will use the default keyword. - /// + /// /// If this method is not called, the default keyword will be `1`. - /// + /// /// Keyword value `0` is special in ETW (but not user_events), and should /// not be used. pub fn with_default_keyword(mut self, kw: u64) -> Self { @@ -118,7 +116,7 @@ where /// Set the provider group to join this provider to. pub fn with_provider_group(mut self, group_id: &G) -> Self where - for <'a> &'a G: Into, + for<'a> &'a G: Into, { self.provider_group = Some(group_id.into()); self @@ -133,22 +131,26 @@ where { // The perf command is very particular about the provider names it accepts. // The Linux kernel itself cares less, and other event consumers should also presumably not need this check. - return Err(EtwError::InvalidProviderNameCharacters(self.provider_name.clone())); + return Err(EtwError::InvalidProviderNameCharacters( + self.provider_name.clone(), + )); } let group_name_len = match &self.provider_group { None => 0, - Some(ref name) => Mode::get_provider_group(&name).as_ref().len() + Some(ref name) => Mode::get_provider_group(&name).as_ref().len(), }; if self.provider_name.len() + group_name_len >= 234 { - return Err(EtwError::TooManyCharacters(self.provider_name.len() + group_name_len)); + return Err(EtwError::TooManyCharacters( + self.provider_name.len() + group_name_len, + )); } } match &self.provider_group { None => Ok(()), - Some(value) => Mode::is_valid(value) + Some(value) => Mode::is_valid(value), } } @@ -160,7 +162,8 @@ where match self.provider_group { None => {} Some(ref name) => { - targets = targets.with_target(Mode::get_provider_group(name).as_ref(), LevelFilter::TRACE); + targets = targets + .with_target(Mode::get_provider_group(name).as_ref(), LevelFilter::TRACE); } } @@ -186,7 +189,7 @@ where ), default_keyword: self.default_keyword, _p: PhantomData, - } + }, } } @@ -196,9 +199,7 @@ where S: Subscriber + for<'a> LookupSpan<'a>, Mode::Provider: EventWriter + 'static, { - EtwFilter:: { - layer - } + EtwFilter:: { layer } } #[cfg_attr(docsrs, doc(cfg(feature = "global_filter")))] diff --git a/src/lib.rs b/src/lib.rs index d5df6d9..3dd3aa7 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -46,18 +46,18 @@ //! ```no_run //! use tracing::{event, Level}; //! use tracing_subscriber::{self, prelude::*}; -//! +//! //! tracing_subscriber::registry() //! .with(tracing_etw::LayerBuilder::new("SampleProviderName").build().unwrap()) //! .init(); //! //! event!(Level::INFO, fieldB = b'x', fieldA = 7, "Event Message!"); //! ``` -//! +//! //! ## etw_event macro -//! +//! //! **Despite the name, this macro works for both ETW and user_events.** -//! +//! //! The `etw_event!` macro is an **optional** additional logging macro //! based on `event!` that adds keyword, tags, and event-name support. //! Keywords are a fundamental part of efficient event filtering in ETW, @@ -65,30 +65,30 @@ //! It is highly recommended that every event have a non-zero keyword; //! the [LayerBuilder::with_default_keyword] function can set the default keyword assigned //! to every event logged through the `tracing` macros (e.g. `event!`). -//! +//! //! This extra information is stored as static metadata in the final //! compiled binary, and relies on linker support to work properly. //! It has been tested with Microsoft's, GCC's, and LLVM's linker. //! //! ## Performance Details -//! +//! //! Performance will vary from machine to machine, but this crate should be //! fast enough to log tens of thousands of events per second. -//! +//! //! There are benchmarks available in the code, but they currently rely on //! an unpublished crate to start and stop an ETW tracing session //! (and rely on the user to manually start collecting events with the //! `perf` tool on Linux). Future work will make these easier to run locally. //! //! ### Disabled Events -//! +//! //! When an event is not enabled by a ETW session or Linux tracing session, //! the cost of logging an event should be effectively zero. This is a few //! instructions to check the process-local enablement mask //! and skip over performing any further work if the event is not enabled. -//! +//! //! ### Enabled Events -//! +//! //! When an event is enabled by a collector, in addition to the unavoidable //! overhead from the `tracing` crate (which is itself quite minimal), this //! crate will dynamically convert the `tracing` event into a Tracelogging/EventHeader @@ -103,48 +103,48 @@ //! however, it may be unexpected for those coming from Tracelogging for C/C++. //! For the most part this translation is quite fast and should not be any slower //! than any other `tracing` layer. -//! +//! //! Events are logged synchronously through to the kernel. They are then delivered //! to consumers asynchronously per the platform design. -//! +//! //! ### Heap Allocations -//! +//! //! Each `tracing-etw::Layer` that is added will heap allocate the provider name and GUID. -//! +//! //! Logging events with the [std::fmt::Debug](debug format specifier (`:?`)) will //! necessitate a heap allocation to format the value into a string. -//! +//! //! Logging strings copies them to the heap first. This is a side-effect of how //! `tracing` presents the strings to each layer; the lifetime of the string is //! too short for what this crate currently needs, but it may be possible to improve //! this in the future. -//! +//! //! Logging a span allocates a copy of the span's fields on the heap. This is needed //! so the values can be updated during execution and the final payload values logged //! when the span ends. This allocation is freed when the span ends. -//! +//! //! The first time an event is logged (the event is enabled at the platform layer and //! the logging code is run), this crate will scan the binary for any metadata left //! by the `etw_event!` macro. This information will be cached in a single heap //! allocation for later use by other logging calls. This cached memory is never freed //! until the process exits; if this crate is used in a dynamic library that unloads //! before the process exits, the memory will be leaked. -//! +//! //! A thread-local event builder is allocated for each thread that logs an event. //! This allows for complete thread safety when logging events. This allocation //! will stay alive until the thread ends. Additionally, the builder itself will allocate //! scratch space for constructing the event. This scratch space will grow to fit the //! very largest event that has been logged so far, but will not shrink. Generally, //! this should not be much more than a few kilobytes per-thread. -//! +//! //! ### Miscellaneous -//! +//! //! This crate attempts to avoid dynamic dispatch in the critical logging path. //! This may result in some very large type names, especially for the global //! subscriber. -//! +//! //! ## Alternative Crates -//! +//! //! There are a few other crates that also convert `tracing` events to ETW and/or user_events. //! - [win_etw_tracing](https://crates.io/crates/win_etw_tracing): This crate should be //! considered superseded by `tracing-etw` when it comes to utilizing it with `tracing`. @@ -170,8 +170,8 @@ mod layer_builder; // Consumers of the crate should not need to use this module directly. #[doc(hidden)] pub mod native; -mod values; mod statics; +mod values; // Module holding internal details that need to be public but should not be directly used by consumers of the crate. #[doc(hidden)] pub mod _details; diff --git a/src/native/common_schema/etw_cs.rs b/src/native/common_schema/etw_cs.rs index 3802ae5..eaa6dba 100644 --- a/src/native/common_schema/etw_cs.rs +++ b/src/native/common_schema/etw_cs.rs @@ -74,7 +74,9 @@ impl CommonSchemaProvider { tracing_core::Level::WARN => tracelogging::Level::Warning, tracing_core::Level::INFO => tracelogging::Level::Informational, tracing_core::Level::DEBUG => tracelogging::Level::Verbose, - tracing_core::Level::TRACE => tracelogging::Level::from_int(tracelogging::Level::Verbose.as_int() + 1), + tracing_core::Level::TRACE => { + tracelogging::Level::from_int(tracelogging::Level::Verbose.as_int() + 1) + } } } } @@ -91,8 +93,7 @@ impl crate::native::ProviderTypes for CommonSchemaProvider { fn is_valid(value: &Self::ProviderGroupType) -> Result<(), EtwError> { if value == &crate::native::native_guid::zero() { Err(EtwError::EmptyProviderGroupGuid) - } - else { + } else { Ok(()) } } @@ -131,8 +132,7 @@ impl crate::native::EventWriter for CommonSchemaProvider { #[inline] fn enabled(&self, level: &tracing_core::Level, keyword: u64) -> bool { - self.provider - .enabled(Self::map_level(level), keyword) + self.provider.enabled(Self::map_level(level), keyword) } fn span_start<'a, 'b, R>( @@ -316,9 +316,7 @@ impl crate::native::EventWriter for CommonSchemaProvider { eb.add_str8( "eventTime", - chrono::DateTime::to_rfc3339(&chrono::DateTime::::from( - timestamp, - )), + chrono::DateTime::to_rfc3339(&chrono::DateTime::::from(timestamp)), OutType::Utf8, 0, ); diff --git a/src/native/common_schema/user_events_cs.rs b/src/native/common_schema/user_events_cs.rs index 3afc26d..679fd13 100644 --- a/src/native/common_schema/user_events_cs.rs +++ b/src/native/common_schema/user_events_cs.rs @@ -1,5 +1,5 @@ -use crate::values::*; use crate::error::EtwError; +use crate::values::*; use eventheader::*; use eventheader_dynamic::EventBuilder; use std::{ @@ -60,10 +60,10 @@ impl crate::native::ProviderTypes for CommonSchemaProvider { fn is_valid(value: &Self::ProviderGroupType) -> Result<(), EtwError> { if !eventheader_dynamic::ProviderOptions::is_valid_option_value(value) { - Err(EtwError::InvalidProviderGroupCharacters(value.clone().into())) - } - else - { + Err(EtwError::InvalidProviderGroupCharacters( + value.clone().into(), + )) + } else { Ok(()) } } @@ -104,7 +104,9 @@ impl CommonSchemaProvider { tracing_core::Level::WARN => eventheader_dynamic::Level::Warning, tracing_core::Level::INFO => eventheader_dynamic::Level::Informational, tracing_core::Level::DEBUG => eventheader_dynamic::Level::Verbose, - tracing_core::Level::TRACE => eventheader_dynamic::Level::from_int(eventheader_dynamic::Level::Verbose.as_int() + 1), + tracing_core::Level::TRACE => eventheader_dynamic::Level::from_int( + eventheader_dynamic::Level::Verbose.as_int() + 1, + ), } } } @@ -127,48 +129,18 @@ impl crate::native::EventWriter for CommonSchemaProvider { // Keywords are static, but levels are dynamic so we have to register them all for event in crate::statics::event_metadata() { - provider.register_set( - Self::map_level(&tracing::Level::ERROR), - event.kw, - ); - provider.register_set( - Self::map_level(&tracing::Level::WARN), - event.kw, - ); - provider.register_set( - Self::map_level(&tracing::Level::INFO), - event.kw, - ); - provider.register_set( - Self::map_level(&tracing::Level::DEBUG), - event.kw, - ); - provider.register_set( - Self::map_level(&tracing::Level::TRACE), - event.kw, - ); + provider.register_set(Self::map_level(&tracing::Level::ERROR), event.kw); + provider.register_set(Self::map_level(&tracing::Level::WARN), event.kw); + provider.register_set(Self::map_level(&tracing::Level::INFO), event.kw); + provider.register_set(Self::map_level(&tracing::Level::DEBUG), event.kw); + provider.register_set(Self::map_level(&tracing::Level::TRACE), event.kw); } - provider.register_set( - Self::map_level(&tracing::Level::ERROR), - default_keyword, - ); - provider.register_set( - Self::map_level(&tracing::Level::WARN), - default_keyword, - ); - provider.register_set( - Self::map_level(&tracing::Level::INFO), - default_keyword, - ); - provider.register_set( - Self::map_level(&tracing::Level::DEBUG), - default_keyword, - ); - provider.register_set( - Self::map_level(&tracing::Level::TRACE), - default_keyword, - ); + provider.register_set(Self::map_level(&tracing::Level::ERROR), default_keyword); + provider.register_set(Self::map_level(&tracing::Level::WARN), default_keyword); + provider.register_set(Self::map_level(&tracing::Level::INFO), default_keyword); + provider.register_set(Self::map_level(&tracing::Level::DEBUG), default_keyword); + provider.register_set(Self::map_level(&tracing::Level::TRACE), default_keyword); Arc::pin(Self { provider: std::sync::RwLock::new(provider), @@ -182,7 +154,11 @@ impl crate::native::EventWriter for CommonSchemaProvider { .read() .unwrap() .find_set(Self::map_level(level), keyword); - if let Some(s) = es { s.enabled() } else { false } + if let Some(s) = es { + s.enabled() + } else { + false + } } fn span_start<'a, 'b, R>( diff --git a/src/native/etw.rs b/src/native/etw.rs index d963ef8..555f952 100644 --- a/src/native/etw.rs +++ b/src/native/etw.rs @@ -1,5 +1,5 @@ -use crate::{error::EtwError, values::*}; use crate::statics::GLOBAL_ACTIVITY_SEED; +use crate::{error::EtwError, values::*}; use chrono::{Datelike, Timelike}; use std::{cell::RefCell, ops::DerefMut, pin::Pin, sync::Arc, time::SystemTime}; use tracelogging::*; @@ -103,8 +103,7 @@ impl crate::native::ProviderTypes for Provider { fn is_valid(value: &Self::ProviderGroupType) -> Result<(), EtwError> { if value == &crate::native::native_guid::zero() { Err(EtwError::EmptyProviderGroupGuid) - } - else { + } else { Ok(()) } } @@ -123,7 +122,9 @@ impl Provider { tracing_core::Level::WARN => tracelogging::Level::Warning, tracing_core::Level::INFO => tracelogging::Level::Informational, tracing_core::Level::DEBUG => tracelogging::Level::Verbose, - tracing_core::Level::TRACE => tracelogging::Level::from_int(tracelogging::Level::Verbose.as_int() + 1), + tracing_core::Level::TRACE => { + tracelogging::Level::from_int(tracelogging::Level::Verbose.as_int() + 1) + } } } } @@ -161,8 +162,7 @@ impl super::EventWriter for Provider { #[inline] fn enabled(&self, level: &tracing_core::Level, keyword: u64) -> bool { - self.provider - .enabled(Self::map_level(level), keyword) + self.provider.enabled(Self::map_level(level), keyword) } fn span_start<'a, 'b, R>( diff --git a/src/native/mod.rs b/src/native/mod.rs index 6b81ece..3a9fc2c 100644 --- a/src/native/mod.rs +++ b/src/native/mod.rs @@ -30,10 +30,10 @@ pub(crate) use user_events::_stop__etw_kw; #[cfg(feature = "common_schema")] pub(crate) mod common_schema; -#[cfg(not(target_os = "linux"))] -pub(crate) use tracelogging_dynamic::Guid as native_guid; #[cfg(target_os = "linux")] pub(crate) use eventheader::Guid as native_guid; +#[cfg(not(target_os = "linux"))] +pub(crate) use tracelogging_dynamic::Guid as native_guid; use crate::error::EtwError; diff --git a/src/native/user_events.rs b/src/native/user_events.rs index 01bfe27..306381a 100644 --- a/src/native/user_events.rs +++ b/src/native/user_events.rs @@ -1,6 +1,6 @@ -use crate::values::*; -use crate::statics::GLOBAL_ACTIVITY_SEED; use crate::error::EtwError; +use crate::statics::GLOBAL_ACTIVITY_SEED; +use crate::values::*; use eventheader::*; use eventheader_dynamic::EventBuilder; use std::{cell::RefCell, ops::DerefMut, pin::Pin, sync::Arc, time::SystemTime}; @@ -68,10 +68,10 @@ impl crate::native::ProviderTypes for Provider { fn is_valid(value: &Self::ProviderGroupType) -> Result<(), EtwError> { if !eventheader_dynamic::ProviderOptions::is_valid_option_value(value) { - Err(EtwError::InvalidProviderGroupCharacters(value.clone().into())) - } - else - { + Err(EtwError::InvalidProviderGroupCharacters( + value.clone().into(), + )) + } else { Ok(()) } } @@ -112,7 +112,9 @@ impl Provider { tracing_core::Level::WARN => eventheader_dynamic::Level::Warning, tracing_core::Level::INFO => eventheader_dynamic::Level::Informational, tracing_core::Level::DEBUG => eventheader_dynamic::Level::Verbose, - tracing_core::Level::TRACE => eventheader_dynamic::Level::from_int(eventheader_dynamic::Level::Verbose.as_int() + 1), + tracing_core::Level::TRACE => eventheader_dynamic::Level::from_int( + eventheader_dynamic::Level::Verbose.as_int() + 1, + ), } } } @@ -135,48 +137,18 @@ impl crate::native::EventWriter for Provider { // Keywords are static, but levels are dynamic so we have to register them all for event in crate::statics::event_metadata() { - provider.register_set( - Self::map_level(&tracing::Level::ERROR), - event.kw, - ); - provider.register_set( - Self::map_level(&tracing::Level::WARN), - event.kw, - ); - provider.register_set( - Self::map_level(&tracing::Level::INFO), - event.kw, - ); - provider.register_set( - Self::map_level(&tracing::Level::DEBUG), - event.kw, - ); - provider.register_set( - Self::map_level(&tracing::Level::TRACE), - event.kw, - ); + provider.register_set(Self::map_level(&tracing::Level::ERROR), event.kw); + provider.register_set(Self::map_level(&tracing::Level::WARN), event.kw); + provider.register_set(Self::map_level(&tracing::Level::INFO), event.kw); + provider.register_set(Self::map_level(&tracing::Level::DEBUG), event.kw); + provider.register_set(Self::map_level(&tracing::Level::TRACE), event.kw); } - provider.register_set( - Self::map_level(&tracing::Level::ERROR), - default_keyword, - ); - provider.register_set( - Self::map_level(&tracing::Level::WARN), - default_keyword, - ); - provider.register_set( - Self::map_level(&tracing::Level::INFO), - default_keyword, - ); - provider.register_set( - Self::map_level(&tracing::Level::DEBUG), - default_keyword, - ); - provider.register_set( - Self::map_level(&tracing::Level::TRACE), - default_keyword, - ); + provider.register_set(Self::map_level(&tracing::Level::ERROR), default_keyword); + provider.register_set(Self::map_level(&tracing::Level::WARN), default_keyword); + provider.register_set(Self::map_level(&tracing::Level::INFO), default_keyword); + provider.register_set(Self::map_level(&tracing::Level::DEBUG), default_keyword); + provider.register_set(Self::map_level(&tracing::Level::TRACE), default_keyword); Arc::pin(Provider { provider: std::sync::RwLock::new(provider), @@ -190,7 +162,11 @@ impl crate::native::EventWriter for Provider { .read() .unwrap() .find_set(Self::map_level(level), keyword); - if let Some(s) = es { s.enabled() } else { false } + if let Some(s) = es { + s.enabled() + } else { + false + } } fn span_start<'a, 'b, R>( diff --git a/src/statics.rs b/src/statics.rs index d1a3230..9bcd464 100644 --- a/src/statics.rs +++ b/src/statics.rs @@ -1,230 +1,234 @@ -// Module for static variables that are used by the crate. - -use std::{cmp, hash::BuildHasher, iter::FusedIterator, sync::LazyLock}; - -use crate::_details::{EventMetadata, ParsedEventMetadata}; - -type FnvHasher = std::hash::BuildHasherDefault::; - -pub(crate) static GLOBAL_ACTIVITY_SEED: LazyLock<[u8; 16]> = LazyLock::new(|| { - let now = std::time::SystemTime::now() - .duration_since(std::time::SystemTime::UNIX_EPOCH) - .unwrap() - .as_nanos(); - let seed = (now >> 64) as u64 | now as u64; - let mut data = [0; 16]; - let (seed_half, _) = data.split_at_mut(8); - seed_half.copy_from_slice(&seed.to_le_bytes()); - data[0] = 0; - data - }); - -fn process_static_metadata() -> Box<[ParsedEventMetadata]> { - // The array of pointers are in a mutable section and can be sorted/deduped, but they are pointing to read-only static data - - let start = - &raw const crate::native::_start__etw_kw as *mut *const EventMetadata; - let stop = - &raw const crate::native::_stop__etw_kw as *mut *const EventMetadata; - - if start.is_null() { - return Box::new([]); - } - - // SAFETY On Windows the start and stop entries are sentry values at the start and end of the linker section. - // Linux does not need these sentries. - #[cfg(target_os = "windows")] - let start = unsafe { start.add(1) }; - // SAFETY The entries in the linker section are all pointers, we can guarantee that stop is a multiple of sizeof(void*) distance from start. - let stop_offset = unsafe { stop.offset_from(start) as usize }; - - // SAFETY Start is not null and points to a valid static in memory (else the code wouldn't link), - // so we can guarantee we aren't making a reference to null here. - let events_slice = unsafe { - &mut *core::ptr::slice_from_raw_parts_mut(start, stop_offset) }; - - if events_slice.is_empty() { - return Box::new([]); - } - - // Sort spurious nulls to the end. This is comparing pointers as usize, not their pointed-to values. - events_slice.sort_unstable_by(|a, b| b.cmp(a)); - - // Remove spurious duplicate pointers - let end_pos = events_slice.len(); - let mut good_pos = 0; - while good_pos != end_pos - 1 { - if events_slice[good_pos] == events_slice[good_pos + 1] { - let mut next_pos = good_pos + 2; - while next_pos != end_pos { - if events_slice[next_pos].is_null() { - break; - } - if events_slice[good_pos] != events_slice[next_pos] { - good_pos += 1; - events_slice[good_pos] = events_slice[next_pos]; - } - next_pos += 1; - } - break; - } - if events_slice[good_pos + 1].is_null() { - break; - } - good_pos += 1; - } - - // Explicitly set all the values at the end to null - let mut next_pos = good_pos + 1; - while next_pos != end_pos { - events_slice[next_pos] = core::ptr::null(); - next_pos += 1; - } - - let bh = FnvHasher::default(); - - let mut vec = Vec::with_capacity(good_pos + 1); - next_pos = 0; - while next_pos <= good_pos { - // SAFETY The above code as already validated that events_slice[0..good_pos] are non-null pointers - let next = unsafe { &*events_slice[next_pos] }; - let identity_hash = bh.hash_one(&next.identity); - vec.push(ParsedEventMetadata { identity_hash, meta: next }); - next_pos += 1; - } - - let mut sorted = vec.into_boxed_slice(); - sorted.sort_unstable_by(|a, b| b.cmp(a)); - sorted -} - -#[cfg(any(target_os = "windows", target_os = "linux"))] -static EVENT_METADATA: LazyLock> = LazyLock::new(process_static_metadata); - -#[cfg(not(any(target_os = "windows", target_os = "linux")))] -static EVENT_METADATA: [ParsedEventMetadata; 0] = []; - -impl core::cmp::PartialEq for ParsedEventMetadata { - fn eq(&self, other: &Self) -> bool { - cmp::Ordering::Equal == self.cmp(other) - } -} - -impl core::cmp::Eq for ParsedEventMetadata {} - -impl core::cmp::PartialOrd for ParsedEventMetadata { - fn partial_cmp(&self, other: &Self) -> Option { - Some(self.cmp(other)) - } -} - -// Order by hash only -impl core::cmp::Ord for ParsedEventMetadata { - fn cmp(&self, other: &Self) -> std::cmp::Ordering { - self.identity_hash.cmp(&other.identity_hash) - } -} - -pub(crate) fn get_event_metadata(id: &tracing::callsite::Identifier) -> Option<&'static crate::_details::EventMetadata> { - let bh = FnvHasher::default(); - let identity_hash = bh.hash_one(id); - let idx = EVENT_METADATA.partition_point(|other| other.identity_hash > identity_hash); - let mut cur = idx; - while cur Option { - if self.current_index >= EVENT_METADATA.len() { - return None; - } - - let result = &EVENT_METADATA[self.current_index].meta; - - self.current_index += 1; - - Some(result) - } -} - -#[allow(dead_code)] -// Currently only used on Linux targets and the tests -pub(crate) fn event_metadata() -> impl Iterator::Item> { - EventMetadataEnumerator{current_index: 0} -} - -// Only one test function can be compiled into the module at a time, since the statics the macro produces are global -#[cfg(test)] -mod test { - use tracing::Level; - - use crate::{etw_event, statics::event_metadata}; - - // #[test] - // fn test_none() { - // let mut sum = 0; - // for event in event_metadata() { - // sum += event.kw; - // } - - // assert_eq!(sum, 0); - // } - - // #[test] - // fn test_one() { - // etw_event!(name: "TestEventWithKeyword1", Level::ERROR, 1, "An event with a name and keyword!"); - - // let mut sum = 0; - // for event in event_metadata() { - // sum += event.kw; - // } - - // assert_eq!(sum, 1); - // } - - #[test] - fn test_ten() { - etw_event!(name: "TestEventWithKeyword1", Level::ERROR, 1, "An event with a name and keyword!"); - etw_event!(name: "TestEventWithKeyword2", Level::WARN, 2, "An event with a name and keyword!"); - etw_event!(name: "TestEventWithKeyword3", Level::INFO, 3, "An event with a name and keyword!"); - etw_event!(name: "TestEventWithKeyword4", Level::DEBUG, 4, "An event with a name and keyword!"); - etw_event!(name: "TestEventWithKeyword5", Level::TRACE, 5, "An event with a name and keyword!"); - etw_event!(name: "TestEventWithKeyword6", Level::TRACE, 6, "An event with a name and keyword!"); - etw_event!(name: "TestEventWithKeyword7", Level::DEBUG, 7, "An event with a name and keyword!"); - etw_event!(name: "TestEventWithKeyword8", Level::INFO, 8, "An event with a name and keyword!"); - etw_event!(name: "TestEventWithKeyword9", Level::WARN, 9, "An event with a name and keyword!"); - etw_event!(name: "TestEventWithKeyword10", Level::ERROR, 10, "An event with a name and keyword!"); - - let mut sum = 0; - for event in event_metadata() { - sum += event.kw; - } - - #[cfg(any(target_os = "windows", target_os = "linux"))] - let expected = 55; - #[cfg(not(any(target_os = "windows", target_os = "linux")))] - let expected = 0; - - assert_eq!(sum, expected); - } -} +// Module for static variables that are used by the crate. + +use std::{cmp, hash::BuildHasher, iter::FusedIterator, sync::LazyLock}; + +use crate::_details::{EventMetadata, ParsedEventMetadata}; + +type FnvHasher = std::hash::BuildHasherDefault; + +pub(crate) static GLOBAL_ACTIVITY_SEED: LazyLock<[u8; 16]> = LazyLock::new(|| { + let now = std::time::SystemTime::now() + .duration_since(std::time::SystemTime::UNIX_EPOCH) + .unwrap() + .as_nanos(); + let seed = (now >> 64) as u64 | now as u64; + let mut data = [0; 16]; + let (seed_half, _) = data.split_at_mut(8); + seed_half.copy_from_slice(&seed.to_le_bytes()); + data[0] = 0; + data +}); + +fn process_static_metadata() -> Box<[ParsedEventMetadata]> { + // The array of pointers are in a mutable section and can be sorted/deduped, but they are pointing to read-only static data + + let start = &raw const crate::native::_start__etw_kw as *mut *const EventMetadata; + let stop = &raw const crate::native::_stop__etw_kw as *mut *const EventMetadata; + + if start.is_null() { + return Box::new([]); + } + + // SAFETY On Windows the start and stop entries are sentry values at the start and end of the linker section. + // Linux does not need these sentries. + #[cfg(target_os = "windows")] + let start = unsafe { start.add(1) }; + // SAFETY The entries in the linker section are all pointers, we can guarantee that stop is a multiple of sizeof(void*) distance from start. + let stop_offset = unsafe { stop.offset_from(start) as usize }; + + // SAFETY Start is not null and points to a valid static in memory (else the code wouldn't link), + // so we can guarantee we aren't making a reference to null here. + let events_slice = unsafe { &mut *core::ptr::slice_from_raw_parts_mut(start, stop_offset) }; + + if events_slice.is_empty() { + return Box::new([]); + } + + // Sort spurious nulls to the end. This is comparing pointers as usize, not their pointed-to values. + events_slice.sort_unstable_by(|a, b| b.cmp(a)); + + // Remove spurious duplicate pointers + let end_pos = events_slice.len(); + let mut good_pos = 0; + while good_pos != end_pos - 1 { + if events_slice[good_pos] == events_slice[good_pos + 1] { + let mut next_pos = good_pos + 2; + while next_pos != end_pos { + if events_slice[next_pos].is_null() { + break; + } + if events_slice[good_pos] != events_slice[next_pos] { + good_pos += 1; + events_slice[good_pos] = events_slice[next_pos]; + } + next_pos += 1; + } + break; + } + if events_slice[good_pos + 1].is_null() { + break; + } + good_pos += 1; + } + + // Explicitly set all the values at the end to null + let mut next_pos = good_pos + 1; + while next_pos != end_pos { + events_slice[next_pos] = core::ptr::null(); + next_pos += 1; + } + + let bh = FnvHasher::default(); + + let mut vec = Vec::with_capacity(good_pos + 1); + next_pos = 0; + while next_pos <= good_pos { + // SAFETY The above code as already validated that events_slice[0..good_pos] are non-null pointers + let next = unsafe { &*events_slice[next_pos] }; + let identity_hash = bh.hash_one(&next.identity); + vec.push(ParsedEventMetadata { + identity_hash, + meta: next, + }); + next_pos += 1; + } + + let mut sorted = vec.into_boxed_slice(); + sorted.sort_unstable_by(|a, b| b.cmp(a)); + sorted +} + +#[cfg(any(target_os = "windows", target_os = "linux"))] +static EVENT_METADATA: LazyLock> = + LazyLock::new(process_static_metadata); + +#[cfg(not(any(target_os = "windows", target_os = "linux")))] +static EVENT_METADATA: [ParsedEventMetadata; 0] = []; + +impl core::cmp::PartialEq for ParsedEventMetadata { + fn eq(&self, other: &Self) -> bool { + cmp::Ordering::Equal == self.cmp(other) + } +} + +impl core::cmp::Eq for ParsedEventMetadata {} + +impl core::cmp::PartialOrd for ParsedEventMetadata { + fn partial_cmp(&self, other: &Self) -> Option { + Some(self.cmp(other)) + } +} + +// Order by hash only +impl core::cmp::Ord for ParsedEventMetadata { + fn cmp(&self, other: &Self) -> std::cmp::Ordering { + self.identity_hash.cmp(&other.identity_hash) + } +} + +pub(crate) fn get_event_metadata( + id: &tracing::callsite::Identifier, +) -> Option<&'static crate::_details::EventMetadata> { + let bh = FnvHasher::default(); + let identity_hash = bh.hash_one(id); + let idx = EVENT_METADATA.partition_point(|other| other.identity_hash > identity_hash); + let mut cur = idx; + while cur < EVENT_METADATA.len() { + let meta = &EVENT_METADATA[cur]; + if meta.identity_hash != identity_hash { + return None; + } + + if meta.meta.identity == *id { + return Some(meta.meta); + } + + cur += 1; + } + None +} + +pub(crate) struct EventMetadataEnumerator { + current_index: usize, +} + +impl FusedIterator for EventMetadataEnumerator {} + +impl Iterator for EventMetadataEnumerator { + type Item = &'static EventMetadata; + + fn next(&mut self) -> Option { + if self.current_index >= EVENT_METADATA.len() { + return None; + } + + let result = &EVENT_METADATA[self.current_index].meta; + + self.current_index += 1; + + Some(result) + } +} + +#[allow(dead_code)] +// Currently only used on Linux targets and the tests +pub(crate) fn event_metadata() -> impl Iterator::Item> +{ + EventMetadataEnumerator { current_index: 0 } +} + +// Only one test function can be compiled into the module at a time, since the statics the macro produces are global +#[cfg(test)] +mod test { + use tracing::Level; + + use crate::{etw_event, statics::event_metadata}; + + // #[test] + // fn test_none() { + // let mut sum = 0; + // for event in event_metadata() { + // sum += event.kw; + // } + + // assert_eq!(sum, 0); + // } + + // #[test] + // fn test_one() { + // etw_event!(name: "TestEventWithKeyword1", Level::ERROR, 1, "An event with a name and keyword!"); + + // let mut sum = 0; + // for event in event_metadata() { + // sum += event.kw; + // } + + // assert_eq!(sum, 1); + // } + + #[test] + fn test_ten() { + etw_event!(name: "TestEventWithKeyword1", Level::ERROR, 1, "An event with a name and keyword!"); + etw_event!(name: "TestEventWithKeyword2", Level::WARN, 2, "An event with a name and keyword!"); + etw_event!(name: "TestEventWithKeyword3", Level::INFO, 3, "An event with a name and keyword!"); + etw_event!(name: "TestEventWithKeyword4", Level::DEBUG, 4, "An event with a name and keyword!"); + etw_event!(name: "TestEventWithKeyword5", Level::TRACE, 5, "An event with a name and keyword!"); + etw_event!(name: "TestEventWithKeyword6", Level::TRACE, 6, "An event with a name and keyword!"); + etw_event!(name: "TestEventWithKeyword7", Level::DEBUG, 7, "An event with a name and keyword!"); + etw_event!(name: "TestEventWithKeyword8", Level::INFO, 8, "An event with a name and keyword!"); + etw_event!(name: "TestEventWithKeyword9", Level::WARN, 9, "An event with a name and keyword!"); + etw_event!(name: "TestEventWithKeyword10", Level::ERROR, 10, "An event with a name and keyword!"); + + let mut sum = 0; + for event in event_metadata() { + sum += event.kw; + } + + #[cfg(any(target_os = "windows", target_os = "linux"))] + let expected = 55; + #[cfg(not(any(target_os = "windows", target_os = "linux")))] + let expected = 0; + + assert_eq!(sum, expected); + } +}