WIP: feat(profiling): track profiler overhead

profiling/Cargo.toml

@@ -44,9 +44,10 @@ name = "stack_walking"
 harness = false
 
 [features]
-default = ["allocation_profiling", "timeline", "exception_profiling"]
+default = ["overhead", "allocation_profiling", "timeline", "exception_profiling"]
 allocation_profiling = []
 timeline = []
+overhead = []
 exception_profiling = []
 stack_walking_tests = []
 

profiling/src/allocation.rs

@@ -8,6 +8,7 @@ use log::{debug, error, trace, warn};
 use rand::rngs::ThreadRng;
 use std::cell::RefCell;
 use std::ffi::CStr;
+use std::time::Instant;
 
 use rand_distr::{Distribution, Poisson};
 
@@ -60,7 +61,7 @@ impl AllocationProfilingStats {
         self.next_sample = self.poisson.sample(&mut self.rng) as i64;
     }
 
-    fn track_allocation(&mut self, len: size_t) {
+    fn track_allocation(&mut self, len: size_t, overhead_start: Instant) {
         self.next_sample -= len as i64;
 
         if self.next_sample > 0 {
@@ -75,12 +76,12 @@ impl AllocationProfilingStats {
             };
 
             if let Some(profiler) = PROFILER.lock().unwrap().as_ref() {
-                // Safety: execute_data was provided by the engine, and the profiler doesn't mutate it.
                 unsafe {
                     profiler.collect_allocations(
                         zend::ddog_php_prof_get_current_execute_data(),
                         1_i64,
                         len as i64,
+                        overhead_start,
                         &locals,
                     )
                 };
@@ -334,9 +335,11 @@ unsafe extern "C" fn alloc_profiling_malloc(len: size_t) -> *mut c_void {
         return ptr;
     }
 
+    let start = Instant::now();
+
     ALLOCATION_PROFILING_STATS.with(|cell| {
         let mut allocations = cell.borrow_mut();
-        allocations.track_allocation(len)
+        allocations.track_allocation(len, start);
     });
 
     ptr
@@ -387,9 +390,11 @@ unsafe extern "C" fn alloc_profiling_realloc(prev_ptr: *mut c_void, len: size_t)
         return ptr;
     }
 
+    let start = Instant::now();
+
     ALLOCATION_PROFILING_STATS.with(|cell| {
         let mut allocations = cell.borrow_mut();
-        allocations.track_allocation(len)
+        allocations.track_allocation(len, start);
     });
 
     ptr

profiling/src/exception.rs

@@ -3,11 +3,10 @@ use crate::PROFILER;
 use crate::REQUEST_LOCALS;
 use log::{error, info};
 use rand::rngs::ThreadRng;
-use std::cell::RefCell;
-use std::sync::atomic::AtomicU32;
-use std::sync::atomic::Ordering;
-
 use rand_distr::{Distribution, Poisson};
+use std::cell::RefCell;
+use std::sync::atomic::{AtomicU32, Ordering};
+use std::time::Instant;
 
 /// The engine's previous throw exception hook
 static mut PREV_ZEND_THROW_EXCEPTION_HOOK: Option<zend::VmZendThrowExceptionHook> = None;
@@ -40,7 +39,7 @@ impl ExceptionProfilingStats {
         self.next_sample = self.poisson.sample(&mut self.rng) as u32;
     }
 
-    fn track_exception(&mut self, name: String) {
+    fn track_exception(&mut self, name: String, start: Instant) {
         if let Some(next_sample) = self.next_sample.checked_sub(1) {
             self.next_sample = next_sample;
             return;
@@ -60,6 +59,7 @@ impl ExceptionProfilingStats {
                     profiler.collect_exception(
                         zend::ddog_php_prof_get_current_execute_data(),
                         name,
+                        start,
                         &locals,
                     )
                 };
@@ -120,14 +120,16 @@ unsafe extern "C" fn exception_profiling_throw_exception_hook(
     // traversed. Fortunately, this behavior can be easily identified by checking for a NULL
     // pointer.
     if exception_profiling && !exception.is_null() {
+        let start = Instant::now();
+
         #[cfg(php7)]
         let exception_name = (*(*exception).value.obj).class_name();
         #[cfg(php8)]
         let exception_name = (*exception).class_name();
 
         EXCEPTION_PROFILING_STATS.with(|cell| {
             let mut exceptions = cell.borrow_mut();
-            exceptions.track_exception(exception_name)
+            exceptions.track_exception(exception_name, start)
         });
     }
 

profiling/src/lib.rs

@@ -1027,8 +1027,15 @@ fn interrupt_function(execute_data: *mut zend::zend_execute_data) {
         }
 
         if let Some(profiler) = PROFILER.lock().unwrap().as_ref() {
+            let overhead_start = Instant::now();
+
             // Safety: execute_data was provided by the engine, and the profiler doesn't mutate it.
-            profiler.collect_time(execute_data, interrupt_count, locals.deref());
+            profiler.collect_time(
+                execute_data,
+                interrupt_count,
+                overhead_start,
+                locals.deref(),
+            );
         }
     });
 }

profiling/src/profiling/mod.rs

@@ -67,6 +67,7 @@ struct SampleValues {
     alloc_size: i64,
     timeline: i64,
     exception: i64,
+    overhead: i64,
 }
 
 const WALL_TIME_PERIOD: Duration = Duration::from_millis(10);
@@ -644,6 +645,7 @@ impl Profiler {
         &self,
         execute_data: *mut zend_execute_data,
         interrupt_count: u32,
+        overhead_start: Instant,
         locals: &RequestLocals,
     ) {
         // todo: should probably exclude the wall and CPU time used by collecting the sample.
@@ -671,6 +673,7 @@ impl Profiler {
                         interrupt_count,
                         wall_time,
                         cpu_time,
+                        overhead: overhead_start.elapsed().as_nanos() as i64,
                         ..Default::default()
                     },
                     labels,
@@ -698,6 +701,7 @@ impl Profiler {
         execute_data: *mut zend_execute_data,
         alloc_samples: i64,
         alloc_size: i64,
+        overhead_start: Instant,
         locals: &RequestLocals,
     ) {
         let result = collect_stack_sample(execute_data);
@@ -712,6 +716,7 @@ impl Profiler {
                     SampleValues {
                         alloc_size,
                         alloc_samples,
+                        overhead: overhead_start.elapsed().as_nanos() as i64,
                         ..Default::default()
                     },
                     labels,
@@ -738,6 +743,7 @@ impl Profiler {
         &self,
         execute_data: *mut zend_execute_data,
         exception: String,
+        start: Instant,
         locals: &RequestLocals,
     ) {
         let result = collect_stack_sample(execute_data);
@@ -756,6 +762,7 @@ impl Profiler {
                     frames,
                     SampleValues {
                         exception: 1,
+                        overhead: start.elapsed().as_nanos() as i64,
                         ..Default::default()
                     },
                     labels,
@@ -783,6 +790,7 @@ impl Profiler {
         duration: i64,
         filename: String,
         line: u32,
+        overhead_start: Instant,
         locals: &RequestLocals,
     ) {
         let mut labels = Profiler::message_labels();
@@ -805,6 +813,7 @@ impl Profiler {
             }],
             SampleValues {
                 timeline: duration,
+                overhead: overhead_start.elapsed().as_nanos() as i64,
                 ..Default::default()
             },
             labels,
@@ -829,6 +838,7 @@ impl Profiler {
         duration: i64,
         filename: String,
         include_type: &str,
+        overhead_start: Instant,
         locals: &RequestLocals,
     ) {
         let mut labels = Profiler::message_labels();
@@ -856,6 +866,7 @@ impl Profiler {
             }],
             SampleValues {
                 timeline: duration,
+                overhead: overhead_start.elapsed().as_nanos() as i64,
                 ..Default::default()
             },
             labels,
@@ -883,6 +894,7 @@ impl Profiler {
         reason: &'static str,
         collected: i64,
         #[cfg(php_gc_status)] runs: i64,
+        overhead_start: Instant,
         locals: &RequestLocals,
     ) {
         let mut labels = Profiler::message_labels();
@@ -919,6 +931,7 @@ impl Profiler {
             }],
             SampleValues {
                 timeline: duration,
+                overhead: overhead_start.elapsed().as_nanos() as i64,
                 ..Default::default()
             },
             labels,
@@ -970,25 +983,27 @@ impl Profiler {
         timestamp: i64,
     ) -> SampleMessage {
         // Lay this out in the same order as SampleValues
-        static SAMPLE_TYPES: &[ValueType; 7] = &[
+        static SAMPLE_TYPES: &[ValueType; 8] = &[
             ValueType::new("sample", "count"),
             ValueType::new("wall-time", "nanoseconds"),
             ValueType::new("cpu-time", "nanoseconds"),
             ValueType::new("alloc-samples", "count"),
             ValueType::new("alloc-size", "bytes"),
             ValueType::new("timeline", "nanoseconds"),
             ValueType::new("exception-samples", "count"),
+            ValueType::new("overhead", "nanoseconds"),
         ];
 
         // Allows us to slice the SampleValues as if they were an array.
-        let values: [i64; 7] = [
+        let values: [i64; 8] = [
             samples.interrupt_count,
             samples.wall_time,
             samples.cpu_time,
             samples.alloc_samples,
             samples.alloc_size,
             samples.timeline,
             samples.exception,
+            samples.overhead,
         ];
 
         let mut sample_types = Vec::with_capacity(SAMPLE_TYPES.len());
@@ -999,6 +1014,11 @@ impl Profiler {
             sample_types.extend_from_slice(&SAMPLE_TYPES[0..len]);
             sample_values.extend_from_slice(&values[0..len]);
 
+            #[cfg(feature = "overhead")]
+            sample_types.push(SAMPLE_TYPES[7]);
+            #[cfg(feature = "overhead")]
+            sample_values.push(values[7]);
+
             // alloc-samples, alloc-size
             if locals.profiling_allocation_enabled {
                 sample_types.extend_from_slice(&SAMPLE_TYPES[3..5]);
@@ -1092,6 +1112,7 @@ mod tests {
             alloc_size: 50,
             timeline: 60,
             exception: 70,
+            overhead: 80,
         }
     }
 

profiling/src/timeline.rs

@@ -66,6 +66,7 @@ unsafe extern "C" fn ddog_php_prof_compile_string(
         #[cfg(not(php_zend_compile_string_has_position))]
         let op_array = prev(source_string, filename);
         let duration = start.elapsed();
+        let overhead_start = Instant::now();
         let now = SystemTime::now().duration_since(UNIX_EPOCH);
 
         // eval() failed
@@ -96,6 +97,7 @@ unsafe extern "C" fn ddog_php_prof_compile_string(
                     duration.as_nanos() as i64,
                     filename,
                     line,
+                    overhead_start,
                     &locals,
                 );
             }
@@ -128,6 +130,7 @@ unsafe extern "C" fn ddog_php_prof_compile_file(
         let start = Instant::now();
         let op_array = prev(handle, r#type);
         let duration = start.elapsed();
+        let overhead_start = Instant::now();
         let now = SystemTime::now().duration_since(UNIX_EPOCH);
 
         // include/require failed, could be invalid PHP in file or file not found, or time went
@@ -169,6 +172,7 @@ unsafe extern "C" fn ddog_php_prof_compile_file(
                     duration.as_nanos() as i64,
                     filename,
                     include_type,
+                    overhead_start,
                     &locals,
                 );
             }
@@ -216,6 +220,7 @@ unsafe extern "C" fn ddog_php_prof_gc_collect_cycles() -> i32 {
         let start = Instant::now();
         let collected = prev();
         let duration = start.elapsed();
+        let overhead_start = Instant::now();
         let now = SystemTime::now().duration_since(UNIX_EPOCH);
         if now.is_err() {
             // time went backwards
@@ -250,6 +255,7 @@ unsafe extern "C" fn ddog_php_prof_gc_collect_cycles() -> i32 {
                             reason,
                             collected as i64,
                             status.runs as i64,
+                            overhead_start,
                             &locals,
                         );
                     } else {
@@ -259,6 +265,7 @@ unsafe extern "C" fn ddog_php_prof_gc_collect_cycles() -> i32 {
                             duration.as_nanos() as i64,
                             reason,
                             collected as i64,
+                            overhead_start,
                             &locals,
                         );
                     }