Events lost during JFR dumping

[yanglong1010]

Hi,

If the CPU samples of a request crosses 2 JFR files, I noticed the events of the first 100 milliseconds are lost in the 2nd JFR file.
Other events like wall clock have the same problem.

The reason may be during dumping, the lock is hold by the dumping thread, prevent other threads to record sample.

The time of data loss is the same as the time of dumping.

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

Lines 1368 to 1376 in 6e6b454

	lockAll();
	Error err = _jfr.dump(path, length);
	__atomic_add_fetch(&_epoch, 1, __ATOMIC_SEQ_CST);
	// Reset calltrace storage
	if (!_omit_stacktraces) {
	_call_trace_storage.clear();
	}
	unlockAll();

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

Lines 643 to 646 in 6e6b454

	u32 lock_index = getLockIndex(tid);
	if (!_locks[lock_index].tryLock() &&
	!_locks[lock_index = (lock_index + 1) % CONCURRENCY_LEVEL].tryLock() &&
	!_locks[lock_index = (lock_index + 2) % CONCURRENCY_LEVEL].tryLock()) {

jfr print --events datadog.ExecutionSample main2.jfr|tail -500|grep 8087-exec-2 -C 8|grep startTime
  startTime = 2025-01-08T08:20:57.463678644Z
  startTime = 2025-01-08T08:20:57.473686007Z
  startTime = 2025-01-08T08:20:57.483690475Z
  startTime = 2025-01-08T08:20:57.493674091Z
  startTime = 2025-01-08T08:20:57.503680221Z
  startTime = 2025-01-08T08:20:57.513683328Z
  startTime = 2025-01-08T08:20:57.523692408Z
  startTime = 2025-01-08T08:20:57.533673566Z
  startTime = 2025-01-08T08:20:57.544679223Z
  startTime = 2025-01-08T08:20:57.554664168Z
  startTime = 2025-01-08T08:20:57.564674269Z
  startTime = 2025-01-08T08:20:57.582691200Z

the events between 57.582 and 57.703 are missing.

jfr print --events datadog.ExecutionSample main3.jfr|head -500|grep 8087-exec-2 -C 8|grep startTime
  startTime = 2025-01-08T08:20:57.703683147Z
  startTime = 2025-01-08T08:20:57.713690997Z
  startTime = 2025-01-08T08:20:57.723691423Z
  startTime = 2025-01-08T08:20:57.733691817Z
  startTime = 2025-01-08T08:20:57.743690838Z
  startTime = 2025-01-08T08:20:57.753689481Z
  startTime = 2025-01-08T08:20:57.763679896Z
  startTime = 2025-01-08T08:20:57.773688623Z
  startTime = 2025-01-08T08:20:57.783685981Z
  startTime = 2025-01-08T08:20:57.793686079Z
  startTime = 2025-01-08T08:20:57.803634162Z
  startTime = 2025-01-08T08:20:57.808048831Z
  startTime = 2025-01-08T08:20:57.813695887Z
  startTime = 2025-01-08T08:20:57.823696239Z
  startTime = 2025-01-08T08:20:57.833692951Z
  startTime = 2025-01-08T08:20:57.843695651Z
  startTime = 2025-01-08T08:20:57.853680821Z
  startTime = 2025-01-08T08:20:57.863703314Z
  startTime = 2025-01-08T08:20:57.873688124Z
  startTime = 2025-01-08T08:20:57.883689480Z
  startTime = 2025-01-08T08:20:57.893689964Z

[r1viollet]

Thanks for the careful report!
I wonder if introducing a 2nd JFR object and swapping between the 2 (one for the report, the other to allow the dump) would be good in this instance.

[jbachorik]

The problem is more complex - the JFR proper does double-buffering for this reason and in order to achieve that it introduced 'tagging' constant pool artifacts (classes, symbols etc.). When the recording is finalized these constant pool artifacts need to be written out but one needs to make sure that:
a) all artifacts referenced from the recording events are written out
b) only artifacts referenceds from the recording events are written out

This is not a trivial task, hence the tagging and epochs in the JDK JFR engine (if you check the sources, the implementation is anything but simple, to handle all the edge cases).

We are using the JFR writer coming from async-profiler (obviously) and that one is, for the sake of simplicity, not doing any double buffering so this leads to the observed data loss.

So far, the reasoning was that the actual data loss is pretty minimal and it didn't really warrant a full rewrite of the trace storage and JFR writer to support overlapping data collection and recording finalization.

[yanglong1010]

Hi,

During dumping, we'll convert jmethodIds to real class names and method names. If the number of methods recorded in the last minute is very large, we'll spent lots of time in JVMTI, even several seconds. This may lead to unacceptable number of events being lost.

Every time a method is written to JFR, the _mark field is set to false. This means in every dump, we invoke JVMTI for the same jmethodId, even the jmethodId is unchanged. I don't know if we can call JVMTI only once for every jmethodId, this can save much time during dumping.

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

Lines 1161 to 1168 in 4f4d70a

	buf->putVar64(T_METHOD);
	buf->putVar64(marked_count);
	for (MethodMap::iterator it = method_map->begin(); it != method_map->end();
	++it) {
	MethodInfo &mi = it->second;
	if (mi._mark) {
	mi._mark = false;
	buf->putVar64(mi._key);

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

Lines 279 to 284 in 4f4d70a

	MethodInfo *Lookup::resolveMethod(ASGCT_CallFrame &frame) {
	jmethodID method = frame.method_id;
	MethodInfo *mi = &(*_method_map)[method];
	if (!mi->_mark) {
	mi->_mark = true;

I also noticed theses structures are never cleared, in extreme scenarios, they may consume a lot of memory.

java-profiler/ddprof-lib/src/main/cpp/flightRecorder.h

Lines 265 to 268 in 4f4d70a

	MethodMap *_method_map;
	Dictionary *_classes;
	Dictionary _packages;
	Dictionary _symbols;

Any thoughts ?

[jbachorik]

Every time a method is written to JFR, the _mark field is set to false. This means in every dump, we invoke JVMTI for the same jmethodId, even the jmethodId is unchanged. I don't know if we can call JVMTI only once for every jmethodId, this can save much time during dumping.

The marking works as follows:

• first, writeStackTraces is called which will lazily resolve the method metadata and set _mark = true
• then, writeMethods is called and that one will write out only marked methods, resetting _mark during the process

So, we are really not re-resolving all jmethodIDs during a single dump.

Each jmethodID is looked up at most once per one dump. The result is cached in the _method_map which lifecycle is scoped to one recording. This also means that the structures are actually cleared - when you check the usage of Lookup you see that those structures (except of _classes which are global) are discarded once we exit from writeCpool() function.

Agreed, this could be more efficient, but spending seconds on serialization sounds a bit extreme. How large are your recordings?

[yanglong1010]

So, we are really not re-resolving all jmethodIDs during a single dump.

I know in a single dump, each jmethodId is only resolved once. It is possible to resolve each jmethodId only once across multiple dumps (i.e. as the same lifecycle as one recording)?

This also means that the structures are actually cleared - when you check the usage of Lookup you see that those structures (except of _classes which are global) are discarded once we exit from writeCpool() function.

You are right, _packages and _symbols are discarded once we exit from writeCpool.

How large are your recordings?

The dump of the JFR file bellow took more than 300 millis to call JVMTI (see flame graph bellow)
20250116-122439_yibo-service_AZRvEvLTAAByOWOgNV00XwAA.zip

In a real case of our internal application, to dump a 4MiB JFR (not compressed) file, It took more than 4 seconds, most of the data is jdk.CheckPoint.

[jbachorik]

I don't know if we can call JVMTI only once for every jmethodId, this can save much time during dumping.

This would require a shared jmethodID cache that could be accessed concurrently. Also, it would have to be something like an LRU cache, otherwise we would end up using too much memory, caching everything.

As I said, I agree things can be improved. But it is a rather complex topic because of the intricacies of the lifecycle of the collected information etc. (eg. you would need to defensively copy the strings returned for method names, signatures etc.)