Skip to content

Fix native socket hook timestamp sequencing (PROF-16151) - #862

Merged
rkennke merged 1 commit into
mainfrom
prof-16151-socket-timestamp-order
Oct 14, 2026
Merged

rkennke merged 1 commit into
mainfrom
prof-16151-socket-timestamp-order

Conversation

@rkennke

@rkennke rkennke commented Oct 14, 2026 •

Copy link
Copy Markdown
Contributor

What does this PR do?:

Explicitly sequence the original I/O call before the end timestamp in NativeSocketSampler's send, recv, write, and read hooks:

u64 t0 = TSC::ticks();
ssize_t ret = fn(/* original arguments */);
u64 t1 = TSC::ticks();
return record_if_positive(fd, ret, t0, t1, op);

Add regression tests that observe the real hooks' recorder arguments, check timestamp bracketing for all four operations, preserve non-positive return handling, and exercise blocking recv/read with a delayed peer over a socketpair.

Motivation:

PROF-16151: C++ does not specify function-argument evaluation order. Previously the original I/O call and the end timestamp were separate arguments to record_if_positive, permitting the timestamp to be read before I/O. This excludes blocking time from durations and distorts duration-based sampling and weights.

Reproduced with GCC 11.4 in both debug and the optimized native release test configuration (-O3): all four timestamp-order checks and both blocking receive tests failed before the fix. Approximately 50 ms of socket wait produced hook durations of only 39–50 ns in debug and 40–52 ns in release. In an isolated worktree, the same six release regression cases failed in each of 10 consecutive runs; restoring the fix made all applicable regression cases pass in each of 10 consecutive runs.

Additional Notes:

  • This is an unspecified-evaluation-order correctness bug, not undefined behavior.
  • The observer is compiled only with UNIT_TEST; recording still follows the normal production path, including its stopped-profiler guard. Symbol inspection confirms the observer is absent from the production debug library.
  • The unfixed GCC release reproduction and fixed control were hook-level tests compiled with -O3 and UNIT_TEST, with gtest assertions enabled. They observe the actual hook timestamps and use real blocking socketpair I/O, but are not end-to-end runs of the packaged production library/JFR recording. Fixed native tests pass with GCC and Clang in both configurations.

How to test the change?:

Validated locally on Linux x64:

./.claude/commands/build-and-summarize \
  :ddprof-lib:gtestDebug_nativeSocketSampler_ut \
  :ddprof-lib:gtestRelease_nativeSocketSampler_ut \
  -Pnative.forceCompiler=g++

./.claude/commands/build-and-summarize \
  :ddprof-lib:gtestDebug_nativeSocketSampler_ut \
  :ddprof-lib:gtestRelease_nativeSocketSampler_ut \
  -Pnative.forceCompiler=clang++

./.claude/commands/build-and-summarize :ddprof-test:testDebug \
  '-Ptests=*.nativesocket.*' -Pnative.forceCompiler=g++

./.claude/commands/build-and-summarize testDebug -Pnative.forceCompiler=clang++

./.claude/commands/build-and-summarize spotlessApply
  • Native socket tests: GCC debug/release passed; Clang debug/release each had 28 passed, 2 inapplicable blocking-send/write cases skipped, 0 failed.
  • GCC release negative/control experiment: revert only the four sequencing fixes in an isolated worktree while retaining the tests and observer, rebuild with GCC, and run nativeSocketSampler_ut '--gtest_filter=AllHooks/NativeSocketSamplerTimingTest.*' --gtest_repeat=10. Unfixed: the same six regression failures in all 10 runs. Fixed: all 10 applicable regression cases passed in all 10 runs; the full native suite also passed (28 passed, 2 skipped, 0 failed).
  • Java socket suite with GCC: 14 passed, 1 platform-specific skip, 0 failed.
  • Full testDebug with Clang: 206 passed, 19 skipped, 0 failed.
  • Formatting and git diff --check passed.

For Datadog employees:

  • If this PR touches code that signs or publishes builds or packages, or handles credentials of any kind, I've requested a security review.
  • This PR doesn't touch any of that.
  • JIRA: PROF-16151

Sequence the original I/O call before reading its end timestamp in send, recv, write, and read hooks so socket durations do not depend on function-argument evaluation order.

Add test-only timestamp observation and regression tests for all four hooks, non-positive results, and delayed socketpair receives.
@rkennke
rkennke requested a review from a team as a code owner October 14, 2026 15:10
@chatgpt-codex-connector

chatgpt-codex-connector Bot commented Oct 14, 2026 •

Copy link
Copy Markdown

Codex Review Summary

This comment shows the latest Codex review activity on this pull request.

Review Status Commit Review trigger
📝 Code Review ✅ Completed 2026-10-14T15:11:29.023839Z 5e77163 PR opened
ℹ️ About Codex in GitHub

Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you

  • Open a pull request for review
  • Mark a draft as ready
  • Comment "@codex review" or "@codex security review".

Codex reacts with 👀 while any review is running, comments if it has suggestions, and reacts with 👍 once all reviews finish with no findings.

@datadog-official datadog-official Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Bits Code Review: PASS

More details

All four socket hooks now take the end timestamp after the original I/O call, ensuring recorded durations include blocking time. The test observer remains restricted to unit-test builds.

Was this helpful? React 👍 or 👎

Open Bits AI session

🤖 Bits Code Review · Commit 5e77163

@dd-octo-sts

dd-octo-sts Bot commented Oct 14, 2026

Copy link
Copy Markdown
Contributor

CI Test Results

Run: #38586942935 | Commit: 9d08e7c | Duration: 18m 13s (longest job)

✅ All 32 test jobs passed

Status Overview

JDK glibc-aarch64/debug glibc-amd64/debug musl-aarch64/debug musl-amd64/debug
8 - ✅ - -
8-ibm - ✅ - -
8-j9 ✅ ✅ - -
8-librca - - ✅ ✅
8-orcl - ✅ - -
11 - ✅ - -
11-j9 ✅ ✅ - -
11-librca - - ✅ ✅
17 ✅ ✅ - -
17-graal ✅ ✅ - -
17-j9 ✅ ✅ - -
17-librca - - ✅ ✅
21 ✅ ✅ - -
21-graal ✅ ✅ - -
21-librca - - ✅ ✅
25 ✅ ✅ - -
25-graal ✅ ✅ - -
25-librca - - ✅ ✅

Legend: ✅ passed | ❌ failed | ⚪ skipped | 🚫 cancelled

Summary: Total: 32 | Passed: 32 | Failed: 0


Updated: 2026-10-14 15:30:24 UTC

Comment on lines +313 to +315
ssize_t ret = fn(fd, buf, len, flags);
u64 t1 = TSC::ticks();
return record_if_positive(fd, ret, t0, t1, 0);

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🤦

@jbachorik jbachorik left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM!

@dd-octo-sts

dd-octo-sts Bot commented Oct 14, 2026

Copy link
Copy Markdown
Contributor

✅ All 40 integration tests passed

📊 Dashboard · 👷 Pipeline · 📦 5e77163b

@rkennke
rkennke merged commit bcd01ba into main Oct 14, 2026
127 checks passed
@rkennke
rkennke deleted the prof-16151-socket-timestamp-order branch October 14, 2026 15:57
@github-actions github-actions Bot added this to the 1.52.0 milestone Oct 14, 2026
#endif
// Separate full expressions ensure the end timestamp follows I/O regardless
// of the compiler's function-argument evaluation order.
u64 t0 = TSC::ticks();

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We probably should switch to monotonic timer.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants