refactor to use a overhead sample type to safe on samples

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

@@ -61,7 +61,7 @@ impl AllocationProfilingStats {
         self.next_sample = self.poisson.sample(&mut self.rng) as i64;
     }
 
-    fn track_allocation(&mut self, len: size_t, start: Instant) {
+    fn track_allocation(&mut self, len: size_t, overhead_start: Instant) {
         self.next_sample -= len as i64;
 
         if self.next_sample > 0 {
@@ -81,11 +81,10 @@ impl AllocationProfilingStats {
                         zend::ddog_php_prof_get_current_execute_data(),
                         1_i64,
                         len as i64,
+                        overhead_start,
                         &locals,
                     )
                 };
-
-                profiler.collect_overhead(start, "allocation", &locals);
             }
         });
     }

profiling/src/exception.rs

@@ -59,11 +59,10 @@ impl ExceptionProfilingStats {
                     profiler.collect_exception(
                         zend::ddog_php_prof_get_current_execute_data(),
                         name,
+                        start,
                         &locals,
                     )
                 };
-
-                profiler.collect_overhead(start, "exception", &locals);
             }
         });
     }

profiling/src/lib.rs

@@ -1027,12 +1027,15 @@ fn interrupt_function(execute_data: *mut zend::zend_execute_data) {
         }
 
         if let Some(profiler) = PROFILER.lock().unwrap().as_ref() {
-            let start = Instant::now();
+            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_overhead(start, "time", &locals);
+            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,
@@ -934,58 +947,6 @@ impl Profiler {
         }
     }
 
-    #[cfg(feature = "timeline")]
-    /// collect a stack frame for garbage collection.
-    /// as we do not know about the overhead currently, we only collect a fake frame.
-    pub fn collect_overhead(&self, start: Instant, reason: &'static str, locals: &RequestLocals) {
-        let mut labels = Profiler::message_labels();
-
-        lazy_static! {
-            static ref TIMELINE_GC_LABELS: Vec<Label> = vec![Label {
-                key: "event",
-                value: LabelValue::Str("stack walk".into()),
-            },];
-        }
-
-        labels.extend_from_slice(&TIMELINE_GC_LABELS);
-        labels.push(Label {
-            key: "reason",
-            value: LabelValue::Str(Cow::from(reason)),
-        });
-        labels.push(Label {
-            key: "end_timestamp_ns",
-            value: LabelValue::Num(
-                SystemTime::now()
-                    .duration_since(UNIX_EPOCH)
-                    .unwrap()
-                    .as_nanos() as i64,
-                None,
-            ),
-        });
-        let n_labels = labels.len();
-
-        match self.send_sample(Profiler::prepare_sample_message(
-            vec![ZendFrame {
-                function: "[stack walk]".into(),
-                file: None,
-                line: 0,
-            }],
-            SampleValues {
-                timeline: start.elapsed().as_nanos() as i64,
-                ..Default::default()
-            },
-            labels,
-            locals,
-        )) {
-            Ok(_) => {
-                trace!("Sent event 'stack walk' with {n_labels} labels and reason {reason} to profiler.")
-            }
-            Err(err) => {
-                warn!("Failed to send event 'stack walk' with {n_labels} and reason {reason} labels to profiler: {err}")
-            }
-        }
-    }
-
     fn message_labels() -> Vec<Label> {
         let gpc = unsafe { datadog_php_profiling_get_profiling_context };
         if let Some(get_profiling_context) = gpc {
@@ -1022,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());
@@ -1051,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]);
@@ -1144,6 +1112,7 @@ mod tests {
             alloc_size: 50,
             timeline: 60,
             exception: 70,
+            overhead: 80,
         }
     }
 

profiling/src/timeline.rs

@@ -66,7 +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 start_overhead = Instant::now();
+        let overhead_start = Instant::now();
         let now = SystemTime::now().duration_since(UNIX_EPOCH);
 
         // eval() failed
@@ -97,9 +97,9 @@ unsafe extern "C" fn ddog_php_prof_compile_string(
                     duration.as_nanos() as i64,
                     filename,
                     line,
+                    overhead_start,
                     &locals,
                 );
-                profiler.collect_overhead(start_overhead, "timeline", &locals);
             }
         });
         return op_array;
@@ -130,7 +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 start_overhead = Instant::now();
+        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
@@ -172,9 +172,9 @@ unsafe extern "C" fn ddog_php_prof_compile_file(
                     duration.as_nanos() as i64,
                     filename,
                     include_type,
+                    overhead_start,
                     &locals,
                 );
-                profiler.collect_overhead(start_overhead, "timeline", &locals);
             }
         });
         return op_array;
@@ -220,7 +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 start_overhead = Instant::now();
+        let overhead_start = Instant::now();
         let now = SystemTime::now().duration_since(UNIX_EPOCH);
         if now.is_err() {
             // time went backwards
@@ -255,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 {
@@ -264,11 +265,11 @@ unsafe extern "C" fn ddog_php_prof_gc_collect_cycles() -> i32 {
                             duration.as_nanos() as i64,
                             reason,
                             collected as i64,
+                            overhead_start,
                             &locals,
                         );
                     }
                 }
-                profiler.collect_overhead(start_overhead, "timeline", &locals);
             }
         });
         collected