Skip to content

Commit 25fa0f2

Browse files
committed
Fix reference-chain test-seam races and cross-test candidate pollution
resetSearchStateForTest() and klassPopulationResetForTest() now stop the BFS thread / take _table_lock respectively before mutating state the thread otherwise owns exclusively. Also reset LivenessTracker's own population history before shouldReconstructReferrerChainThroughUnboundedCacheLeak() so a stale candidate from the prior test can't outrank CachedPayload, and align its per-round growth rate with the sibling test's.
1 parent 9972bff commit 25fa0f2

7 files changed

Lines changed: 211 additions & 3 deletions

File tree

ddprof-lib/src/main/cpp/javaApi.cpp

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1168,4 +1168,11 @@ Java_com_datadoghq_profiler_JavaProfiler_drainReferenceChainEventCount0(
11681168
ReferenceChainTracker::instance()->drainPendingChainEvents(&events);
11691169
return (jint)events.size();
11701170
}
1171+
1172+
extern "C" DLLEXPORT void JNICALL
1173+
Java_com_datadoghq_profiler_JavaProfiler_resetReferenceChainSearchForTest0(
1174+
JNIEnv *env, jclass unused) {
1175+
jvmtiEnv *jvmti = VM::jvmti();
1176+
ReferenceChainTracker::instance()->resetSearchStateForTest(jvmti, env);
1177+
}
11711178
#endif // DEBUG

ddprof-lib/src/main/cpp/livenessTracker.h

Lines changed: 11 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -372,7 +372,17 @@ class alignas(alignof(SpinLock)) LivenessTracker {
372372
}
373373
}
374374
}
375-
void klassPopulationResetForTest() { _klass_population_size = 0; }
375+
// Unlike the other klassPopulation*ForTest() seams above, this one is
376+
// also called from a live-JVM test (not just gtest) while the BFS thread
377+
// (ReferenceChainTracker::threadLoop()) may concurrently be inside
378+
// cleanup_table()'s epoch-advance pass, which holds _table_lock while
379+
// mutating _klass_population_size/_klass_population - so this seam must
380+
// take the same lock rather than writing the field unguarded.
381+
void klassPopulationResetForTest() {
382+
_table_lock.lock();
383+
_klass_population_size = 0;
384+
_table_lock.unlock();
385+
}
376386

377387
// Sets _gc_generations directly, bypassing initialize() (which requires a
378388
// live JVM - VM::hotspot_version()/VM::jni(), see that method's own code -

ddprof-lib/src/main/cpp/profiler.cpp

Lines changed: 14 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -829,11 +829,15 @@ void Profiler::writeReferenceChainAbandoned(ReferenceChainAbandonedEvent *event)
829829
void Profiler::writeReferenceChain(ReferenceChainEvent *event, u64 deadline_ns) {
830830
int tid = ProfiledThread::currentTid();
831831
if (tid < 0) {
832+
TEST_LOG("Profiler::writeReferenceChain drop: currentTid() < 0");
832833
return;
833834
}
834835
u32 lock_index;
835836
bool locked = false;
837+
int sweeps = 0;
838+
u64 start_ns = OS::nanotime();
836839
for (;;) {
840+
sweeps++;
837841
lock_index = getLockIndex(tid);
838842
if (_locks[lock_index].tryLock() ||
839843
_locks[lock_index = (lock_index + 1) % CONCURRENCY_LEVEL].tryLock() ||
@@ -857,8 +861,14 @@ void Profiler::writeReferenceChain(ReferenceChainEvent *event, u64 deadline_ns)
857861
// (REFERENCE_CHAIN_EVENTS_DROPPED's own comment) rather than dropping it
858862
// silently.
859863
Counters::increment(REFERENCE_CHAIN_WRITE_DROPPED);
864+
TEST_LOG("Profiler::writeReferenceChain drop: lock contention exhausted shared "
865+
"deadline after sweeps=%d waited_us=%llu",
866+
sweeps, (unsigned long long)((OS::nanotime() - start_ns) / 1000));
860867
return;
861868
}
869+
TEST_LOG("Profiler::writeReferenceChain locked lock_index=%u after sweeps=%d "
870+
"waited_us=%llu",
871+
lock_index, sweeps, (unsigned long long)((OS::nanotime() - start_ns) / 1000));
862872
_jfr.recordReferenceChain(lock_index, event);
863873
_locks[lock_index].unlock();
864874
}
@@ -1811,9 +1821,13 @@ Error Profiler::dump(const char *path, const int length) {
18111821
// _locks[] contention.
18121822
const u64 kChainDrainBudgetNs = 50 * 1000000ULL;
18131823
u64 chain_drain_deadline_ns = OS::nanotime() + kChainDrainBudgetNs;
1824+
long long write_dropped_before = Counters::getCounter(REFERENCE_CHAIN_WRITE_DROPPED);
18141825
for (auto &rc_event : pending_chain_events) {
18151826
writeReferenceChain(&rc_event, chain_drain_deadline_ns);
18161827
}
1828+
TEST_LOG("Profiler::dump reference-chain batch=%d write_dropped=%lld",
1829+
(int)pending_chain_events.size(),
1830+
Counters::getCounter(REFERENCE_CHAIN_WRITE_DROPPED) - write_dropped_before);
18171831

18181832
Libraries::instance()->refresh();
18191833
updateJavaThreadNames();

ddprof-lib/src/main/cpp/referenceChains.cpp

Lines changed: 95 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -352,6 +352,13 @@ void ReferenceChainTracker::startThread() {
352352
// previously call pthread_kill() on a still value-initialized (0) or
353353
// stale/joined pthread_t, which is undefined behavior. Publishing _thread
354354
// before _running closes that window.
355+
// Reset from any previous stopThread() call - a dynamic-attach profiler
356+
// can go through multiple start()/stop() cycles in one JVM lifetime (this
357+
// class's own start()/stop() header comments), and a stale abort request
358+
// left set from the prior cycle would make heapReferenceCallback() abort
359+
// this new cycle's very first pass instantly.
360+
_abort_pass_requested.store(false, std::memory_order_relaxed);
361+
355362
pthread_t thread;
356363
if (pthread_create(&thread, NULL, threadEntry, this) != 0) {
357364
Log::warn("Unable to create ReferenceChains BFS thread");
@@ -366,6 +373,11 @@ void ReferenceChainTracker::stopThread() {
366373
return;
367374
}
368375
_running = false;
376+
// Ask any in-flight JVMTI FollowReferences walk (heapReferenceCallback())
377+
// to abort at its next callback invocation - set before pthread_kill()
378+
// below, since that signal alone cannot interrupt a call already inside
379+
// the JVM/JVMTI implementation.
380+
_abort_pass_requested.store(true, std::memory_order_relaxed);
369381
// Same wake-then-join shape as BaseWallClock::stop() (wallClock.cpp:324-333):
370382
// pthread_kill(WAKEUP_SIGNAL) interrupts threadLoop()'s OS::sleep() early
371383
// (WAKEUP_SIGNAL/SIGIO is installed with a no-op handler unconditionally
@@ -601,6 +613,63 @@ void ReferenceChainTracker::restartSearch() {
601613
// _search_start_ns again on this restarted search's own first pass.
602614
}
603615

616+
void ReferenceChainTracker::resetSearchStateForTest(jvmtiEnv *jvmti,
617+
JNIEnv *jni) {
618+
// Every field touched below is otherwise only ever mutated by the BFS
619+
// thread itself (threadLoop()/runPass()/pollWatchedTargets()) - without
620+
// stopping it first, a pass already in flight on that thread can observe
621+
// this reset only partially, or overwrite it right back (e.g. finish a
622+
// pass that was already headed for SearchState::ABANDONED after this
623+
// method has just forced SearchState::RUNNING below), a race found in
624+
// practice, not just in theory. stopThread() (now that it can abort an
625+
// in-flight JVMTI walk promptly - see its own comment) makes this a cheap,
626+
// clean stop/reset/restart rather than an indefinite wait.
627+
stopThread();
628+
629+
// Clear every live tag this search still holds before resetting - the
630+
// same ordering restartSearch() itself requires (its own assert), so a
631+
// stale tag from whatever search a previous test left running cannot
632+
// collide with the fresh search's own tags once _next_tag is rewound
633+
// below.
634+
if (jvmti != nullptr && jni != nullptr) {
635+
releaseSearchTags(jvmti, jni);
636+
}
637+
_tags_released = true;
638+
639+
_pain_budget.spend(_search_pain_ms);
640+
_search_pain_ms = 0;
641+
642+
if (_frontier != nullptr) {
643+
_frontier->resetForRestart();
644+
}
645+
_next_tag = 1;
646+
647+
_search_started = false;
648+
store(_search_state, (u8)SearchState::RUNNING);
649+
store(_abandon_reason, (u8)SearchAbandonReason::NONE);
650+
store(_search_start_ns, (u64)0);
651+
_expand_cursor = 1;
652+
_last_pass_gc_finish_epoch = 0;
653+
store(_last_pass_ns, (u64)0);
654+
store(_passes_run, 0);
655+
656+
// Unlike restartSearch(), which leaves these for pollWatchedTargets() to
657+
// notice the _search_start_ns change and clear naturally on its own next
658+
// call, this reset must take effect immediately - there is no next real
659+
// pass here to trigger that self-clear.
660+
_emitted_target_tags.clear();
661+
_emitted_search_start_ns = 0;
662+
663+
_pending_chain_events_lock.lock();
664+
_pending_chain_events.clear();
665+
_pending_chain_events_lock.unlock();
666+
667+
// Restart the BFS thread against this freshly reset state - startThread()
668+
// itself clears _abort_pass_requested, so the new thread's very first
669+
// pass is not instantly aborted by the flag stopThread() just set above.
670+
startThread();
671+
}
672+
604673
jlong ReferenceChainTracker::tagObject(jvmtiEnv *jvmti, jobject obj) {
605674
assert(!t_inGCCallback &&
606675
"SetTag is a JVMTI Heap-category call and must not be made from "
@@ -797,6 +866,21 @@ jint JNICALL ReferenceChainTracker::heapReferenceCallback(
797866
jlong *referrer_tag_ptr, jint length, void *user_data) {
798867
PassContext *ctx = (PassContext *)user_data;
799868

869+
if (ctx->tracker->_abort_pass_requested.load(std::memory_order_relaxed)) {
870+
// stopThread() has set this right before pthread_kill()/pthread_join() -
871+
// see that method's own comment. pthread_kill(WAKEUP_SIGNAL) only
872+
// interrupts threadLoop()'s OS::sleep(); it cannot interrupt an
873+
// in-flight JVMTI FollowReferences call, so without this check
874+
// pthread_join() would block until this pass's walk finishes on its own
875+
// - potentially the whole reachable graph, well past any caller's
876+
// shutdown timeout. Treat it exactly like an ordinary budget exhaustion
877+
// (ctx->truncated = true): this pass ends early and the search stays
878+
// non-terminal - fine, since the tracker is shutting down and simply
879+
// never resumes it.
880+
ctx->truncated = true;
881+
return JVMTI_VISIT_ABORT;
882+
}
883+
800884
if (*tag_ptr < 0 || reference_kind == JVMTI_HEAP_REFERENCE_CLASS ||
801885
reference_kind == JVMTI_HEAP_REFERENCE_SYSTEM_CLASS) {
802886
// Referee is a class object - either already tagged negative by
@@ -1133,6 +1217,10 @@ bool ReferenceChainTracker::runPass(jvmtiEnv *jvmti, JNIEnv *jni,
11331217

11341218
resolveLoadedClasses(jvmti, jni);
11351219

1220+
TEST_LOG("ReferenceChainTracker::runPass starting JVMTI walk: "
1221+
"search_started=%d frontierSize=%zu",
1222+
_search_started, _frontier != nullptr ? _frontier->size() : (size_t)0);
1223+
11361224
int edges_admitted = 0;
11371225
bool truncated = false;
11381226
bool frontier_cap_hit = false;
@@ -1462,8 +1550,13 @@ void ReferenceChainTracker::enqueueChainEvent(ReferenceChainEvent &&event) {
14621550
// "dropped-event-without-counter" review lens).
14631551
_pending_chain_events.erase(_pending_chain_events.begin());
14641552
Counters::increment(REFERENCE_CHAIN_EVENTS_DROPPED);
1553+
TEST_LOG("ReferenceChainTracker::enqueueChainEvent dropped oldest queued event, "
1554+
"queue_size=%d (at MAX_PENDING_CHAIN_EVENTS=%d)",
1555+
(int)_pending_chain_events.size(), MAX_PENDING_CHAIN_EVENTS);
14651556
}
14661557
_pending_chain_events.push_back(std::move(event));
1558+
TEST_LOG("ReferenceChainTracker::enqueueChainEvent queued, queue_size=%d",
1559+
(int)_pending_chain_events.size());
14671560
_pending_chain_events_lock.unlock();
14681561
}
14691562

@@ -1480,4 +1573,6 @@ void ReferenceChainTracker::drainPendingChainEvents(
14801573
_pending_chain_events.clear();
14811574
}
14821575
_pending_chain_events_lock.unlock();
1576+
TEST_LOG("ReferenceChainTracker::drainPendingChainEvents drained=%d",
1577+
(int)out->size());
14831578
}

ddprof-lib/src/main/cpp/referenceChains.h

Lines changed: 34 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -692,6 +692,22 @@ class ReferenceChainTracker {
692692
pthread_t _thread;
693693
volatile bool _running;
694694

695+
// Cooperative-cancellation flag for an in-flight JVMTI FollowReferences
696+
// walk: stopThread() sets this before pthread_kill()/pthread_join()
697+
// (that signal alone cannot interrupt a call already inside the JVM/JVMTI
698+
// implementation), and heapReferenceCallback() checks it on every
699+
// invocation, aborting the walk within one callback rather than letting
700+
// pthread_join() block until the walk finishes on its own - see both
701+
// methods' own comments. startThread() resets it back to false, since a
702+
// dynamic-attach profiler can cycle through multiple start()/stop() calls
703+
// in one JVM lifetime and a stale abort request would instantly kill the
704+
// next cycle's very first pass. std::atomic<bool>: written from
705+
// stopThread()/startThread() on the calling (shutdown) thread and read
706+
// from heapReferenceCallback() on the BFS thread - the same cross-thread
707+
// shape _running above already has, just made explicit via atomic rather
708+
// than a plain volatile bool.
709+
std::atomic<bool> _abort_pass_requested;
710+
695711
ReferenceChainTracker()
696712
: _enabled(false), _frontier(nullptr), _last_resolved_class_count(0),
697713
_gc_start_epoch(0),
@@ -703,7 +719,8 @@ class ReferenceChainTracker {
703719
_abandon_reason(SearchAbandonReason::NONE), _search_start_ns(0),
704720
_expand_cursor(1), _last_pass_gc_finish_epoch(0), _last_pass_ns(0),
705721
_passes_run(0), _emitted_search_start_ns(0), _pain_budget(0.0),
706-
_search_pain_ms(0), _thread(), _running(false) {}
722+
_search_pain_ms(0), _thread(), _running(false),
723+
_abort_pass_requested(false) {}
707724

708725
void onGCStart();
709726
void onGCFinish();
@@ -1099,6 +1116,22 @@ class ReferenceChainTracker {
10991116
// failure (obj/jvmti/jni null, SetTag failed, or the frontier table is at
11001117
// capacity).
11011118
jlong tagAsRootForTest(jvmtiEnv *jvmti, JNIEnv *jni, jobject obj);
1119+
1120+
// Test seam - not part of the production API. Since ReferenceChainTracker
1121+
// is a process-wide singleton (ExternalProcessReferenceChainTest's own
1122+
// class javadoc explains why that matters: only the *first* test to ever
1123+
// call runPass() in a shared JVM gets a real root-seeded walk, since
1124+
// runPass() only re-walks from the roots once per search's whole
1125+
// lifetime), an in-process test that needs its own genuine first-ever
1126+
// root walk calls this at the start of its test body to force exactly
1127+
// that - releasing any tags a previous test's search still held, then
1128+
// resetting search/frontier state to the same "brand-new tracker" state
1129+
// restartSearch() (referenceChains.cpp) produces, plus the target-
1130+
// dedup/pending-event state restartSearch() itself intentionally leaves
1131+
// for pollWatchedTargets()/drainPendingChainEvents() to self-clear (this
1132+
// is an immediate, out-of-band reset - there is no next real pass here to
1133+
// observe the change and clear them the ordinary way).
1134+
void resetSearchStateForTest(jvmtiEnv *jvmti, JNIEnv *jni);
11021135
};
11031136

11041137
#endif // _REFERENCECHAINS_H

ddprof-lib/src/main/java/com/datadoghq/profiler/JavaProfiler.java

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -771,6 +771,16 @@ public ContextStorageMode contextStorageMode() {
771771
*/
772772
public static native int drainReferenceChainEventCount0();
773773

774+
/**
775+
* Test seam (debug native builds only): resets ReferenceChainTracker's search/frontier state
776+
* back to a brand-new tracker's, releasing any tags a previous search still held. Since the
777+
* tracker is a process-wide singleton, an in-process test that needs its own genuine first
778+
* root-seeded walk (runPass() only re-walks from the roots once per search's whole lifetime)
779+
* calls this at the start of its test body to force one, rather than depending on being the
780+
* first reference-chain test to run in a shared test JVM.
781+
*/
782+
public static native void resetReferenceChainSearchForTest0();
783+
774784
/**
775785
* Resets the cached ThreadContext for the current storage slot — the calling thread in
776786
* {@link ContextStorageMode#THREAD}, or its current carrier in

ddprof-test/src/test/java/com/datadoghq/profiler/referencechains/ReferenceChainTrackingTest.java

Lines changed: 40 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,7 @@
66
package com.datadoghq.profiler.referencechains;
77

88
import com.datadoghq.profiler.AbstractProfilerTest;
9+
import com.datadoghq.profiler.JavaProfiler;
910
import com.datadoghq.profiler.Platform;
1011
import org.junit.jupiter.api.MethodOrderer;
1112
import org.junit.jupiter.api.Order;
@@ -239,6 +240,18 @@ public void shouldExposeReferenceChainsSettingWhenEnabled() {
239240
@Test
240241
@Order(1)
241242
public void shouldReconstructReferrerChainToGcRoot() throws Exception {
243+
if ("debug".equals(System.getProperty("ddprof_test.config"))) {
244+
// Being pinned to run first *within this class* (this class's own header comment, "Why
245+
// @TestMethodOrder/@Order(1)") does not guarantee this is the first reference-chain test
246+
// to ever call into the shared, process-wide singleton ReferenceChainTracker in this whole
247+
// test JVM - no forkEvery is configured (same header comment), so another test class can
248+
// run first and leave the singleton search already non-RUNNING/already-tagged, in which
249+
// case runPass() never takes its real root-seeded-walk branch again. Force a genuine fresh
250+
// search so this test's own ChainLink population is guaranteed reachable by a real walk,
251+
// regardless of what ran earlier in this JVM. Debug-only: this native seam does not exist
252+
// in a release build.
253+
JavaProfiler.resetReferenceChainSearchForTest0();
254+
}
242255
List<Object> gcRootHolder = new ArrayList<>();
243256
Path scratchDumpPath = Paths.get("referencechains-population-scratch.jfr");
244257
try {
@@ -385,6 +398,26 @@ public void shouldReconstructReferrerChainToGcRoot() throws Exception {
385398
@Test
386399
@Order(2)
387400
public void shouldReconstructReferrerChainThroughUnboundedCacheLeak() throws Exception {
401+
if ("debug".equals(System.getProperty("ddprof_test.config"))) {
402+
// Mirrors shouldReconstructReferrerChainToGcRoot()'s own reset (see that method's comment):
403+
// the natural restartSearch() cycle (shouldRunPass(), referenceChains.cpp) that would
404+
// otherwise give this method its own fresh root walk once shouldReconstructReferrerChainToGcRoot()'s
405+
// own ChainLink candidate is found and its tags released is gated on cadence/pacing budget
406+
// (canAffordNewSearch()) - not guaranteed to fire again before this method's own round/retry
407+
// budget runs out. Force a genuine fresh search here too, rather than depend on that timing,
408+
// so cache (below) is guaranteed reachable by a real walk regardless of it. Debug-only: this
409+
// native seam does not exist in a release build.
410+
//
411+
// resetReferenceChainSearchForTest0() only resets ReferenceChainTracker's own search state
412+
// (frontier/tags/search-progress fields); it does not touch LivenessTracker's per-klass
413+
// population-history rings, which selectLeakCandidates() consults independently to decide
414+
// which klass is "trending". Without also resetting those, a klass ChainLink already
415+
// accumulated a positive slope for during shouldReconstructReferrerChainToGcRoot() can still
416+
// outrank CachedPayload as the leak candidate here, so the fresh search below ends up
417+
// reconstructing ChainLink's chain again instead of CachedPayload's.
418+
JavaProfiler.resetKlassPopulationForTest0();
419+
JavaProfiler.resetReferenceChainSearchForTest0();
420+
}
388421
Map<String, CachedPayload> cache = new HashMap<>();
389422
Path scratchDumpPath = Paths.get("referencechains-cache-leak-scratch.jfr");
390423
try {
@@ -397,7 +430,13 @@ public void shouldReconstructReferrerChainThroughUnboundedCacheLeak() throws Exc
397430
ReferenceChainAssertions.ChainMatch match = null;
398431
int totalRounds = 16;
399432
for (int round = 1; round <= totalRounds && match == null; round++) {
400-
int newEntries = Math.min(round, 10) * 300;
433+
// Matches shouldReconstructReferrerChainToGcRoot()'s own *600 growth rate (not *300, this
434+
// method's previous value) - CachedPayload and ChainLink are near-identical in size (same
435+
// padding fields; CachedPayload is actually slightly smaller, missing ChainLink's `next`
436+
// reference), so halving the growth rate here bought no headroom and instead just let
437+
// CachedPayload's own population ring stall short of KLASS_POPULATION_MIN_FILL_FOR_TREND
438+
// within the same totalRounds budget both methods share.
439+
int newEntries = Math.min(round, 10) * 600;
401440
int roundNumber = round;
402441
Thread allocator = new Thread(() -> {
403442
for (int i = 0; i < newEntries; i++) {

0 commit comments

Comments
 (0)