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

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged

morrisonlevi merged 36 commits into master from levi/perf-time-alloc-piggyback

Jan 21, 2026

.github/workflows/prof_correctness.yml

-Original file line number
+Diff line change
@@ Expand Up / @@ -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
@@ Expand Down Expand Up / @@ -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: |
@@ Expand Down Expand Up / @@ -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
@@ Expand Down @@

profiling/src/allocation/mod.rs

-Original file line number
+Diff line change
@@ Expand Up / @@ -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(),
 _i64,
                     len as i64,
+                    (interrupt_count > 0).then_some(interrupt_count),
                 )
             };
         }
@@ Expand Down @@

profiling/src/profiling/mod.rs

            
                      Original file line number
                      Diff line number
                      Diff line change
                  
    @@ -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

profiling/src/profiling/uploader.rs

realFlowControl marked this conversation as resolved.

Show resolved Hide resolved

-Original file line number
+Diff line change
@@ Expand Up / @@ -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);
@@ Expand Down @@

profiling/tests/correctness/allocation_time_combined.json

morrisonlevi marked this conversation as resolved.

Show resolved Hide resolved

-Original file line number
+Diff line change
@@ -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
+            }
+          ]
+        }
+      ]
+    }

profiling/tests/correctness/allocation_time_combined.php

-Original file line number
+Diff line change
@@ -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();

profiling/tests/phpt/allocation_sampling_distance.phpt

-Original file line number
+Diff line change
@@ Expand Up / @@ -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\..*

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

Uh oh!

Diff view

Diff view

There are no files selected for viewing

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!