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.

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

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<Option<tracing::span::EnteredSpan>> = 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<Tag>, 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,13 +680,17 @@ 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
 }
 
 /// Prints the module info. Calls many C functions from the Zend Engine,
 /// 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<str>, resource:
             }
         }
     });
-}
+}

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,

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<str> = Cow::Borrowed("<?php");
 const COW_TRUNCATED: Cow<str> = Cow::Borrowed("[truncated]");
@@ -62,22 +61,6 @@ pub fn extract_function_name(func: &zend_function) -> Option<String> {
     Some(String::from_utf8_lossy(buffer.as_slice()).into_owned())
 }
 
-unsafe fn extract_file_and_line(execute_data: &zend_execute_data) -> (Option<String>, 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<Vec<ZendFrame>, 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<String>, 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<Vec<ZendFrame>, 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;

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();
-}
+}