fix(ci): harden flaky test_extension_ci timing races#4044
Conversation
Three independent flaky-test root causes in the test_extension_ci valgrind lane, each confirmed with direct evidence before fixing: - [7.2] tracer/functions.c await_remote_config: replaced a blind php_sleep(timeout_sec) with a bounded active-polling loop (mirrors await_agent_info). Local tracing proved the blind sleep can leave reread_remote_configuration set *before* sleeping and still not process it until the full timeout elapses -- PHP's sleep() retries internally on EINTR, so the SIGVTALRM-driven VM-interrupt checkpoint that applies remote config is never reached during the wait. An earlier hypothesis that this was a fork-specific sidecar re-subscription gap was traced end-to-end (sidecar.c, remote_config.c, datadog.c, and the libdatadog RC manager) and disproven: target tracking, SHM path computation, and queue registration are all fork-safe. The failure hits parent and child symmetrically, matching a generic timing race, not a fork defect. - [8.0] tests/ext/live-debugger/live_debugger.inc await_probe_installation: hardened to verify the RC-applied probe count (via get_loaded_remote_configs) rather than trusting the hook-install counter alone, and to actively drive RC processing each poll iteration via a new process_remote_config_now() test primitive. Confirmed via real CI sidecar logs: all 3 LIVE_DEBUGGING configs were acknowledged, then one dropped out of the acknowledged set and never returned, leaving the root-span decoration probe inactive. This hardening closes the same class of slow/transient apply race as the 7.2 fix; it cannot recover from a probe that is genuinely dropped server-side after being applied. - [8.3] tests/ext/includes/request_replayer.inc waitForDataAndReplay: widened maxIteration from 500 (~16.65s) to 900 (~30s at the 33.3ms flush interval). Confirmed via real CI sidecar logs: the trace was enqueued correctly, but the sidecar's trace_flusher stalled ~18s across all sessions under contention and drained ~1s after the old budget expired. Data provably arrives, just later than the old budget under load -- not a valgrind issue, not a selection race in the mock agent (single-threaded, per-token storage, ruled out by reading its source). No tests skipped or disabled. Verified locally under test_extension_ci valgrind: rc_fork_notify.phpt and dynamic_config_update.phpt 50/50 pass each; full remote_config/, live-debugger/, and request-replayer/ test directories pass with no regressions.
|
The active-poll rewrite of await_remote_config/process_remote_config_now
addressed the timing-checkpoint race in test_extension_ci, but
await_probe_installation still counted hook-install events, which can
return mid-churn when remote config removes and re-adds probes
("churn") during delivery -- observed as an empty span-decoration
capture when the last (targetSpan=ROOT) probe hadn't been re-installed
yet when the test body ran.
Root-cause fix, folded in from the span-decoration-capture branch:
- tracer/live_debugger.c: drop the stale active_live_debugger_hooks
index entry when a probe is removed, so its element count reflects
only currently-installed probes.
- tracer/functions.c: add live_debugger_installed_probe_count, a net
installed-probe counter derived from that hash table.
- tests/ext/live-debugger/live_debugger.inc: rewrite
await_probe_installation to poll the net installed-probe count via
live_debugger_installed_probe_count and require it to stay >= $num
continuously for a 1s stability window, so a churn dip resets the
wait instead of returning early. Still actively drives RC
application each iteration via process_remote_config_now.
…ension_ci] Return only after an RC update has been applied AND a 500ms settle window observes no further change (or the overall timeout elapses), instead of returning on the first observed update. A per-request reader against a warm/shared sidecar can otherwise race ahead of the config the caller just published, applying it one poll-cycle late.
Benchmarks [ tracer ]Benchmark execution time: 2026-07-16 13:49:36 Comparing candidate commit bac7c25 in PR branch Found 3 performance improvements and 0 performance regressions! Performance is the same for 191 metrics, 0 unstable metrics.
|
What
Fixes flaky/racy tests in the
test_extension_civalgrind lane:tests/ext/remote_config/rc_fork_notify.phpt(and the widerdynamic_config_*/rc_*family that sharesawait_remote_config:dynamic_config_update.phpt,dynamic_config_auto_update.phpt,dynamic_config_multiconfig.phpt,rc_trace_enabled_rinit.phpt)tests/ext/live-debugger/debugger_span_decoration_probe.phpt(and theother live-debugger probe tests that share
await_probe_installation)tests/ext/request-replayer/dd_trace_span_event.phpt(and the otherrequest-replayer tests that share
request_replayer.inc:client_side_stats.phpt,client_side_stats_peer_tags.phpt,client_side_stats_trace_filters.phpt)No tests are skipped or disabled. Each fix addresses a confirmed root cause
with direct evidence gathered before the change was made.
Why + How, per fix
tracer/functions.c—await_remote_configsettle-window active-pollRoot cause (confirmed via local reproduction + tracing):
dd_trace_internal_fn("await_remote_config")called a single blindphp_sleep(timeout_sec). Remote config is only applied at a ZendVM-interrupt checkpoint (
dd_vm_interrupt->ddog_process_remote_configs(),ext/remote_config.c), which is only reached between opcode dispatches.Temporary debug instrumentation (added, used to confirm the mechanism, then
fully removed) proved that
reread_remote_configurationcan already be setbefore the sleep starts and still not get processed until the full 10s
timeout elapses — PHP's
sleep()retries internally onEINTRfor theremaining duration, so the SIGVTALRM-driven interrupt never gets a chance to
run mid-sleep.
An earlier hypothesis — that this was a fork-specific sidecar
re-subscription gap (the reproduced failure happened to hit only the
pcntl_fork()'d child process in the first sample) — was traced end-to-endthrough
ext/sidecar.c(datadog_sidecar_handle_fork),ext/remote_config.c,ext/datadog.c, and the libdatadog RC manager (SHM path computation, targettracking, queue registration). The trace disproved it: target tracking and
SHM paths are identical and fork-safe for parent and child. A larger sample
showed the failure hits parent, child, or both, symmetrically — a generic
timing race, not a fork defect.
Fix: replaced the blind sleep with a bounded active-polling loop that
waits for RC application to settle (not just for a single update): it
calls
ddog_process_remote_configs()every 10ms, and only returns onceeither the overall
timeout_secelapses, or at least one update has beenseen and a subsequent 500ms quiet period observes no further change —
draining any update actively instead of racing ahead of it. This closes a
second, related early-return bug: previously the call could return
truethe instant the first of several in-flight RC updates landed, one poll
cycle before the config the caller actually cares about was applied. Also
added
dd_trace_internal_fn("process_remote_config_now")— a thin wrapperaround the existing
datadog_check_for_new_config_now()used by thelive-debugger test helper (see below) to actively drive RC application from
within its own poll loop instead of depending on a VM-interrupt checkpoint
landing inside it.
tracer/live_debugger.c+tests/ext/live-debugger/live_debugger.inc— probe-count race inawait_probe_installationRoot cause (confirmed via real CI sidecar logs — could not be reproduced
locally despite ~130 valgrind runs across targeted and full-directory
sweeps): all 3
LIVE_DEBUGGINGRC configs were acknowledged(
apply_state:2), then one dropped out of the acknowledgedconfig_statesa few seconds later and never returned. The root-span decoration probe (id 3)
was consequently inactive, producing empty
meta. Separately,await_probe_installation()only polled a hook-install counter — it neverasserted the probes were actually effective, and returned unconditionally
once the counter matched, and stale hook-index entries were never dropped on
removal so the counter didn't reflect the currently-installed set.
Fix:
tracer/live_debugger.c: on probe removal,zend_hash_index_del()the(now stale) index entry so
zend_hash_num_elements(&active_live_debugger_hooks)reflects the currently-installed probes, not a historical high-water mark.
dd_trace_internal_fn("live_debugger_installed_probe_count")exposingthat live count to tests.
await_probe_installation()rewritten to poll the net installed-probecount and only return once it has been
>= $numcontinuously for a 1sstability window (any dip below
$numresets the wait), actively drivingRC application each iteration via
process_remote_config_now()instead ofrelying on a VM-interrupt checkpoint happening to land inside the loop.
This waits out the remote-config remove/re-add churn described below
rather than sampling in the middle of it.
Known limitation: this closes the same class of slow/transient-apply
race as the
await_remote_configfix, but it is also a client-sidemitigation for a distinct, upstream libdatadog remote-config churn issue —
see "Known limitations" below.
tests/ext/includes/request_replayer.inc—waitForDataAndReplaytimeoutRoot cause (confirmed via real CI sidecar logs): the trace was captured
and enqueued correctly at time T, but the sidecar's
trace_flusherstalled~18s across all sessions under contention and drained the backlog ~1s
after the test's
500 * 33.3ms ≈ 16.65sclient budget had alreadyexpired. This is not a valgrind-specific issue, and not a request-selection
race — the mock agent (
datadog/dd-trace-ci:php-request-replayer-2.0) wasread directly: it's a single-threaded
php -Sserver with per-session-tokenstorage, so concurrent unrelated tests can't cross-contaminate, and a wrong
entry pick would show up as a content mismatch, not the observed timeout
exception. This helper is shared by
dd_trace_span_event.phptand theclient_side_stats*.phptfamily, so all of them were exposed to the samerace.
Fix: widened
maxIterationfrom 500 (~16.65s) to 900 (~30s at the33.3ms flush interval used by the affected tests), comfortably exceeding the
observed ~17.7s worst case. This is a synchronization-budget fix, not a
skip; the underlying sidecar flush-stall is out of scope here.
Testing
Verified locally against
datadog/dd-trace-ci:php-8.3_bookworm-9, replicatingthe
test_extension_civalgrind recipe (make test_extension_ci), underartificial CPU contention:
rc_fork_notify.phpt: 50/50 pass (post-fix, realistic contention level)dynamic_config_update.phpt: 50/50 pass (post-fix, heavier contention)tests/ext/remote_config/(full directory): 4/4 clean runstests/ext/live-debugger/(full directory): 5/5 clean runstests/ext/request-replayer/(full directory): 5/5 clean runs under load,7/7 clean with no artificial load
Pre-fix, the same harness reproduced the
rc_fork_notify.phptfailure(1-2 per 50 runs) with a debug-instrumented build that pinpointed the exact
mechanism (see the
await_remote_configsection above); that instrumentationwas fully removed before this diff.
Realistic single-pipeline CI is green with these changes; do not expect
100% under an artificial 10x-parallel-same-branch stress harness — see
"Known limitations" below.
Known limitations
Upstream libdatadog remote-config churn (separate, unresolved — tracked
upstream): under heavy concurrent load, remote-config target switching in
libdatadog's
RemoteConfigManager(datadog-sidecar/src/shm_remote_config.rs)unconditionally Remove-then-Add-cycles every active config whenever the RC
Targetchanges at all — including on aprocess_tags-only change, whichcarries no RC-relevant information. This produces a real, if narrow,
Remove→Add gap during which a probe genuinely reads as absent even though it
never changed. A/B evidence: with
DD_EXPERIMENTAL_PROPAGATE_PROCESS_TAGS_ENABLEDon, ~113Removeevents areemitted under the stress harness vs. ~1 with it off. The
await_probe_installationstability-window fix in this PR waits this churnout client-side and is sufficient for realistic CI concurrency (0 failures
in normal pipeline runs), but does not fix the underlying churn. Root cause,
A/B evidence, and two falsified fix attempts are documented in a follow-up
libdatadog issue (link to be added here once filed). Do not re-attempt a
client-side fix for this specific mechanism without reading that issue
first.
Irreducible RINIT/fork delivery-latency limit: under extreme
artificial CPU saturation (deliberately pegging 3 of 4 cores with tight spin
loops, well beyond realistic CI contention), a residual flake in
rc_fork_notify.phpt/rc_trace_enabled_rinit.phptpersists post-fix.Tracing showed this is a pure data-delivery-latency limit —
ddog_process_remote_configs()legitimately returnschanged=falsebecausethe RC update hasn't arrived in local shared memory within the timeout
window yet, not because polling isn't happening. No amount of additional
polling manufactures data that hasn't arrived over the network/sidecar path
in time. This was not addressed here as it's outside the bounded scope of
this fix; realistic CI does not hit it.
Keep #3849 as a separate PR (A/F, unrelated scope).