diff --git a/opentelemetry-user-events-logs/CHANGELOG.md b/opentelemetry-user-events-logs/CHANGELOG.md index 5056443b7..9e69e9a44 100644 --- a/opentelemetry-user-events-logs/CHANGELOG.md +++ b/opentelemetry-user-events-logs/CHANGELOG.md @@ -2,6 +2,7 @@ ## vNext + ## v0.14.0 Released 2025-July-24 diff --git a/opentelemetry-user-events-logs/benches/logs.rs b/opentelemetry-user-events-logs/benches/logs.rs index d9217eb64..6c3e772d6 100644 --- a/opentelemetry-user-events-logs/benches/logs.rs +++ b/opentelemetry-user-events-logs/benches/logs.rs @@ -5,21 +5,26 @@ Hardware: Apple M4 Pro Total Number of Cores: 10 (Inside multipass vm running Ubuntu 22.04) - // When no listener + + // When no listener (automatic disable via RAII guard) | Test | Average time| |-----------------------------|-------------| - | User_Event_4_Attributes | 8 ns | - | User_Event_6_Attributes | 8 ns | + | User_Event_4_Attributes | 19.2 ns | + | User_Event_6_Attributes | 19.6 ns | + | User_Event_4_Attributes_EventName_Custom | 20.2 ns | + | User_Event_4_Attributes_EventName_FromLogRecord | 20.6 ns | - // When listener is enabled - // Run below to enable + // When listener is enabled (automatic enable via RAII guard) + // The benchmark now automatically enables/disables the listener + // using the commands below internally: // echo 1 | sudo tee /sys/kernel/debug/tracing/events/user_events/myprovider_L2K1/enable - // Run below to disable // echo 0 | sudo tee /sys/kernel/debug/tracing/events/user_events/myprovider_L2K1/enable | Test | Average time| |-----------------------------|-------------| | User_Event_4_Attributes | 530 ns | | User_Event_6_Attributes | 586 ns | + | User_Event_4_Attributes_EventName_Custom | 590 ns | + | User_Event_4_Attributes_EventName_FromLogRecord | 595 ns | */ // running the following from the current directory @@ -32,10 +37,232 @@ use opentelemetry_sdk::Resource; #[cfg(feature = "experimental_eventname_callback")] use opentelemetry_user_events_logs::EventNameCallback; use opentelemetry_user_events_logs::Processor; +use std::fs; +use std::io; use tracing::error; use tracing_subscriber::prelude::*; use tracing_subscriber::Registry; +const PROVIDER_NAME: &str = "myprovider"; +/// Suffix used by the kernel user_events provider naming in these benchmarks. +/// Documented to avoid magic strings in path construction. +/// +/// The kernel appends a unique suffix (such as "_L2K1") to user events provider names +/// when registering them via the user_events interface. This suffix is generated by the +/// kernel to ensure uniqueness and to encode internal information about the provider. +/// In this benchmark, "_L2K1" is the suffix assigned by the kernel to the "myprovider" +/// provider. This value may differ across systems or kernel versions, and is required +/// when constructing sysfs paths for enabling/disabling the provider's listener, e.g.: +/// /sys/kernel/debug/tracing/events/user_events/myprovider_L2K1/enable +/// For more details, see the Linux kernel documentation on user_events: +/// https://docs.kernel.org/trace/user_events.html +const USER_EVENTS_PROVIDER_SUFFIX: &str = "_L2K1"; +/// Provider name used for dummy guards that perform no operations. +/// This value is not used for actual provider operations, only for internal tracking. +const DUMMY_PROVIDER_NAME: &str = "dummy"; + +/// RAII guard for enabling/disabling user events listener +/// +/// This guard automatically enables the user events listener when created and +/// disables it when dropped, ensuring proper cleanup even if the benchmark +/// panics or exits early. +/// +/// The guard tracks whether the listener was already enabled before it was +/// created, and only disables it on drop if it wasn't already enabled. +/// This prevents interfering with other tests or processes that might have +/// enabled the listener. +/// +/// # Fields +/// * `provider_name` - The name of the kernel user events provider being managed by this guard. +/// This is used to construct sysfs paths and identify which provider's listener should be enabled or disabled. +/// It is essential for ensuring that the guard operates on the correct provider, especially when multiple +/// providers may exist or when running benchmarks that interact with different user events sources. +/// * `was_enabled` - Tracks whether the listener was already enabled before this guard was created. +/// This field is crucial for preventing the guard from disabling listeners that were enabled +/// by external processes or other parts of the system. When the guard is dropped, it only +/// disables the listener if `was_enabled` is false, ensuring that external processes that +/// may have enabled the listener for their own purposes are not disrupted. +/// * `is_dummy` - Indicates whether this is a dummy guard that performs no operations. +/// Dummy guards are created when enabling the listener fails, ensuring benchmarks can proceed +/// without attempting to disable anything later. When `is_dummy` is true, the drop implementation +/// performs no cleanup operations. +struct UserEventsListenerGuard { + provider_name: String, + was_enabled: bool, + is_dummy: bool, +} + +impl UserEventsListenerGuard { + /// Enable the user events listener for the given provider + /// + /// This method: + /// 1. Checks if the listener is already enabled + /// 2. Enables it if it's not already enabled + /// 3. Returns a guard that will disable the listener on drop (if it wasn't already enabled) + /// + /// # Arguments + /// * `provider_name` - The name of the provider to enable/disable + /// + /// # Returns + /// * `Ok(Self)` - A guard that will disable the listener on drop + /// * `Err(String)` - Error message if enabling failed + fn enable(provider_name: &str) -> Result { + let enable_path = format!( + "/sys/kernel/debug/tracing/events/user_events/{}{}/enable", + provider_name, USER_EVENTS_PROVIDER_SUFFIX + ); + + // Check if already enabled by reading the entire file and checking if it equals "1" + let was_enabled = match fs::read_to_string(&enable_path) { + Ok(contents) => contents.trim() == "1", + Err(e) => { + if e.kind() == io::ErrorKind::PermissionDenied { + return Err(format!( + "Insufficient permissions to read '{}'. Please run the benchmark as root or with appropriate capabilities (CAP_SYS_ADMIN). Error: {}", + enable_path, e + )); + } else { + return Err(format!("Failed to check listener status: {}", e)); + } + } + }; + + // Only enable the listener if it's not already enabled + if !was_enabled { + // Enable the listener by writing "1\n" to the enable file + // Most sysfs/debugfs interfaces expect a newline character. + if let Err(e) = fs::write(&enable_path, b"1\n") { + if e.kind() == io::ErrorKind::PermissionDenied { + return Err(format!( + "Insufficient permissions to write to '{}'. Please run the benchmark as root or with appropriate capabilities (CAP_SYS_ADMIN). Error: {}", + enable_path, e + )); + } else { + return Err(format!("Failed to enable listener: {}", e)); + } + } + } + + if was_enabled { + println!( + "User events listener was already enabled for provider: {}", + provider_name + ); + } else { + println!( + "User events listener enabled for provider: {}", + provider_name + ); + } + + Ok(UserEventsListenerGuard { + provider_name: provider_name.to_string(), + was_enabled, + is_dummy: false, + }) + } + + /// Check if user events are available on the system + /// + /// This method checks if the user_events subsystem is available by + /// reading from `/sys/kernel/tracing/user_events_status`. + /// + /// # Returns + /// * `Ok(String)` - The status content if user events are available + /// * `Err(String)` - Error message if user events are not available + fn check_user_events_available() -> Result { + match fs::read_to_string("/sys/kernel/tracing/user_events_status") { + Ok(status) => Ok(status), + Err(e) => { + if e.kind() == io::ErrorKind::PermissionDenied { + Err(format!( + "Insufficient permissions to read '/sys/kernel/tracing/user_events_status'. Please run the benchmark as root or with appropriate capabilities (CAP_SYS_ADMIN). Error: {}", + e + )) + } else if e.kind() == io::ErrorKind::NotFound { + Err("User events subsystem not available on this system".to_string()) + } else { + Err(format!("Failed to check user events availability: {}", e)) + } + } + } + } + + /// Create a dummy guard that performs no action on drop + /// + /// This is used when enabling the listener fails; it ensures the + /// benchmark can proceed without attempting to disable anything later. + fn dummy_guard() -> Self { + UserEventsListenerGuard { + provider_name: DUMMY_PROVIDER_NAME.to_string(), + was_enabled: false, // Not relevant for dummy guards + is_dummy: true, + } + } +} + +impl Drop for UserEventsListenerGuard { + fn drop(&mut self) { + let disable_path = format!( + "/sys/kernel/debug/tracing/events/user_events/{}{}/enable", + self.provider_name, USER_EVENTS_PROVIDER_SUFFIX + ); + + // Skip cleanup for dummy guards + if self.is_dummy { + return; + } + + // Only disable if it wasn't already enabled + if !self.was_enabled { + match fs::write(&disable_path, b"0\n") { + Ok(_) => { + eprintln!( + "User events listener disabled for provider: {}", + self.provider_name + ); + } + Err(e) => { + if e.kind() == io::ErrorKind::PermissionDenied { + eprintln!( + "Failed to disable listener due to insufficient permissions. Please run the benchmark as root or with appropriate capabilities (CAP_SYS_ADMIN). Error: {}", + e + ); + } else { + eprintln!("Failed to disable listener: {}", e); + } + } + } + } else { + eprintln!( + "User events listener was already enabled, leaving enabled for provider: {}", + self.provider_name + ); + } + } +} + +/// Helper function to enable user events listener with fallback to dummy guard +/// +/// This function attempts to enable the user events listener for the given provider. +/// If enabling fails, it prints a warning message and returns a dummy guard that +/// performs no operations. This ensures benchmarks can proceed even when the +/// listener cannot be enabled. +/// +/// # Arguments +/// * `provider_name` - The name of the provider to enable +/// +/// # Returns +/// * `UserEventsListenerGuard` - Either a real guard or a dummy guard +fn enable_listener_with_fallback(provider_name: &str) -> UserEventsListenerGuard { + UserEventsListenerGuard::enable(provider_name).unwrap_or_else(|e| { + eprintln!("Warning: Failed to enable listener: {}", e); + eprintln!("Benchmarks will run without listener enabled"); + // Return a dummy guard that does nothing on drop + UserEventsListenerGuard::dummy_guard() + }) +} + #[cfg(feature = "experimental_eventname_callback")] struct EventNameFromLogRecordEventName; @@ -64,7 +291,7 @@ impl EventNameCallback for EventNameFromLogRecordCustom { } fn setup_provider_default() -> SdkLoggerProvider { - let user_event_processor = Processor::builder("myprovider").build().unwrap(); + let user_event_processor = Processor::builder(PROVIDER_NAME).build().unwrap(); SdkLoggerProvider::builder() .with_resource( @@ -81,7 +308,7 @@ fn setup_provider_with_callback(event_name_callback: C) -> SdkLoggerProvider where C: EventNameCallback + 'static, { - let user_event_processor = Processor::builder("myprovider") + let user_event_processor = Processor::builder(PROVIDER_NAME) .with_event_name_callback(event_name_callback) .build() .unwrap(); @@ -97,91 +324,241 @@ where } fn benchmark_4_attributes(c: &mut Criterion) { - let provider = setup_provider_default(); - let ot_layer = tracing_layer::OpenTelemetryTracingBridge::new(&provider); - let subscriber = Registry::default().with(ot_layer); - - tracing::subscriber::with_default(subscriber, || { - c.bench_function("User_Event_4_Attributes", |b| { - b.iter(|| { - error!( - name : "CheckoutFailed", - field1 = "field1", - field2 = "field2", - field3 = "field3", - field4 = "field4", - message = "Unable to process checkout." - ); + // Check if user events are available + if let Err(e) = UserEventsListenerGuard::check_user_events_available() { + eprintln!("Warning: User events not available: {}", e); + eprintln!("Benchmarks will run without listener enabled"); + } + + let mut group = c.benchmark_group("User_Event_4_Attributes"); + + // Benchmark with listener disabled + { + let provider = setup_provider_default(); + let ot_layer = tracing_layer::OpenTelemetryTracingBridge::new(&provider); + let subscriber = Registry::default().with(ot_layer); + + tracing::subscriber::with_default(subscriber, || { + group.bench_function("disabled", |b| { + b.iter(|| { + error!( + name : "CheckoutFailed", + field1 = "field1", + field2 = "field2", + field3 = "field3", + field4 = "field4", + message = "Unable to process checkout." + ); + }); + }); + }); + } + + // Benchmark with listener enabled + { + let provider = setup_provider_default(); + // Enable listener with RAII guard (after provider is built so tracepoints exist) + let _guard = enable_listener_with_fallback(PROVIDER_NAME); + let ot_layer = tracing_layer::OpenTelemetryTracingBridge::new(&provider); + let subscriber = Registry::default().with(ot_layer); + + tracing::subscriber::with_default(subscriber, || { + group.bench_function("enabled", |b| { + b.iter(|| { + error!( + name : "CheckoutFailed", + field1 = "field1", + field2 = "field2", + field3 = "field3", + field4 = "field4", + message = "Unable to process checkout." + ); + }); }); }); - }); + } + + group.finish(); } #[cfg(feature = "experimental_eventname_callback")] fn benchmark_4_attributes_event_name_custom(c: &mut Criterion) { - let provider = setup_provider_with_callback(EventNameFromLogRecordCustom); - let ot_layer = tracing_layer::OpenTelemetryTracingBridge::new(&provider); - let subscriber = Registry::default().with(ot_layer); - - tracing::subscriber::with_default(subscriber, || { - c.bench_function("User_Event_4_Attributes_EventName_Custom", |b| { - b.iter(|| { - error!( - name : "CheckoutFailed", - field1 = "field1", - field2 = "field2", - field3 = "field3", - field4 = "field4", - message = "Unable to process checkout." - ); + // Check if user events are available + if let Err(e) = UserEventsListenerGuard::check_user_events_available() { + eprintln!("Warning: User events not available: {}", e); + eprintln!("Benchmarks will run without listener enabled"); + } + + let mut group = c.benchmark_group("User_Event_4_Attributes_EventName_Custom"); + + // Benchmark with listener disabled + { + let provider = setup_provider_with_callback(EventNameFromLogRecordCustom); + let ot_layer = tracing_layer::OpenTelemetryTracingBridge::new(&provider); + let subscriber = Registry::default().with(ot_layer); + + tracing::subscriber::with_default(subscriber, || { + group.bench_function("disabled", |b| { + b.iter(|| { + error!( + name : "CheckoutFailed", + field1 = "field1", + field2 = "field2", + field3 = "field3", + field4 = "field4", + message = "Unable to process checkout." + ); + }); + }); + }); + } + + // Benchmark with listener enabled + { + let provider = setup_provider_with_callback(EventNameFromLogRecordCustom); + // Enable listener with RAII guard (after provider is built so tracepoints exist) + let _guard = enable_listener_with_fallback(PROVIDER_NAME); + let ot_layer = tracing_layer::OpenTelemetryTracingBridge::new(&provider); + let subscriber = Registry::default().with(ot_layer); + + tracing::subscriber::with_default(subscriber, || { + group.bench_function("enabled", |b| { + b.iter(|| { + error!( + name : "CheckoutFailed", + field1 = "field1", + field2 = "field2", + field3 = "field3", + field4 = "field4", + message = "Unable to process checkout." + ); + }); }); }); - }); + } + + group.finish(); } #[cfg(feature = "experimental_eventname_callback")] fn benchmark_4_attributes_event_name_from_log_record(c: &mut Criterion) { - let provider = setup_provider_with_callback(EventNameFromLogRecordEventName); - let ot_layer = tracing_layer::OpenTelemetryTracingBridge::new(&provider); - let subscriber = Registry::default().with(ot_layer); - - tracing::subscriber::with_default(subscriber, || { - c.bench_function("User_Event_4_Attributes_EventName_FromLogRecord", |b| { - b.iter(|| { - error!( - name : "CheckoutFailed", - field1 = "field1", - field2 = "field2", - field3 = "field3", - field4 = "field4", - message = "Unable to process checkout." - ); + // Check if user events are available + if let Err(e) = UserEventsListenerGuard::check_user_events_available() { + eprintln!("Warning: User events not available: {}", e); + eprintln!("Benchmarks will run without listener enabled"); + } + + let mut group = c.benchmark_group("User_Event_4_Attributes_EventName_FromLogRecord"); + + // Benchmark with listener disabled + { + let provider = setup_provider_with_callback(EventNameFromLogRecordEventName); + let ot_layer = tracing_layer::OpenTelemetryTracingBridge::new(&provider); + let subscriber = Registry::default().with(ot_layer); + + tracing::subscriber::with_default(subscriber, || { + group.bench_function("disabled", |b| { + b.iter(|| { + error!( + name : "CheckoutFailed", + field1 = "field1", + field2 = "field2", + field3 = "field3", + field4 = "field4", + message = "Unable to process checkout." + ); + }); }); }); - }); + } + + // Benchmark with listener enabled + { + let provider = setup_provider_with_callback(EventNameFromLogRecordEventName); + // Enable listener with RAII guard (after provider is built so tracepoints exist) + let _guard = enable_listener_with_fallback(PROVIDER_NAME); + let ot_layer = tracing_layer::OpenTelemetryTracingBridge::new(&provider); + let subscriber = Registry::default().with(ot_layer); + + tracing::subscriber::with_default(subscriber, || { + group.bench_function("enabled", |b| { + b.iter(|| { + error!( + name : "CheckoutFailed", + field1 = "field1", + field2 = "field2", + field3 = "field3", + field4 = "field4", + message = "Unable to process checkout." + ); + }); + }); + }); + } + + group.finish(); } fn benchmark_6_attributes(c: &mut Criterion) { - let provider = setup_provider_default(); - let ot_layer = tracing_layer::OpenTelemetryTracingBridge::new(&provider); - let subscriber = Registry::default().with(ot_layer); - - tracing::subscriber::with_default(subscriber, || { - c.bench_function("User_Event_6_Attributes", |b| { - b.iter(|| { - error!( - name : "CheckoutFailed", - field1 = "field1", - field2 = "field2", - field3 = "field3", - field4 = "field4", - field5 = "field5", - field6 = "field6", - message = "Unable to process checkout." - ); + // Check if user events are available + if let Err(e) = UserEventsListenerGuard::check_user_events_available() { + eprintln!("Warning: User events not available: {}", e); + eprintln!("Benchmarks will run without listener enabled"); + } + + let mut group = c.benchmark_group("User_Event_6_Attributes"); + + // Benchmark with listener disabled + { + let provider = setup_provider_default(); + let ot_layer = tracing_layer::OpenTelemetryTracingBridge::new(&provider); + let subscriber = Registry::default().with(ot_layer); + + tracing::subscriber::with_default(subscriber, || { + group.bench_function("disabled", |b| { + b.iter(|| { + error!( + name : "CheckoutFailed", + field1 = "field1", + field2 = "field2", + field3 = "field3", + field4 = "field4", + field5 = "field5", + field6 = "field6", + message = "Unable to process checkout." + ); + }); }); }); - }); + } + + // Benchmark with listener enabled + { + let provider = setup_provider_default(); + // Enable listener with RAII guard (after provider is built so tracepoints exist) + let _guard = enable_listener_with_fallback(PROVIDER_NAME); + let ot_layer = tracing_layer::OpenTelemetryTracingBridge::new(&provider); + let subscriber = Registry::default().with(ot_layer); + + tracing::subscriber::with_default(subscriber, || { + group.bench_function("enabled", |b| { + b.iter(|| { + error!( + name : "CheckoutFailed", + field1 = "field1", + field2 = "field2", + field3 = "field3", + field4 = "field4", + field5 = "field5", + field6 = "field6", + message = "Unable to process checkout." + ); + }); + }); + }); + } + + group.finish(); } fn criterion_benchmark(c: &mut Criterion) {