From 6412563e9cd3c0df0627c08f9072c66ac2c07eea Mon Sep 17 00:00:00 2001 From: Levi Morrison Date: Fri, 14 Feb 2025 13:41:52 -0700 Subject: [PATCH] feat(prof): add 'tracing' features This adds tracing features to the profiler. These are not meant to be enabled for customer builds at this time. The goal is to use this data to enable benchmarking and other useful tools during development. Currently it's turned on by the RUST_LOG env var. We may want to move some of our logging of the PHP lifecycle to use this in the future. --- Cargo.lock | 2 ++ profiling/Cargo.toml | 26 ++++++++------ profiling/src/lib.rs | 35 +++++++++++++++++- profiling/src/profiling/mod.rs | 10 ++++++ profiling/src/profiling/stack_walking.rs | 45 +++++++++++++----------- profiling/src/pthread.rs | 2 +- 6 files changed, 87 insertions(+), 33 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 32efa4af9e..320a8fbefe 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1472,6 +1472,8 @@ dependencies = [ "rustc-hash", "serde_json", "thiserror 2.0.11", + "tracing", + "tracing-subscriber", "uuid", ] diff --git a/profiling/Cargo.toml b/profiling/Cargo.toml index ef19028f97..b992116f41 100644 --- a/profiling/Cargo.toml +++ b/profiling/Cargo.toml @@ -11,6 +11,19 @@ bench = false # disables cargo build in libtest bench # See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html +[features] +default = ["allocation_profiling", "exception_profiling", "timeline"] +allocation_profiling = [] +exception_profiling = [] +timeline = [] +stack_walking_tests = [] +test = [] + +# Not for prod: +tracing = ["dep:tracing"] +tracing-subscriber = ["tracing", "dep:tracing-subscriber"] +trigger_time_sample = [] + [dependencies] # Avoid ahash 0.8.7 we run into https://github.com/tkaitchuck/aHash/issues/195. ahash = { version = "0.8.11" } @@ -34,6 +47,8 @@ rand = { version = "0.8.5" } rand_distr = { version = "0.4.3" } rustc-hash = "1.1.0" thiserror = "2" +tracing = { version = "0.1", optional = true } +tracing-subscriber = { version = "0.3", optional = true, features = ["env-filter"] } uuid = { version = "1.0", features = ["v4"] } [dev-dependencies] @@ -48,17 +63,6 @@ perfcnt = "0.8.0" name = "stack_walking" harness = false -[features] -default = ["allocation_profiling", "timeline", "exception_profiling"] -allocation_profiling = [] -timeline = [] -exception_profiling = [] -stack_walking_tests = [] -test = [] - -# only for testing: -trigger_time_sample = [] - [build-dependencies] bindgen = { version = "0.69.4" } cc = { version = "1.0" } diff --git a/profiling/src/lib.rs b/profiling/src/lib.rs index f9f6434644..585da2bc2b 100644 --- a/profiling/src/lib.rs +++ b/profiling/src/lib.rs @@ -226,6 +226,7 @@ unsafe extern "C" fn gshutdown(_globals_ptr: *mut c_void) { * Be careful out there! */ extern "C" fn minit(_type: c_int, module_number: c_int) -> ZendResult { + // todo: merge these lifecycle things to tracing feature? /* When developing the extension, it's useful to see log messages that * occur before the user can configure the log level. However, if we * initialized the logger here unconditionally then they'd have no way to @@ -237,6 +238,13 @@ extern "C" fn minit(_type: c_int, module_number: c_int) -> ZendResult { trace!("MINIT({_type}, {module_number})"); } + #[cfg(feature = "tracing-subscriber")] + tracing_subscriber::fmt() + .with_env_filter(tracing_subscriber::EnvFilter::from_default_env()) + .with_writer(std::io::stderr) + .with_span_events(tracing_subscriber::fmt::format::FmtSpan::CLOSE) + .init(); + #[cfg(target_vendor = "apple")] { /* If PHP forks and certain ObjC classes are not initialized before the @@ -444,10 +452,22 @@ static mut ZAI_CONFIG_ONCE: Once = Once::new(); /// The mut here is *only* for resetting this back to uninitialized each minit. static mut RINIT_ONCE: Once = Once::new(); +#[cfg(feature = "tracing")] +thread_local! { + static REQUEST_SPAN: RefCell> = const { + RefCell::new(None) + }; +} + /* If Failure is returned the VM will do a C exit; try hard to avoid that, * using it for catastrophic errors only. */ extern "C" fn rinit(_type: c_int, _module_number: c_int) -> ZendResult { + #[cfg(feature = "tracing")] + REQUEST_SPAN.set(Some(tracing::info_span!("request").entered())); + + let _rinit_span = tracing::info_span!("rinit").entered(); + #[cfg(debug_assertions)] trace!("RINIT({_type}, {_module_number})"); @@ -626,6 +646,9 @@ fn add_tag(tags: &mut Vec, key: &str, value: &str) { } extern "C" fn rshutdown(_type: c_int, _module_number: c_int) -> ZendResult { + let _rshutdown_span = tracing::info_span!("rshutdown").entered(); + + // todo: merge these lifecycle things to tracing feature? #[cfg(debug_assertions)] trace!("RSHUTDOWN({_type}, {_module_number})"); @@ -657,6 +680,9 @@ extern "C" fn rshutdown(_type: c_int, _module_number: c_int) -> ZendResult { #[cfg(feature = "allocation_profiling")] allocation::alloc_prof_rshutdown(); + #[cfg(feature = "tracing")] + REQUEST_SPAN.take(); + ZendResult::Success } @@ -664,6 +690,7 @@ extern "C" fn rshutdown(_type: c_int, _module_number: c_int) -> ZendResult { /// including calling variadic functions. It's essentially all unsafe, so be /// careful, and do not call this manually (only let the engine call it). unsafe extern "C" fn minfo(module_ptr: *mut zend::ModuleEntry) { + // todo: merge these lifecycle things to tracing feature? #[cfg(debug_assertions)] trace!("MINFO({:p})", module_ptr); @@ -842,6 +869,7 @@ unsafe extern "C" fn minfo(module_ptr: *mut zend::ModuleEntry) { } extern "C" fn mshutdown(_type: c_int, _module_number: c_int) -> ZendResult { + // todo: merge these lifecycle things to tracing feature? #[cfg(debug_assertions)] trace!("MSHUTDOWN({_type}, {_module_number})"); @@ -860,6 +888,7 @@ extern "C" fn mshutdown(_type: c_int, _module_number: c_int) -> ZendResult { } extern "C" fn startup(extension: *mut ZendExtension) -> ZendResult { + // todo: merge these lifecycle things to tracing feature? #[cfg(debug_assertions)] trace!("startup({:p})", extension); @@ -889,6 +918,10 @@ extern "C" fn startup(extension: *mut ZendExtension) -> ZendResult { } extern "C" fn shutdown(extension: *mut ZendExtension) { + #[cfg(feature = "tracing")] + let _shutdown_span = tracing::info_span!("shutdown").entered(); + + // todo: merge these lifecycle things to tracing feature? #[cfg(debug_assertions)] trace!("shutdown({:p})", extension); @@ -946,4 +979,4 @@ fn notify_trace_finished(local_root_span_id: u64, span_type: Cow, resource: } } }); -} \ No newline at end of file +} diff --git a/profiling/src/profiling/mod.rs b/profiling/src/profiling/mod.rs index 37e6e8bee7..9206e91c92 100644 --- a/profiling/src/profiling/mod.rs +++ b/profiling/src/profiling/mod.rs @@ -755,6 +755,7 @@ impl Profiler { /// Collect a stack sample with elapsed wall time. Collects CPU time if /// it's enabled and available. + #[cfg_attr(feature = "tracing", tracing::instrument(skip_all, level = "debug"))] pub fn collect_time(&self, execute_data: *mut zend_execute_data, interrupt_count: u32) { // todo: should probably exclude the wall and CPU time used by collecting the sample. let interrupt_count = interrupt_count as i64; @@ -809,6 +810,7 @@ impl Profiler { /// Collect a stack sample with memory allocations. #[cfg(feature = "allocation_profiling")] + #[cfg_attr(feature = "tracing", tracing::instrument(skip_all))] pub fn collect_allocations( &self, execute_data: *mut zend_execute_data, @@ -848,6 +850,7 @@ impl Profiler { /// Collect a stack sample with exception. #[cfg(feature = "exception_profiling")] + #[cfg_attr(feature = "tracing", tracing::instrument(skip_all))] pub fn collect_exception( &self, execute_data: *mut zend_execute_data, @@ -919,6 +922,7 @@ impl Profiler { }]; #[cfg(feature = "timeline")] + #[cfg_attr(feature = "tracing", tracing::instrument(skip_all))] pub fn collect_compile_string(&self, now: i64, duration: i64, filename: String, line: u32) { let mut labels = Profiler::common_labels(Self::TIMELINE_COMPILE_FILE_LABELS.len()); labels.extend_from_slice(Self::TIMELINE_COMPILE_FILE_LABELS); @@ -949,6 +953,7 @@ impl Profiler { } #[cfg(feature = "timeline")] + #[cfg_attr(feature = "tracing", tracing::instrument(skip_all, level = "debug"))] pub fn collect_compile_file( &self, now: i64, @@ -991,6 +996,7 @@ impl Profiler { /// This function will collect a thread start or stop timeline event #[cfg(all(feature = "timeline", php_zts))] + #[cfg_attr(feature = "tracing", tracing::instrument(skip_all, level = "debug"))] pub fn collect_thread_start_end(&self, now: i64, event: &'static str) { let mut labels = Profiler::common_labels(1); @@ -1025,6 +1031,7 @@ impl Profiler { /// This function can be called to collect any fatal errors #[cfg(feature = "timeline")] + #[cfg_attr(feature = "tracing", tracing::instrument(skip_all, level = "debug"))] pub fn collect_fatal(&self, now: i64, file: String, line: u32, message: String) { let mut labels = Profiler::common_labels(2); @@ -1065,6 +1072,7 @@ impl Profiler { /// This function can be called to collect an opcache restart #[cfg(all(feature = "timeline", php_opcache_restart_hook))] + #[cfg_attr(feature = "tracing", tracing::instrument(skip_all, level = "debug"))] pub(crate) fn collect_opcache_restart( &self, now: i64, @@ -1109,6 +1117,7 @@ impl Profiler { /// This function can be called to collect any kind of inactivity that is happening #[cfg(feature = "timeline")] + #[cfg_attr(feature = "tracing", tracing::instrument(skip_all, level = "debug"))] pub fn collect_idle(&self, now: i64, duration: i64, reason: &'static str) { let mut labels = Profiler::common_labels(1); @@ -1144,6 +1153,7 @@ impl Profiler { /// collect a stack frame for garbage collection. /// as we do not know about the overhead currently, we only collect a fake frame. #[cfg(feature = "timeline")] + #[cfg_attr(feature = "tracing", tracing::instrument(skip_all, level = "debug"))] pub fn collect_garbage_collection( &self, now: i64, diff --git a/profiling/src/profiling/stack_walking.rs b/profiling/src/profiling/stack_walking.rs index d1a2fc9831..063f5010db 100644 --- a/profiling/src/profiling/stack_walking.rs +++ b/profiling/src/profiling/stack_walking.rs @@ -1,13 +1,12 @@ -use crate::bindings::{zai_str_from_zstr, zend_execute_data, zend_function}; -use std::borrow::Cow; -use std::str::Utf8Error; - #[cfg(php_frameless)] use crate::bindings::zend_flf_functions; +use crate::bindings::{zai_str_from_zstr, zend_execute_data, zend_function}; #[cfg(php_frameless)] use crate::bindings::{ ZEND_FRAMELESS_ICALL_0, ZEND_FRAMELESS_ICALL_1, ZEND_FRAMELESS_ICALL_2, ZEND_FRAMELESS_ICALL_3, }; +use std::borrow::Cow; +use std::str::Utf8Error; const COW_PHP_OPEN_TAG: Cow = Cow::Borrowed(" = Cow::Borrowed("[truncated]"); @@ -62,22 +61,6 @@ pub fn extract_function_name(func: &zend_function) -> Option { Some(String::from_utf8_lossy(buffer.as_slice()).into_owned()) } -unsafe fn extract_file_and_line(execute_data: &zend_execute_data) -> (Option, u32) { - // This should be Some, just being cautious. - match execute_data.func.as_ref() { - Some(func) if !func.is_internal() => { - // Safety: zai_str_from_zstr will return a valid ZaiStr. - let file = zai_str_from_zstr(func.op_array.filename.as_mut()).into_string(); - let lineno = match execute_data.opline.as_ref() { - Some(opline) => opline.lineno, - None => 0, - }; - (Some(file), lineno) - } - _ => (None, 0), - } -} - #[cfg(php_run_time_cache)] mod detail { use super::*; @@ -199,6 +182,9 @@ mod detail { pub fn collect_stack_sample( top_execute_data: *mut zend_execute_data, ) -> Result, Utf8Error> { + #[cfg(feature = "tracing")] + let _span = tracing::trace_span!("collect_stack_sample").entered(); + CACHED_STRINGS.with(|cell| { let string_set: &mut StringSet = &mut cell.borrow_mut(); let max_depth = 512; @@ -354,6 +340,22 @@ mod detail { } } +unsafe fn extract_file_and_line(execute_data: &zend_execute_data) -> (Option, u32) { + // This should be Some, just being cautious. + match execute_data.func.as_ref() { + Some(func) if !func.is_internal() => { + // Safety: zai_str_from_zstr will return a valid ZaiStr. + let file = zai_str_from_zstr(func.op_array.filename.as_mut()).into_string(); + let lineno = match execute_data.opline.as_ref() { + Some(opline) => opline.lineno, + None => 0, + }; + (Some(file), lineno) + } + _ => (None, 0), + } +} + #[cfg(not(php_run_time_cache))] mod detail { use super::*; @@ -371,6 +373,9 @@ mod detail { pub fn collect_stack_sample( top_execute_data: *mut zend_execute_data, ) -> Result, Utf8Error> { + #[cfg(feature = "tracing")] + let _span = tracing::trace_span!("collect_stack_sample").entered(); + let max_depth = 512; let mut samples = Vec::with_capacity(max_depth >> 3); let mut execute_data_ptr = top_execute_data; diff --git a/profiling/src/pthread.rs b/profiling/src/pthread.rs index f448a71702..512631c671 100644 --- a/profiling/src/pthread.rs +++ b/profiling/src/pthread.rs @@ -46,4 +46,4 @@ unsafe extern "C" fn child() { // SAFETY: done after config is used to shut down other things, and in a // thread-safe context. config::on_fork_in_child(); -} \ No newline at end of file +}