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 +}