add TaskBlock events for blocking intervals#570
Conversation
|
CI Test ResultsRun: #29265266134 | Commit:
Status Overview
Legend: ✅ passed | ❌ failed | ⚪ skipped | 🚫 cancelled Failed Testsmusl-aarch64/debug / 11-librcaJob: View logs No detailed failure information available. Check the job logs. musl-aarch64/debug / 21-librcaJob: View logs No detailed failure information available. Check the job logs. musl-aarch64/debug / 25-librcaJob: View logs No detailed failure information available. Check the job logs. musl-amd64/debug / 17-librcaJob: View logs No detailed failure information available. Check the job logs. musl-amd64/debug / 21-librcaJob: View logs No detailed failure information available. Check the job logs. musl-amd64/debug / 11-librcaJob: View logs No detailed failure information available. Check the job logs. musl-aarch64/debug / 17-librcaJob: View logs No detailed failure information available. Check the job logs. glibc-aarch64/debug / 17-graalJob: View logs No detailed failure information available. Check the job logs. glibc-aarch64/debug / 11-j9Job: View logs No detailed failure information available. Check the job logs. glibc-aarch64/debug / 17Job: View logs No detailed failure information available. Check the job logs. glibc-aarch64/debug / 25Job: View logs No detailed failure information available. Check the job logs. musl-amd64/debug / 25-librcaJob: View logs No detailed failure information available. Check the job logs. glibc-aarch64/debug / 21Job: View logs No detailed failure information available. Check the job logs. glibc-aarch64/debug / 25-graalJob: View logs No detailed failure information available. Check the job logs. glibc-aarch64/debug / 21-graalJob: View logs No detailed failure information available. Check the job logs. glibc-amd64/debug / 25Job: View logs No detailed failure information available. Check the job logs. glibc-amd64/debug / 11Job: View logs No detailed failure information available. Check the job logs. glibc-amd64/debug / 25-graalJob: View logs No detailed failure information available. Check the job logs. glibc-amd64/debug / 21-graalJob: View logs No detailed failure information available. Check the job logs. glibc-amd64/debug / 21Job: View logs No detailed failure information available. Check the job logs. glibc-amd64/debug / 17Job: View logs No detailed failure information available. Check the job logs. glibc-amd64/debug / 17-graalJob: View logs No detailed failure information available. Check the job logs. Summary: Total: 32 | Passed: 10 | Failed: 22 Updated: 2026-07-13 16:29:56 UTC |
kaahos
force-pushed
the
paul.fournillon/wallclock-taskblock
branch
from
bcf3c2b to
a46d368
Compare
kaahos
force-pushed
the
paul.fournillon/wallclock-taskblock
branch
3 times, most recently
from
3f2f71a to
d1e3210
Compare
|
@copilot review this PR |
Reviewed and found a flaky assertion in |
![chatgpt-codex-connector[bot]](https://avatars.githubusercontent.com/in/1144995?s=60&v=4){kind=small}
There was a problem hiding this comment.
💡 Codex Review
Here are some automated review suggestions for this pull request.
Reviewed commit: d21e4936d2
ℹ️ 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".
If Codex has suggestions, it will comment; otherwise it will react with 👍.
Codex can also answer questions or update the PR. Try commenting "@codex address that feedback".
kaahos
force-pushed
the
paul.fournillon/wallclock-taskblock
branch
2 times, most recently
from
2101007 to
a94677a
Compare
kaahos
force-pushed
the
paul.fournillon/wallclock-taskblock
branch
from
a94677a to
681582c
Compare
Benchmark Results (commit 821cac8)Pipeline: https://gitlab.ddbuild.io/DataDog/apm-reliability/benchmarking-platform/-/pipelines/122545771 Commit: ✅ Within expected boundariesNo significant runtime deltas (all within run-to-run noise) and no internal-counter outliers. Runtime details (per benchmark × JDK)
Internal counter details (ddprof)ddprof internal counters, latest / dev (✅ = 0, · = unavailable):
|
rkennke
left a comment
rkennke
left a comment
There was a problem hiding this comment.
Looks good to me (pending Jaroslav's Sphinx reviews)
Benchmark Results (commit bfdc687)Pipeline: https://gitlab.ddbuild.io/DataDog/apm-reliability/benchmarking-platform/-/pipelines/122570556 Commit: ✅ Within expected boundariesNo significant runtime deltas (all within run-to-run noise) and no internal-counter outliers. Runtime details (per benchmark × JDK)
Internal counter details (ddprof)ddprof internal counters, latest / dev (✅ = 0, · = unavailable):
|
Benchmark Results (commit b2d5245)Pipeline: https://gitlab.ddbuild.io/DataDog/apm-reliability/benchmarking-platform/-/pipelines/122598460 Commit:
|
| Benchmark | JDK | Latest | Dev | Δ (dev vs latest) | Issues L/D |
|---|---|---|---|---|---|
| akka-uct | 21 | ✅ 10094 ms (7 iters) | ✅ 10356 ms (7 iters) | ≈ +2.6% (±21.2%) | — / — |
| akka-uct | 25 | ✅ 8837 ms (8 iters) | ✅ 8743 ms (8 iters) | ≈ -1.1% (±22.7%) | — / — |
| finagle-chirper | 21 | ✅ 5853 ms (11 iters) | ✅ 5910 ms (11 iters) | ≈ +1% (±43.6%) | |
| finagle-chirper | 25 | ✅ 5478 ms (12 iters) | ✅ 5368 ms (12 iters) | ≈ -2% (±44%) | |
| fj-kmeans | 21 | ✅ 2824 ms (22 iters) | ✅ 2834 ms (22 iters) | ≈ +0.4% (±4.8%) | — / — |
| fj-kmeans | 25 | ✅ 2817 ms (22 iters) | ✅ 2840 ms (22 iters) | ≈ +0.8% (±4.8%) | — / — |
| future-genetic | 21 | ✅ 2210 ms (28 iters) | ✅ 2091 ms (30 iters) | 🟢 -5.4% | — / — |
| future-genetic | 25 | ✅ 1923 ms (32 iters) | ✅ 1931 ms (32 iters) | ≈ +0.4% (±4.8%) | — / — |
| naive-bayes | 21 | ✅ 1260 ms (45 iters) | ✅ 1229 ms (46 iters) | ≈ -2.5% (±56.9%) | — / — |
| naive-bayes | 25 | ✅ 1016 ms (56 iters) | ✅ 1020 ms (56 iters) | ≈ +0.4% (±56.3%) | — / — |
| reactors | 21 | ✅ 17030 ms (5 iters) | ✅ 17150 ms (5 iters) | ≈ +0.7% (±12.4%) | — / — |
| reactors | 25 | ✅ 18323 ms (5 iters) | ✅ 18162 ms (5 iters) | ≈ -0.9% (±3.7%) | — / — |
Internal counter details (ddprof)
ddprof internal counters, latest / dev (✅ = 0, · = unavailable):
| Benchmark | JDK | Dropped rec | Dropped jvmti | Dropped trace | Skipped WC | AGCT fail | Unwind fail |
|---|---|---|---|---|---|---|---|
| akka-uct | 21 | ✅ / ✅ | ✅ / ✅ | ✅ / ✅ | ✅ / ✅ | ✅ / ✅ | ✅ / ✅ |
| akka-uct | 25 | ✅ / ✅ | ✅ / ✅ | 4 / 4 | 2267 / 2432 | ✅ / ✅ | ✅ / ✅ |
| finagle-chirper | 21 | ✅ / ✅ | ✅ / ✅ | ✅ / ✅ | ✅ / ✅ | ✅ / ✅ | ✅ / ✅ |
| finagle-chirper | 25 | ✅ / ✅ | ✅ / ✅ | 2 / 2 | 8669 / 8358 | ✅ / ✅ | ✅ / ✅ |
| fj-kmeans | 21 | ✅ / ✅ | ✅ / ✅ | ✅ / ✅ | ✅ / ✅ | ✅ / ✅ | ✅ / ✅ |
| fj-kmeans | 25 | ✅ / ✅ | ✅ / ✅ | 2 / 4 | 1268 / 1225 | ✅ / ✅ | ✅ / ✅ |
| future-genetic | 21 | ✅ / ✅ | ✅ / ✅ | 7 / ✅ | 3051 / ✅ | ✅ / ✅ | ✅ / ✅ |
| future-genetic | 25 | ✅ / ✅ | ✅ / ✅ | 1 / 1 | 2773 / 2068 | ✅ / ✅ | ✅ / ✅ |
| naive-bayes | 21 | ✅ / ✅ | ✅ / ✅ | ✅ / ✅ | ✅ / ✅ | ✅ / ✅ | ✅ / ✅ |
| naive-bayes | 25 | ✅ / ✅ | ✅ / ✅ | 7 / 6 | 3483 / 3500 | ✅ / ✅ | ✅ / ✅ |
| reactors | 21 | ✅ / ✅ | ✅ / ✅ | ✅ / ✅ | ✅ / ✅ | ✅ / ✅ | ✅ / ✅ |
| reactors | 25 | ✅ / ✅ | ✅ / ✅ | ✅ / 4 | 1846 / 1692 | ✅ / ✅ | ✅ / ✅ |
|
@copilot resolve the merge conflicts in this pull request |
Resolved. I merged |
jbachorik
left a comment
jbachorik
left a comment
There was a problem hiding this comment.
I did review ~50% of the code but I will need to get more info on some design decisions before I continue because things might change depending on that info.
| ExecutionMode _execution_mode; | ||
| u64 _weight; | ||
| u32 _call_trace_id; | ||
| u64 _call_trace_id; |
| u64 _end; | ||
| u64 _blocker; | ||
| u64 _unblockingSpanId; | ||
| Context _ctx; |
There was a problem hiding this comment.
I don't think you need to carry context here.
IIUC, this event would be written at the moment a thread is ublocked. At that point its context is valid and can be retrieved and written along this event.
| u64 _unblockingSpanId; | ||
| Context _ctx; | ||
| u64 _callTraceId; | ||
| u64 _correlationId; |
There was a problem hiding this comment.
I think we discussed this already (or maybe it was another place?).
For the current work the correlation ID adds only overhead. The event will capture the correct stacktrace when it is written - if the implementation is correct, the event stacktrace should be exactly the same as the one that it would get by the correlation id.
So, it would be mostly just an overhead per TaskBlockEvent
| JNIEnv *env, jclass unused, jboolean delegateMonitorEvents, jboolean wallPrecheck) { | ||
| // JavaVM* has already been stored when the native library was loaded so we can pass nullptr here | ||
| return VM::initProfilerBridge(nullptr, true); | ||
| return VM::initProfilerBridge(nullptr, true, delegateMonitorEvents, wallPrecheck); |
There was a problem hiding this comment.
Historically, these engine specific settings would have been passed by an argument (via arguments.cpp)
I am a bit worried by introducing an alternative way of doing that here - also, the args are not engine agnostic so they kind of mix concerns here.
Could you take a look how to convert this to an arg that can be passed to the agent?
| inline bool parkEnter(u64 start_ticks) { | ||
| u32 flags = __atomic_load_n(&_misc_flags, __ATOMIC_ACQUIRE); | ||
| while ((flags & FLAG_PARKED) == 0) { | ||
| _park_context = ContextApi::snapshot(); |
There was a problem hiding this comment.
I don't think we need to capture the context here. The event will be written at appropriate parkExit and since the thread is parking, there is no way the context would change.
| // Virtual-thread path: span/root ids captured at block entry are passed explicitly because | ||
| // the native OTEP TLS is carrier-scoped and cannot be trusted. Custom attributes not propagated. | ||
| Context ctx{(u64)spanId, (u64)rootSpanId}; | ||
| return recordTaskBlockWithContextIfEligible(tid, (u64)startTicks, (u64)endTicks, |
There was a problem hiding this comment.
Is this still true? We did a bunch of fixes in the context area and I think this might be redundant as we should always get correct context when we ask for it from the same thread.
| extern "C" DLLEXPORT void JNICALL | ||
| Java_com_datadoghq_profiler_JavaProfiler_blockExitWithSnapshot0( | ||
| JNIEnv *env, jclass unused, jlong token, jlongArray snapshotArray) { | ||
| BlockRunSnapshot snapshot{}; | ||
| snapshot.active_state = OSThreadState::UNKNOWN; | ||
| snapshot.sampled_state = OSThreadState::UNKNOWN; | ||
| snapshot.owner = BlockRunOwner::NONE; | ||
| if (snapshotAndExitBlockedRun(token, &snapshot)) { | ||
| writeBlockRunSnapshot(env, snapshotArray, &snapshot); | ||
| } else { | ||
| writeBlockRunSnapshot(env, snapshotArray, nullptr); | ||
| } | ||
| ThreadFilter::SlotID slot_id = ThreadFilter::tokenSlotId(block_token); | ||
| if (current->filterSlotId() != slot_id) { | ||
| return; | ||
| } | ||
|
|
||
| extern "C" DLLEXPORT jboolean JNICALL | ||
| Java_com_datadoghq_profiler_JavaProfiler_recordTaskBlock0( | ||
| JNIEnv *env, jclass unused, jlong startTicks, jlong endTicks, | ||
| jlong blocker, jlong unblockingSpanId) { | ||
| int tid = ProfiledThread::currentTid(); | ||
| if (tid < 0) { | ||
| return JNI_FALSE; | ||
| } | ||
| ThreadFilter *tf = Profiler::instance()->threadFilter(); | ||
| if (tf->enabled()) { | ||
| tf->exitBlockedRun(slot_id, ThreadFilter::tokenGeneration(block_token)); | ||
| // Context (span ids + tags) is captured from OTEP TLS via ContextApi::snapshot() | ||
| // inside recordTaskBlockLiveIfEligible, mirroring the recordQueueTime convention. | ||
| return recordTaskBlockLiveIfEligible(tid, (u64)startTicks, (u64)endTicks, | ||
| (u64)blocker, (u64)unblockingSpanId) | ||
| ? JNI_TRUE | ||
| : JNI_FALSE; | ||
| } | ||
|
|
||
| extern "C" DLLEXPORT jboolean JNICALL | ||
| Java_com_datadoghq_profiler_JavaProfiler_recordTaskBlockWithContext0( | ||
| JNIEnv *env, jclass unused, jlong startTicks, jlong endTicks, | ||
| jlong blocker, jlong unblockingSpanId, | ||
| jlong spanId, jlong rootSpanId) { | ||
| int tid = ProfiledThread::currentTid(); | ||
| if (tid < 0) { | ||
| return JNI_FALSE; | ||
| } | ||
| // Virtual-thread path: span/root ids captured at block entry are passed explicitly because |
There was a problem hiding this comment.
I will need some explanation about why we need to snapshot the context - are we deferring writing related events way after they were collected?
|
|
||
| #if defined(__linux__) | ||
|
|
||
| class NativeFdClassifier { |
There was a problem hiding this comment.
Could you add some comment block here about what the classification spec is?
| }); | ||
| } | ||
|
|
||
| ssize_t NativeSocketInterposer::write_hook(int fd, const void* buf, size_t len) { |
There was a problem hiding this comment.
Sounds good, thanks! Can we get some benchmark numbers to get the feeling about what kind of overhead we are talking here?
| bool Profiler::recordTaskBlockAsync(int tid, TaskBlockEvent *event) { | ||
| if (!_task_block_drain_running.load(std::memory_order_acquire)) { | ||
| Counters::increment(TASK_BLOCK_QUEUE_DROPPED); | ||
| return false; | ||
| } | ||
|
|
||
| QueuedTaskBlockEvent queued; | ||
| queued.tid = tid; | ||
| queued.generation = _task_block_generation.load(std::memory_order_acquire); | ||
| queued.event = *event; | ||
| if (!_task_block_queue.tryPush(queued)) { | ||
| Counters::increment(TASK_BLOCK_QUEUE_DROPPED); | ||
| return false; | ||
| } | ||
| return true; | ||
| } | ||
|
|
There was a problem hiding this comment.
I will need also some info why we must record those events asynchronously - I see this used only from monitor exit and fd interposer; both places do not seem like we could not record the event synchronously.
Could you put some explanations either to the PR description or even on the related classes, why we need this asynchronous machinery?
kaahos
force-pushed
the
paul.fournillon/wallclock-taskblock
branch
from
362277b to
be21617
Compare
Benchmark Results (commit be21617)Pipeline: https://gitlab.ddbuild.io/DataDog/apm-reliability/benchmarking-platform/-/pipelines/124350404 Commit: ✅ Within expected boundariesNo significant runtime deltas (all within run-to-run noise) and no internal-counter outliers. Runtime details (per benchmark × JDK)
Internal counter details (ddprof)ddprof internal counters, latest / dev (✅ = 0, · = unavailable):
|
Benchmark Results (commit 1223a7c)Pipeline: https://gitlab.ddbuild.io/DataDog/apm-reliability/benchmarking-platform/-/pipelines/124358363 Commit:
|
| Benchmark | JDK | Latest | Dev | Δ (dev vs latest) | Issues L/D |
|---|---|---|---|---|---|
| akka-uct | 21 | ✅ 10241 ms (21 iters) | ✅ 10329 ms (21 iters) | ≈ +0.9% (±12%) | — / — |
| akka-uct | 25 | ✅ 8793 ms (24 iters) | ✅ 8870 ms (24 iters) | ≈ +0.9% (±9.6%) | — / — |
| finagle-chirper | 21 | ✅ 6031 ms (33 iters) | ✅ 5953 ms (33 iters) | ≈ -1.3% (±24.8%) | |
| finagle-chirper | 25 | ✅ 5508 ms (36 iters) | ✅ 5461 ms (36 iters) | ≈ -0.9% (±24.6%) | |
| fj-kmeans | 21 | ✅ 2735 ms (68 iters) | ✅ 2825 ms (66 iters) | 🔴 +3.3% | — / — |
| fj-kmeans | 25 | ✅ 2732 ms (69 iters) | ✅ 2798 ms (67 iters) | ≈ +2.4% (±2.6%) | — / — |
| future-genetic | 21 | ✅ 2082 ms (89 iters) | ✅ 2057 ms (90 iters) | ≈ -1.2% (±2.6%) | — / — |
| future-genetic | 25 | ✅ 2077 ms (89 iters) | ✅ 2057 ms (90 iters) | ≈ -1% (±2.5%) | — / — |
| naive-bayes | 21 | ✅ 1299 ms (133 iters) | ✅ 1277 ms (135 iters) | ≈ -1.7% (±32.6%) | — / — |
| naive-bayes | 25 | ✅ 970 ms (175 iters) | ✅ 970 ms (175 iters) | ≈ 0% (±32%) | — / — |
| reactors | 21 | ✅ 16487 ms (15 iters) | ✅ 16190 ms (15 iters) | ≈ -1.8% (±8.2%) | — / — |
| reactors | 25 | ✅ 18641 ms (15 iters) | ✅ 18560 ms (15 iters) | ≈ -0.4% (±5.6%) | — / — |
Internal counter details (ddprof)
ddprof internal counters, latest / dev (✅ = 0, · = unavailable):
| Benchmark | JDK | Dropped rec | Dropped jvmti | Dropped trace | Skipped WC | AGCT fail | Unwind fail |
|---|---|---|---|---|---|---|---|
| akka-uct | 21 | ✅ / ✅ | ✅ / ✅ | 1 / 1 | 2079 / 1985 | ✅ / ✅ | ✅ / ✅ |
| akka-uct | 25 | ✅ / ✅ | ✅ / ✅ | 2 / 3 | 2288 / 2554 | ✅ / ✅ | ✅ / ✅ |
| finagle-chirper | 21 | ✅ / ✅ | ✅ / ✅ | 4 / 2 | 8417 / 8277 | ✅ / ✅ | ✅ / ✅ |
| finagle-chirper | 25 | ✅ / ✅ | ✅ / ✅ | 1 / ✅ | 8609 / 8606 | ✅ / ✅ | ✅ / ✅ |
| fj-kmeans | 21 | ✅ / ✅ | ✅ / ✅ | 2 / 1 | 1287 / 1261 | ✅ / ✅ | ✅ / ✅ |
| fj-kmeans | 25 | ✅ / ✅ | ✅ / ✅ | 5 / 1 | 1244 / 1323 | ✅ / ✅ | ✅ / ✅ |
| future-genetic | 21 | ✅ / ✅ | ✅ / ✅ | 3 / 1 | 3040 / 2964 | ✅ / ✅ | ✅ / ✅ |
| future-genetic | 25 | ✅ / ✅ | ✅ / ✅ | 2 / 3 | 2870 / 2849 | ✅ / ✅ | ✅ / ✅ |
| naive-bayes | 21 | ✅ / ✅ | ✅ / ✅ | 4 / 6 | 3527 / 3555 | ✅ / ✅ | ✅ / ✅ |
| naive-bayes | 25 | ✅ / ✅ | ✅ / ✅ | 6 / 8 | 3430 / 3480 | ✅ / ✅ | ✅ / ✅ |
| reactors | 21 | ✅ / ✅ | ✅ / ✅ | 1 / 1 | 1687 / 1541 | ✅ / ✅ | ✅ / ✅ |
| reactors | 25 | ✅ / ✅ | ✅ / ✅ | ✅ / 1 | 1890 / 1841 | ✅ / ✅ | ✅ / ✅ |
What does this PR do?:
Adds
datadog.TaskBlockJFR events for blocking intervals such asLockSupport.park,Object.wait, monitor contention, including recording APIs used bydd-trace-javafor instrumented blocking operations such asThread.sleep.Motivation:
This builds on
paul.fournillon/wallclock-suppression(#560) by preserving visibility into blocked spans as explicit duration events.Additional Notes:
This PR does not add the dd-trace-java instrumentation itself;
Thread.sleepemission depends on that side calling the new profiler APIs. Monitor callback support is HotSpot-specific, and virtual-thread carrier attribution is avoided.How to test the change?:
./.claude/commands/build-and-summarize :ddprof-test:testDebug -Ptests="*.wallclock.*TaskBlockTest"./.claude/commands/build-and-summarize :ddprof-lib:gtestDebugFor Datadog employees:
credentials of any kind, I've requested a review from
@DataDog/security-design-and-guidance.Unsure? Have a question? Request a review!