diff --git a/.github/workflows/prof_correctness.yml b/.github/workflows/prof_correctness.yml index e26054c48f..96f0c257b0 100644 --- 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 @@ -76,7 +77,7 @@ jobs: export DD_PROFILING_EXCEPTION_MESSAGE_ENABLED=1 php -v php -d extension=target/profiler-release/libdatadog_php_profiling.so --ri datadog-profiling - for test_case in "allocations" "time" "strange_frames" "timeline" "exceptions"; do + for test_case in "allocations" "time" "strange_frames" "timeline" "exceptions" "allocation_time_combined"; do mkdir -p profiling/tests/correctness/"$test_case"/ export DD_PROFILING_OUTPUT_PPROF=$PWD/profiling/tests/correctness/"$test_case"/test.pprof php -d extension="${PWD}/target/profiler-release/libdatadog_php_profiling.so" "profiling/tests/correctness/${test_case}.php" @@ -94,7 +95,7 @@ jobs: export DD_PROFILING_EXCEPTION_MESSAGE_ENABLED=1 php -v php -d extension=target/profiler-release/libdatadog_php_profiling.so --ri datadog-profiling - for test_case in "allocations" "time" "strange_frames" "timeline" "exceptions"; do + for test_case in "allocations" "time" "strange_frames" "timeline" "exceptions" "allocation_time_combined"; do mkdir -p profiling/tests/correctness/"$test_case"/ export DD_PROFILING_OUTPUT_PPROF=$PWD/profiling/tests/correctness/"$test_case"/test.pprof php -d extension=$PWD/target/profiler-release/libdatadog_php_profiling.so profiling/tests/correctness/"$test_case".php @@ -160,6 +161,12 @@ jobs: expected_json: profiling/tests/correctness/timeline.json pprof_path: profiling/tests/correctness/timeline/ + - name: Check profiler correctness for allocation_time_combined + 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 index 84dea83ba2..d4f347adfc 100644 --- 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 index 31059ef396..389fd35a83 100644 --- 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, ) { 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 index 4ba6da2e2b..9e0ac570ed 100644 --- 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 new file mode 100644 index 0000000000..d7dc726c75 --- /dev/null +++ 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": " 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 + strlen($zs); // Use the result to prevent optimization + } +} + +main(); diff --git a/profiling/tests/phpt/allocation_sampling_distance.phpt b/profiling/tests/phpt/allocation_sampling_distance.phpt index f1069c561c..46c0c94c66 100644 --- 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\..*