feat(prof): improve time sample accuracy by gathering during allocation samples (#3559)

morrisonlevi · realFlowControl · web-flow · commit a700b4d026c5 · 2026-01-21T11:01:50.000-07:00
* perf(profiling): piggyback time samples onto allocation samples When allocation profiler takes a sample and interrupt_count > 0, collect both allocation and time samples in a single stack walk. Benefits: - Eliminates redundant stack walks when samples coincide. - Improves time sample accuracy (closer to timer expiry). * refactor orderings of collect_* and extract helpers * refactor(test): allocation + CPU combined tests * refactor: make jq for combined samples less brittle * refactor: revert Ordering optimizations Let's do this in a dedicated PR. * style: use SAFETY instead of Safety * test: hammer piggybacking * refactor: simplify test and hook it up properly * test: fix prof-correctness * ci(profiling): run allocation_time_combined on PHP 8.4+ * test(profiling): fix allocation_time_combined float->int * ci(profiling): update expected data * ci(profiling): run allocation_time_combined with ALLOCATION_SAMPLING_DISTANCE=1 * ci(profiling): ignore main for wall-time for allocation_time_combined * EXPERIMENTAL: check ZEND_OP_DATA too * DEBUG: do we hit frameless icalls? * DEBUG: more info in panic * refactor: simplify Profiler::get_timeline_timestamp * Revert "DEBUG: more info in panic" This reverts commit a3e3e4e. * Revert "DEBUG: do we hit frameless icalls?" This reverts commit e16e1b1. * undo experimental debugging * test: fix expected log message * test: use more replaces to exaggerate effect * EXPERIMENT: show leaf frame * do not fail fast, finish prof correctness * upload artifacts * Disable Xdebug for prof-correctness * Revert "upload artifacts" This reverts commit 44e2734. * test: allow any non-zero wall-time for piggy-backed samples * remove first_frame for performance * Remove misleading strlen and comment Co-authored-by: Florian Engelhardt <florian.engelhardt@datadoghq.com>
diff --git a/.github/workflows/prof_correctness.yml b/.github/workflows/prof_correctness.yml
@@ -9,8 +9,9 @@ jobs:
   prof-correctness:
     runs-on: ubuntu-24.04
     strategy:
+      fail-fast: false
       matrix:
-        php-version: [8.0, 8.1, 8.2, 8.3, 8.4, 8.5]
+        php-version: ['8.0', '8.1', '8.2', '8.3', '8.4', '8.5']
         phpts: [nts, zts]
         include:
           - phpts: zts
@@ -109,6 +110,26 @@ jobs:
           USE_ZEND_ALLOC=0 php -d extension=$PWD/target/profiler-release/libdatadog_php_profiling.so profiling/tests/correctness/allocations.php
           unset DD_PROFILING_ALLOCATION_SAMPLING_DISTANCE
 
+      - name: Run allocation_time_combined test (PHP 8.4+)
+        if: fromJSON(matrix.php-version) >= 8.4
+        run: |
+          export DD_PROFILING_LOG_LEVEL=trace
+          export DD_PROFILING_EXPERIMENTAL_FEATURES_ENABLED=1
+          export DD_PROFILING_EXPERIMENTAL_EXCEPTION_SAMPLING_DISTANCE=1
+          export DD_PROFILING_EXCEPTION_MESSAGE_ENABLED=1
+          php -v
+          php -d extension=target/profiler-release/libdatadog_php_profiling.so --ri datadog-profiling
+          mkdir -p profiling/tests/correctness/allocation_time_combined/
+          export DD_PROFILING_OUTPUT_PPROF=$PWD/profiling/tests/correctness/allocation_time_combined/test.pprof
+          export DD_PROFILING_ALLOCATION_ENABLED=yes
+          export DD_PROFILING_ALLOCATION_SAMPLING_DISTANCE=1
+          export DD_PROFILING_WALL_TIME_ENABLED=yes
+          export DD_PROFILING_EXPERIMENTAL_CPU_TIME_ENABLED=no
+          export DD_PROFILING_ENDPOINT_COLLECTION_ENABLED=no
+          export EXECUTION_TIME=5
+          php -d extension=$PWD/target/profiler-release/libdatadog_php_profiling.so profiling/tests/correctness/allocation_time_combined.php
+          unset DD_PROFILING_ALLOCATION_ENABLED DD_PROFILING_ALLOCATION_SAMPLING_DISTANCE DD_PROFILING_WALL_TIME_ENABLED DD_PROFILING_EXPERIMENTAL_CPU_TIME_ENABLED DD_PROFILING_ENDPOINT_COLLECTION_ENABLED EXECUTION_TIME
+
       - name: Run ZTS tests
         if: matrix.phpts == 'zts'
         run: |
@@ -160,6 +181,13 @@ jobs:
           expected_json: profiling/tests/correctness/timeline.json
           pprof_path: profiling/tests/correctness/timeline/
 
+      - name: Check profiler correctness for allocation_time_combined
+        if: fromJSON(matrix.php-version) >= 8.4
+        uses: Datadog/prof-correctness/analyze@main
+        with:
+          expected_json: profiling/tests/correctness/allocation_time_combined.json
+          pprof_path: profiling/tests/correctness/allocation_time_combined/
+
       - name: Check profiler correctness for exceptions ZTS
         if: matrix.phpts == 'zts'
         uses: Datadog/prof-correctness/analyze@main
diff --git a/profiling/src/allocation/mod.rs b/profiling/src/allocation/mod.rs
@@ -92,12 +92,21 @@ impl AllocationProfilingStats {
 #[cold]
 pub fn collect_allocation(len: size_t) {
     if let Some(profiler) = Profiler::get() {
-        // Safety: execute_data was provided by the engine, and the profiler doesn't mutate it.
+        // Check if there's a pending time interrupt that we can handle now
+        // instead of waiting for an interrupt handler. This is slightly more
+        // accurate and efficient, win-win.
+        let interrupt_count = REQUEST_LOCALS
+            .try_with_borrow(|locals| locals.interrupt_count.swap(0, Ordering::SeqCst))
+            .unwrap_or(0);
+
+        // 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,
+                (interrupt_count > 0).then_some(interrupt_count),
             )
         };
     }
diff --git a/profiling/src/profiling/mod.rs b/profiling/src/profiling/mod.rs
@@ -917,14 +917,7 @@ impl Profiler {
                 let labels = Profiler::common_labels(0);
                 let n_labels = labels.len();
 
-                let mut timestamp = NO_TIMESTAMP;
-                {
-                    if self.is_timeline_enabled() {
-                        if let Ok(now) = SystemTime::now().duration_since(UNIX_EPOCH) {
-                            timestamp = now.as_nanos() as i64;
-                        }
-                    }
-                }
+                let timestamp = self.get_timeline_timestamp();
 
                 match self.prepare_and_send_message(
                     frames,
@@ -951,33 +944,51 @@ impl Profiler {
         }
     }
 
-    /// Collect a stack sample with memory allocations.
+    /// Collect a stack sample with memory allocations, and optionally time data.
+    ///
+    /// When `interrupt_count` is provided, this piggybacks time sampling onto
+    /// allocation sampling to avoid redundant stack walks.
     #[cfg_attr(feature = "tracing", tracing::instrument(skip_all))]
     pub fn collect_allocations(
         &self,
         execute_data: *mut zend_execute_data,
         alloc_samples: i64,
         alloc_size: i64,
+        interrupt_count: Option<u32>,
     ) {
         let result = collect_stack_sample(execute_data);
         match result {
             Ok(frames) => {
                 let depth = frames.len();
+
+                // Optionally collect time data when interrupt_count is provided
+                let (interrupt_count, wall_time, cpu_time, timestamp) =
+                    if let Some(count) = interrupt_count {
+                        let (wall_time, cpu_time) = CLOCKS.with_borrow_mut(Clocks::rotate_clocks);
+                        let timestamp = self.get_timeline_timestamp();
+                        (count as i64, wall_time, cpu_time, timestamp)
+                    } else {
+                        (0, 0, 0, NO_TIMESTAMP)
+                    };
+
                 let labels = Profiler::common_labels(0);
                 let n_labels = labels.len();
 
                 match self.prepare_and_send_message(
                     frames,
                     SampleValues {
-                        alloc_size,
+                        interrupt_count,
+                        wall_time,
+                        cpu_time,
                         alloc_samples,
+                        alloc_size,
                         ..Default::default()
                     },
                     labels,
-                    NO_TIMESTAMP,
+                    timestamp,
                 ) {
                     Ok(_) => trace!(
-                        "Sent stack sample of {depth} frames, {n_labels} labels, {alloc_size} bytes allocated, and {alloc_samples} allocations to profiler."
+                        "Sent stack sample of {depth} frames, {n_labels} labels, {alloc_size} bytes allocated, {alloc_samples} allocations, and {interrupt_count} time interrupts to profiler."
                     ),
                     Err(err) => warn!(
                         "Failed to send stack sample of {depth} frames, {n_labels} labels, {alloc_size} bytes allocated, and {alloc_samples} allocations to profiler: {err}"
@@ -1018,14 +1029,7 @@ impl Profiler {
 
                 let n_labels = labels.len();
 
-                let mut timestamp = NO_TIMESTAMP;
-                {
-                    if self.is_timeline_enabled() {
-                        if let Ok(now) = SystemTime::now().duration_since(UNIX_EPOCH) {
-                            timestamp = now.as_nanos() as i64;
-                        }
-                    }
-                }
+                let timestamp = self.get_timeline_timestamp();
 
                 match self.prepare_and_send_message(
                     frames,
@@ -1436,6 +1440,16 @@ impl Profiler {
         }
     }
 
+    /// Gets a timestamp for timeline profiling if timeline is enabled.
+    /// Returns NO_TIMESTAMP if timeline is disabled or if getting the time fails.
+    fn get_timeline_timestamp(&self) -> i64 {
+        self.is_timeline_enabled()
+            .then(|| SystemTime::now().duration_since(UNIX_EPOCH).ok())
+            .flatten()
+            .map(|now| now.as_nanos() as i64)
+            .unwrap_or(NO_TIMESTAMP)
+    }
+
     /// Creates the common message labels for all samples.
     ///
     /// * `n_extra_labels` - Reserve room for extra labels, such as when the
diff --git a/profiling/src/profiling/uploader.rs b/profiling/src/profiling/uploader.rs
@@ -162,12 +162,11 @@ impl Uploader {
     }
 }
 
-#[cfg(test)]
+#[cfg(all(test, feature = "debug_stats"))]
 mod tests {
     use super::*;
 
     #[test]
-    #[cfg(feature = "debug_stats")]
     fn test_create_internal_metadata() {
         // Set up all counters with known values
         EXCEPTION_PROFILING_EXCEPTION_COUNT.store(42, Ordering::Relaxed);
diff --git a/profiling/tests/correctness/allocation_time_combined.json b/profiling/tests/correctness/allocation_time_combined.json
@@ -0,0 +1,46 @@
+{
+  "scale_by_duration": true,
+  "test_name": "php_allocation_time_combined",
+  "stacks": [
+    {
+      "profile-type": "alloc-size",
+      "stack-content": [
+        {
+          "regular_expression": "<?php;main;standard\\|str_replace$",
+          "percent": 66,
+          "error_margin": 1
+        },
+        {
+          "regular_expression": "<?php;main;standard\\|str_repeat$",
+          "percent": 33,
+          "error_margin": 1
+        }
+      ]
+    },
+    {
+      "profile-type": "alloc-samples",
+      "stack-content": [
+        {
+          "regular_expression": "<?php;main;standard\\|str_replace$",
+          "percent": 66,
+          "error_margin": 1
+        },
+        {
+          "regular_expression": "<?php;main;standard\\|str_repeat$",
+          "percent": 33,
+          "error_margin": 1
+        }
+      ]
+    },
+    {
+      "profile-type": "wall-time",
+      "stack-content": [
+        {
+          "regular_expression": "<?php;main;standard\\|str_replace$",
+          "percent": 51,
+          "error_margin": 50
+        }
+      ]
+    }
+  ]
+}
diff --git a/profiling/tests/correctness/allocation_time_combined.php b/profiling/tests/correctness/allocation_time_combined.php
@@ -0,0 +1,24 @@
+<?php
+
+// Test to verify that allocation and time profiling can coexist and that
+// the piggybacking optimization works (where time samples are taken during
+// allocation samples when interrupt_count > 0).
+//
+// This test uses str_replace, a frameless function (PHP 8.4+) which allocates
+// large amounts of memory, increasing the likelihood of capturing piggybacked
+// samples. Frameless functions don't handle VM interrupts, making them ideal
+// for demonstrating the piggybacking optimization.
+
+function main() {
+    $duration = $_ENV["EXECUTION_TIME"] ?? 10;
+    $end = microtime(true) + $duration;
+
+    while (microtime(true) < $end) {
+        // str_replace is frameless in PHP 8.4+ and allocates a new string
+        $xs = str_repeat("x", 10_000_000); // 10MB source
+        $ys = str_replace("x", "y", $xs); // 10MB allocation in frameless function
+        $zs = str_replace("y", "z", $ys); // 10MB allocation in frameless function
+    }
+}
+
+main();
diff --git a/profiling/tests/phpt/allocation_sampling_distance.phpt b/profiling/tests/phpt/allocation_sampling_distance.phpt
@@ -44,5 +44,5 @@ $str = \str_repeat('a', 87);
 Done.
 --EXPECTREGEX--
 .* Memory allocation profiling initialized with a sampling distance of 1 bytes.*
-.* Sent stack sample of [0-9]* frames, .* labels, 11[2,9] bytes allocated, and 1 allocations to profiler.*
+.* Sent stack sample of [0-9]* frames, .* labels, 11[2,9] bytes allocated, 1 allocations, and .* time interrupts to profiler.*
 .*Done\..*

Original file line number	Diff line number	Diff line change
`@@ -162,12 +162,11 @@ impl Uploader {`
`162`	`162`	`}`
`163`	`163`	`}`
`164`	`164`
`165`		`-#[cfg(test)]`
	`165`	`+#[cfg(all(test, feature = "debug_stats"))]`
`166`	`166`	`mod tests {`
`167`	`167`	`use super::*;`
`168`	`168`
`169`	`169`	`#[test]`
`170`		`- #[cfg(feature = "debug_stats")]`
`171`	`170`	`fn test_create_internal_metadata() {`
`172`	`171`	`// Set up all counters with known values`
`173`	`172`	`EXCEPTION_PROFILING_EXCEPTION_COUNT.store(42, Ordering::Relaxed);`