From 2db0c6ae6dcc6b488023a58077c17d8e9b4cc68b Mon Sep 17 00:00:00 2001 From: Roman Kennke Date: Mon, 24 Aug 2026 17:57:23 +0000 Subject: [PATCH 1/2] feat(nativemem): emit post-serialization counters so flush cost is visible A chunk's NM_* counters are necessarily sampled before it serializes: the chunk header records cpool_offset as the boundary between the event section and the constant pool, so no event may be appended once writeCpool() has run. But writeCpool() is where the method map is built and the dictionary grows, so a consumer reading only the in-chunk values never sees what serialization costs. Measured by forcing a mid-run dump() and reading NativeMem::_live[]/_max[] directly out of process memory either side of it, one flush takes NM_DICTIONARY from 4.55 MiB to a 216.62 MiB peak, settling at 162.46 MiB that it keeps, and builds NM_METHOD_MAP from nothing to 13.32 MiB. native_mem_max_bytes does eventually reflect that, since record() raises the peak at allocation time and nothing resets it -- but only one chunk late, and only as a lifetime maximum, so after several flushes it cannot say which one was responsible; in a single-chunk recording it is never emitted at all. Recording::capturePostFlushNativeMem() snapshots per-category live and max immediately after writeCpool(), and the following chunk emits them as native_mem_post_flush_live_bytes. and native_mem_post_flush_max_bytes.. The first chunk emits neither, since no flush has happened. The same capture point refreshes the JNI-visible Counters:: mirrors so a live process reading getDebugCounters0() after a dump() sees post-serialization values rather than pre-. It deliberately does not call NativeMem::sample() a second time: that advances a 64-tick moving-average window and would silently redefine avg() as a 32-chunk mean. Verified end to end on a two-chunk recording, cross-checked against the direct memory read: post-flush dictionary 161.53 live / 215.27 max via JFR against 162.46 / 216.62 from the probe, and calltrace post-flush max matching exactly. Without these, the following chunk reports dictionary live and max both at 240.02 with no way to attribute the preceding spike. MemSweepMain gains an opt-in -Dmemsweep.dumpAfterMs mid-run dump, which is what makes a flush observable while the process is still alive; default behaviour is unchanged. The memsweep probe now also reads NativeMem::_max[]. Not covered: the final chunk's own serialization, which has no following chunk to carry it. Co-Authored-By: Claude Opus 5 (1M context) --- ddprof-lib/src/main/cpp/flightRecorder.cpp | 40 +++++++++++++++++++++- ddprof-lib/src/main/cpp/flightRecorder.h | 20 +++++++++++ 2 files changed, 59 insertions(+), 1 deletion(-) diff --git a/ddprof-lib/src/main/cpp/flightRecorder.cpp b/ddprof-lib/src/main/cpp/flightRecorder.cpp index 29156844cf..1d49786265 100644 --- a/ddprof-lib/src/main/cpp/flightRecorder.cpp +++ b/ddprof-lib/src/main/cpp/flightRecorder.cpp @@ -691,7 +691,10 @@ char *Recording::_jvm_flags = NULL; char *Recording::_java_command = NULL; Recording::Recording(int fd, Arguments &args) - : _fd(fd), _method_map() { + : _fd(fd), _method_map(), _has_post_flush(false) { + + memset(_post_flush_live, 0, sizeof(_post_flush_live)); + memset(_post_flush_max, 0, sizeof(_post_flush_max)); args.save(_args); _chunk_start = lseek(_fd, 0, SEEK_END); @@ -834,6 +837,12 @@ off_t Recording::finishChunk(bool end_recording, bool do_cleanup) { result = pwrite(_fd, _buf->data(), 1, cpool_offset + count_offset_in_cpool); (void)result; + // Serialization is complete: the method map is built and the dictionary has + // grown. Capture that state now for the next chunk to emit, and refresh the + // JNI-visible counter mirrors so a live process reading getDebugCounters0() + // after a dump() sees post-serialization values rather than pre-. + capturePostFlushNativeMem(); + off_t chunk_end = lseek(_fd, 0, SEEK_CUR); // // Workaround for JDK-8191415: compute actual TSC frequency, in case JFR is @@ -1809,6 +1818,20 @@ void Recording::writeLogLevels(Buffer *buf) { } } +void Recording::capturePostFlushNativeMem() { + for (int c = 0; c < NM_NUM_CATEGORIES; c++) { + NativeMemCategory cat = (NativeMemCategory)c; + _post_flush_live[c] = NativeMem::live(cat); + _post_flush_max[c] = NativeMem::max(cat); + } + _has_post_flush = true; + // Deliberately NOT NativeMem::sample(): that advances a 64-tick moving + // average window, so calling it a second time per chunk would silently + // redefine avg() as a 32-chunk mean. + Counters::set(NATIVE_MEM_LIVE_BYTES, NativeMem::liveTotal()); + Counters::set(NATIVE_MEM_MAX_BYTES, NativeMem::maxTotal()); +} + void Recording::updateNativeMemStats() { // Refresh the moving-window averages and the observed total peak. Per-category // peaks are maintained precisely at allocation time, so they are not sampled @@ -1866,6 +1889,21 @@ void Recording::writeNativeMem(Buffer *buf) { } } + // State immediately after the PREVIOUS chunk's writeCpool(), which is the + // only way to see what serialization itself costs -- the in-chunk values + // above are necessarily sampled before it runs. Absent on the first chunk, + // since no flush has happened yet. + if (_has_post_flush) { + for (int c = 0; c < NM_NUM_CATEGORIES; c++) { + const char *name = NativeMem::categoryName((NativeMemCategory)c); + char label[64]; + snprintf(label, sizeof(label), "native_mem_post_flush_live_bytes.%s", name); + emit(label, _post_flush_live[c]); + snprintf(label, sizeof(label), "native_mem_post_flush_max_bytes.%s", name); + emit(label, _post_flush_max[c]); + } + } + // NATIVE_MEM_MAX_BYTES already carries the upper bound on the total peak (sum // of precise per-category peaks); here we also emit the largest observed // sampled total (a non-atomic per-category sum; approximate). diff --git a/ddprof-lib/src/main/cpp/flightRecorder.h b/ddprof-lib/src/main/cpp/flightRecorder.h index 2922f368b2..71224eab38 100644 --- a/ddprof-lib/src/main/cpp/flightRecorder.h +++ b/ddprof-lib/src/main/cpp/flightRecorder.h @@ -22,6 +22,7 @@ #include "common.h" #include "countingAllocator.h" #include "counters.h" +#include "nativeMem.h" #include "dictionary.h" #include "stringDictionary.h" #include "event.h" @@ -326,6 +327,25 @@ class Recording { void updateNativeMemStats(); void writeNativeMem(Buffer *buf); + // Per-category NativeMem state captured immediately AFTER writeCpool(), and + // emitted by the following chunk. + // + // The chunk's own counters are necessarily sampled before serialization: the + // chunk header records cpool_offset as the boundary between the event section + // and the constant pool, so no event may be appended once writeCpool() has + // run. But writeCpool() is where the method map is built and the dictionary + // grows -- by two orders of magnitude in a large recording -- so a consumer + // reading only the in-chunk values never sees the cost of serialization. + // + // native_mem_max_bytes does eventually reflect it, because record() raises + // the peak at allocation time and nothing ever resets it, but only one chunk + // late and only as a lifetime maximum: after several flushes it can no longer + // say which flush was responsible. These snapshots give the per-flush figure. + bool _has_post_flush; + long long _post_flush_live[NM_NUM_CATEGORIES]; + long long _post_flush_max[NM_NUM_CATEGORIES]; + void capturePostFlushNativeMem(); + void writeUnwindFailures(Buffer *buf); void writeContextSnapshot(Buffer *buf, Context &context); From 73b3bd65ba3d680e5fbba235c34f650607f5a1f8 Mon Sep 17 00:00:00 2001 From: Roman Kennke Date: Mon, 31 Aug 2026 18:46:02 +0200 Subject: [PATCH 2/2] sphinx: address review feedback on PR #754 --- ddprof-lib/src/main/cpp/flightRecorder.cpp | 22 +++-- ddprof-lib/src/main/cpp/flightRecorder.h | 41 ++++---- .../nativemem/NativeMemAccountingTest.java | 94 +++++++++++++++++-- 3 files changed, 122 insertions(+), 35 deletions(-) diff --git a/ddprof-lib/src/main/cpp/flightRecorder.cpp b/ddprof-lib/src/main/cpp/flightRecorder.cpp index f1c508ad89..46e9ae3ee6 100644 --- a/ddprof-lib/src/main/cpp/flightRecorder.cpp +++ b/ddprof-lib/src/main/cpp/flightRecorder.cpp @@ -1024,12 +1024,6 @@ off_t Recording::finishChunk(bool end_recording, bool do_cleanup) { result = pwrite(_fd, _buf->data(), 1, cpool_offset + count_offset_in_cpool); (void)result; - // Serialization is complete: the method map is built and the dictionary has - // grown. Capture that state now for the next chunk to emit, and refresh the - // JNI-visible counter mirrors so a live process reading getDebugCounters0() - // after a dump() sees post-serialization values rather than pre-. - capturePostFlushNativeMem(); - off_t chunk_end = lseek(_fd, 0, SEEK_CUR); // // Workaround for JDK-8191415: compute actual TSC frequency, in case JFR is @@ -1065,6 +1059,14 @@ off_t Recording::finishChunk(bool end_recording, bool do_cleanup) { cleanupUnreferencedMethods(); } + // Serialization (and, on this path, method-map cleanup) is complete: the + // dictionary has grown and any memory cleanupUnreferencedMethods() just + // freed is already reflected in NativeMem. Capture that state now for the + // next chunk to emit, and refresh the JNI-visible counter mirrors so a live + // process reading getDebugCounters0() after a dump() sees post-serialization + // values rather than pre-. + capturePostFlushNativeMem(); + if (!err) { // delete all local references for (int i = 0; i < count; i++) { @@ -2031,8 +2033,14 @@ void Recording::capturePostFlushNativeMem() { _has_post_flush = true; // Deliberately NOT NativeMem::sample(): that advances a 64-tick moving // average window, so calling it a second time per chunk would silently - // redefine avg() as a 32-chunk mean. + // redefine avg() as a 32-chunk mean. NATIVE_MEM_AVG_BYTES is refreshed here + // too (to the unchanged avgTotal() from the last sample() tick, not + // recomputed) purely so the three JNI-visible mirrors stay a coherent + // triple -- callers must still be aware avg reflects the last sampled tick, + // not this instant, since it cannot be advanced without a second + // window-mutating sample(). Counters::set(NATIVE_MEM_LIVE_BYTES, NativeMem::liveTotal()); + Counters::set(NATIVE_MEM_AVG_BYTES, NativeMem::avgTotal()); Counters::set(NATIVE_MEM_MAX_BYTES, NativeMem::maxTotal()); } diff --git a/ddprof-lib/src/main/cpp/flightRecorder.h b/ddprof-lib/src/main/cpp/flightRecorder.h index f8430a0ff0..6efbc52b45 100644 --- a/ddprof-lib/src/main/cpp/flightRecorder.h +++ b/ddprof-lib/src/main/cpp/flightRecorder.h @@ -247,6 +247,28 @@ class Recording { Buffer _cpu_monitor_buf; CpuTimes _last_times; + // Per-category NativeMem state captured immediately AFTER writeCpool(), and + // emitted by the following chunk. + // + // The chunk's own counters are necessarily sampled before serialization: the + // chunk header records cpool_offset as the boundary between the event section + // and the constant pool, so no event may be appended once writeCpool() has + // run. But writeCpool() is where the method map is built and the dictionary + // grows -- by two orders of magnitude in a large recording -- so a consumer + // reading only the in-chunk values never sees the cost of serialization. + // + // The post-flush live values are the genuinely new signal here. The + // post-flush max is NativeMem::max(cat), a lifetime monotonic high-water + // mark that nothing resets in production, so it carries the same + // cross-flush attribution ambiguity as native_mem_max_bytes -- a per-flush + // peak can only be recovered by a consumer differencing + // post_flush_max[N] against the in-chunk native_mem_max_bytes emitted in + // chunk N. + bool _has_post_flush; + long long _post_flush_live[NM_NUM_CATEGORIES]; + long long _post_flush_max[NM_NUM_CATEGORIES]; + void capturePostFlushNativeMem(); + static float ratio(float value) { return value < 0 ? 0 : value > 1 ? 1 : value; } @@ -345,25 +367,6 @@ class Recording { void updateNativeMemStats(); void writeNativeMem(Buffer *buf); - // Per-category NativeMem state captured immediately AFTER writeCpool(), and - // emitted by the following chunk. - // - // The chunk's own counters are necessarily sampled before serialization: the - // chunk header records cpool_offset as the boundary between the event section - // and the constant pool, so no event may be appended once writeCpool() has - // run. But writeCpool() is where the method map is built and the dictionary - // grows -- by two orders of magnitude in a large recording -- so a consumer - // reading only the in-chunk values never sees the cost of serialization. - // - // native_mem_max_bytes does eventually reflect it, because record() raises - // the peak at allocation time and nothing ever resets it, but only one chunk - // late and only as a lifetime maximum: after several flushes it can no longer - // say which flush was responsible. These snapshots give the per-flush figure. - bool _has_post_flush; - long long _post_flush_live[NM_NUM_CATEGORIES]; - long long _post_flush_max[NM_NUM_CATEGORIES]; - void capturePostFlushNativeMem(); - void writeUnwindFailures(Buffer *buf); void writeContextSnapshot(Buffer *buf, Context &context); diff --git a/ddprof-test/src/test/java/com/datadoghq/profiler/nativemem/NativeMemAccountingTest.java b/ddprof-test/src/test/java/com/datadoghq/profiler/nativemem/NativeMemAccountingTest.java index 0779a01cd9..038874ed16 100644 --- a/ddprof-test/src/test/java/com/datadoghq/profiler/nativemem/NativeMemAccountingTest.java +++ b/ddprof-test/src/test/java/com/datadoghq/profiler/nativemem/NativeMemAccountingTest.java @@ -5,8 +5,13 @@ package com.datadoghq.profiler.nativemem; import com.datadoghq.profiler.AbstractProfilerTest; +import com.datadoghq.profiler.JfrEvents; import org.junit.jupiter.api.Test; +import java.nio.file.Files; +import java.nio.file.Path; + +import static org.junit.jupiter.api.Assertions.assertEquals; import static org.junit.jupiter.api.Assertions.assertTrue; /** @@ -33,15 +38,7 @@ public void shouldPublishSaneNativeMemCounters() throws Exception { // Keep the sampler busy briefly so the profiler's native buffers // (calltrace storage, dictionaries, per-thread data, ...) are populated // while the recording captures the counters. - long deadline = System.nanoTime() + 100_000_000L; // ~100ms - double sink = 0; - while (System.nanoTime() < deadline) { - for (int i = 0; i < 10_000; i++) { - sink += Math.sqrt(i); - } - } - // Guard against dead-code elimination of the busy loop. - assertTrue(!Double.isNaN(sink)); + busyLoop(); stopProfiler(); @@ -61,4 +58,83 @@ public void shouldPublishSaneNativeMemCounters() throws Exception { assertTrue(max >= live, "max (" + max + ") >= live (" + live + ")"); assertTrue(max >= avg, "max (" + max + ") >= avg (" + avg + ")"); } + + /** + * Integration test for the cross-chunk post-flush snapshot ({@code + * Recording::capturePostFlushNativeMem}, {@code flightRecorder.cpp}): a + * dump() mid-recording forces exactly one chunk switch on the continuous + * recording, so the resulting file has exactly two chunks. This pins: + *
    + *
  • the first-chunk-absent invariant ({@code _has_post_flush} starts + * {@code false}): the post-flush labels must not appear in the first + * chunk;
    • + *
  • the later-chunk-present case: they must appear, and be sane, once + * {@code finishChunk()} has run at least once;
    • + *
  • the label spelling ({@code native_mem_post_flush_live_bytes.*} / + * {@code native_mem_post_flush_max_bytes.*}).
    • + *
+ * With exactly one forced chunk switch, a post-flush label can appear at + * most once in the whole recording (only in the second chunk) -- so + * "exactly one occurrence" is equivalent to "absent in chunk 1, present in + * chunk 2", without needing per-chunk parsing. + */ + @Test + public void shouldEmitPostFlushCountersOnlyAfterAChunkSwitch() throws Exception { + String liveLabel = "native_mem_post_flush_live_bytes.jfr_buffers"; + String maxLabel = "native_mem_post_flush_max_bytes.jfr_buffers"; + + // Nothing has flushed yet: the very first getRecordedCounterValue below + // would find these labels nowhere in the recording if this busyLoop() + // were the only chunk. Populate some native memory before forcing the + // switch so the post-flush snapshot has a non-trivial "jfr_buffers" + // value to capture. + busyLoop(); + + Path dumpTarget = Files.createTempFile("native-mem-post-flush", ".jfr"); + try { + // Forces exactly one finishChunk(end_recording=true, do_cleanup=true) + // on the continuous recording (see FlightRecorder::dump -> + // Recording::switchChunk), which is where capturePostFlushNativeMem() + // runs. + dump(dumpTarget); + + // Keep the second chunk non-empty too. + busyLoop(); + stopProfiler(); + + long live = getRecordedCounterValue(liveLabel); + long max = getRecordedCounterValue(maxLabel); + assertTrue(live >= 0, liveLabel + " present, was " + live); + assertTrue(max >= 0, maxLabel + " present, was " + max); + assertTrue(max >= live, "post-flush max (" + max + ") >= post-flush live (" + live + ")"); + + assertEquals(1, countCounterOccurrences(liveLabel), + liveLabel + " must appear exactly once: absent in the first chunk (_has_post_flush" + + " starts false), present from the second chunk onward"); + assertEquals(1, countCounterOccurrences(maxLabel), + maxLabel + " must appear exactly once: absent in the first chunk, present from the" + + " second chunk onward"); + } finally { + Files.deleteIfExists(dumpTarget); + } + } + + /** Keeps the sampler busy briefly so native buffers are populated for the counters to report. */ + private void busyLoop() { + long deadline = System.nanoTime() + 100_000_000L; // ~100ms + double sink = 0; + while (System.nanoTime() < deadline) { + for (int i = 0; i < 10_000; i++) { + sink += Math.sqrt(i); + } + } + // Guard against dead-code elimination of the busy loop. + assertTrue(!Double.isNaN(sink)); + } + + /** Counts how many {@code datadog.ProfilerCounter} events carry {@code counterName}. */ + private long countCounterOccurrences(String counterName) throws Exception { + JfrEvents events = verifyEvents("datadog.ProfilerCounter", false); + return events.filter(item -> counterName.equals(item.getString(NAME))).count(); + } }