diff --git a/ddprof-lib/src/main/cpp/flightRecorder.cpp b/ddprof-lib/src/main/cpp/flightRecorder.cpp index 6d6b46003b..46e9ae3ee6 100644 --- a/ddprof-lib/src/main/cpp/flightRecorder.cpp +++ b/ddprof-lib/src/main/cpp/flightRecorder.cpp @@ -878,7 +878,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); @@ -1056,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++) { @@ -2013,6 +2024,26 @@ 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. 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()); +} + 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 @@ -2070,6 +2101,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 2f59570ced..6efbc52b45 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" @@ -246,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; } 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: + * + * 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(); + } }