native-image, JFR, buffers "[warn][jfr,system] Unable to commit. Requested size too large"

[Karm]

Hello,

This issue, or perhaps a feature request if you will, concerns with handling buffers for larger JFR events when JFR is used with native-image built binaries. I will demonstrate what I mean on my homemade JDK 11 build (HEAD f700d37d2b) and Mandrel master build (HEAD 6e6bbca) and then show the behavior is also reproducible with GraalVM CE 21.2.0.

printf debuging

I patched the JDK 11 build (HEAD f700d37d2b) as follows:

index 595635e41b..708effdeb1 100644
--- a/src/hotspot/share/jfr/recorder/storage/jfrStorage.cpp
+++ b/src/hotspot/share/jfr/recorder/storage/jfrStorage.cpp
@@ -562,6 +562,7 @@ static BufferPtr large_fail(BufferPtr cur, bool native, JfrStorage& storage_inst
 // even though it might be smaller than the requested size.
 // Caller needs to ensure if the size was successfully accommodated.
 BufferPtr JfrStorage::provision_large(BufferPtr cur, const u1* const cur_pos, size_t used, size_t req, bool native, Thread* t) {
+  log_info(jfr)("JfrStorage::provision_large called, used: " SIZE_FORMAT ", requested: " SIZE_FORMAT ".", used, req);
   debug_only(assert_provision_large_precondition(cur, used, req, t);)
   assert(t->jfr_thread_local()->shelved_buffer() != NULL, "invariant");
   BufferPtr const buffer = acquire_large(req, t);
diff --git a/src/jdk.jfr/share/classes/jdk/jfr/internal/EventWriter.java b/src/jdk.jfr/share/classes/jdk/jfr/internal/EventWriter.java
index a1d697bb9e..e5825eed21 100644
--- a/src/jdk.jfr/share/classes/jdk/jfr/internal/EventWriter.java
+++ b/src/jdk.jfr/share/classes/jdk/jfr/internal/EventWriter.java
@@ -195,7 +195,9 @@ public final class EventWriter {
             return false;
         }
         if (currentPosition + requestedSize > maxPosition) {
+            System.out.printf("KARM 1: currentPosition: %d, requestedSize: %d , maxPosition: %d\n", currentPosition, requestedSize, maxPosition);
             flushOnEnd = flush(usedSize(), requestedSize);
+            System.out.printf("KARM 2: currentPosition: %d, requestedSize: %d , maxPosition: %d\n", currentPosition, requestedSize, maxPosition);
             // retry
             if (currentPosition + requestedSize > maxPosition) {
                 Logger.log(LogTag.JFR_SYSTEM,
@@ -273,6 +275,7 @@ public final class EventWriter {
     }
 
     private EventWriter(long startPos, long maxPos, long startPosAddress, long threadID, boolean valid) {
+        System.out.printf("KARM EventWriter: startPos: %d, maxPos: %d, startPosAddress: %d\n", startPos, maxPos, startPosAddress);
         startPosition = currentPosition = startPos;
         maxPosition = maxPos;
         startPositionAddress = startPosAddress;

Resulting Mandrel native-image --version:

native-image 21.3.0-dev6e6bbcacb30d Mandrel Distribution (Java Version 11.0.13-internal+0-adhoc.karm.jdk11u-dev)

How to reproduce

Build example code

1. Open a fresh new terminal window. This is an important step.
2. Create Main.java e.g. as follows:

public class Main {
    public static void main(String... args) {
        System.out.println("Meh.");
    }
}

3. Set env vars to your native-image capable JDK distro, in my case:
   export JAVA_HOME=/home/karm/tmp/mandrel-java11-21.3-SNAPSHOT/;export PATH=${JAVA_HOME}/bin:${PATH}
4. Compile Main class to bytecode:
   javac Main.java
5. Compile Main class to a native executable, JFR enabled:
   native-image -H:+AllowVMInspection Main

Run without any huge env vars ✔️

Java run

$ java -XX:+FlightRecorder -XX:StartFlightRecording=filename=flight-java.jfr -Xlog:jfr Main
[0.310s][info][jfr] Flight Recorder initialized
[0.310s][info][jfr] Created repository /tmp/2021_07_30_13_08_56_263300
[0.340s][info][jfr] Creating thread sampler for java:20 ms, native 0 ms
[0.340s][info][jfr] Enrolling thread sampler
[0.340s][info][jfr] Enrolling thread sampler
[0.340s][info][jfr] Updated thread sampler for java: 20  ms, native 0 ms
[0.340s][info][jfr] Updated thread sampler for java: 20  ms, native 0 ms
[0.340s][info][jfr] Updated thread sampler for java: 20  ms, native 20 ms
KARM EventWriter: startPos: 140076470131632, maxPos: 140076470139824, startPosAddress: 140076470131608
KARM 1: currentPosition: 140076470139796, requestedSize: 33 , maxPosition: 140076470139824
KARM 2: currentPosition: 140076470131648, requestedSize: 33 , maxPosition: 140076470139824
[0.352s][info][jfr] JfrStorage::provision_large called, used: 14, requested: 14368.
[0.353s][info][jfr] Started recording "1" (1) {dumponexit=true, filename=/tmp/rep/flight-java.jfr}
Started recording 1. No limit specified, using maxsize=250MB as default.

Use jcmd 263300 JFR.dump name=1 to copy recording data to file.
Meh.
[0.368s][info][jfr] JfrStorage::provision_large called, used: 21, requested: 14327.
[0.369s][info][jfr] JfrStorage::provision_large called, used: 14, requested: 17102.
[0.373s][info][jfr] Updated thread sampler for java: 0  ms, native 20 ms
[0.373s][info][jfr] Disenrolling thread sampler
[0.373s][info][jfr] Stopped recording "1" (1). Reason "Dump on exit".
[0.419s][info][jfr] Wrote recording "1" (1) to /tmp/rep/flight-java.jfr
[0.420s][info][jfr] Closed recording "1" (1)
[0.422s][info][jfr] Removed repository /tmp/2021_07_30_13_08_56_263300

Native image run

$ ./main -XX:+FlightRecorder -XX:StartFlightRecording=filename=flight-native.jfr -Xlog:jfr
KARM EventWriter: startPos: 28949856, maxPos: 28958048, startPosAddress: 28949824
KARM 1: currentPosition: 28958037, requestedSize: 27 , maxPosition: 28958048
KARM 2: currentPosition: 28949873, requestedSize: 27 , maxPosition: 28958048
KARM 1: currentPosition: 28951632, requestedSize: 7863 , maxPosition: 28958048
KARM 2: currentPosition: 28949875, requestedSize: 7863 , maxPosition: 28958048
KARM 1: currentPosition: 28957011, requestedSize: 5343 , maxPosition: 28958048
KARM 2: currentPosition: 28949880, requestedSize: 5343 , maxPosition: 28958048
Meh.
KARM EventWriter: startPos: 139757363399936, maxPos: 139757363408128, startPosAddress: 139757363399904

Run with a huge env var set ❌

Set a bigger env var. This could be your PATH or something else...

$ export HUGE_X_VAR=$(eval echo {1..70} | sed "s/[[:digit:]]*/Something very log, perhaps a concatenated path.../g")

$ echo $HUGE_X_VAR | wc -c 
3570

Java run

No warning. Good.

$ java -XX:+FlightRecorder -XX:StartFlightRecording=filename=flight-java.jfr -Xlog:jfr Main
[0.289s][info][jfr] Flight Recorder initialized
[0.289s][info][jfr] Created repository /tmp/2021_07_30_13_19_09_266044
[0.329s][info][jfr] Creating thread sampler for java:20 ms, native 0 ms
[0.329s][info][jfr] Enrolling thread sampler
[0.329s][info][jfr] Enrolling thread sampler
[0.329s][info][jfr] Updated thread sampler for java: 20  ms, native 0 ms
[0.329s][info][jfr] Updated thread sampler for java: 20  ms, native 0 ms
[0.329s][info][jfr] Updated thread sampler for java: 20  ms, native 20 ms
KARM EventWriter: startPos: 139906013715888, maxPos: 139906013724080, startPosAddress: 139906013715864
KARM 1: currentPosition: 139906013724052, requestedSize: 33 , maxPosition: 139906013724080
KARM 2: currentPosition: 139906013715904, requestedSize: 33 , maxPosition: 139906013724080
[0.340s][info][jfr] JfrStorage::provision_large called, used: 14, requested: 14368.
[0.341s][info][jfr] Started recording "1" (1) {dumponexit=true, filename=/tmp/rep/flight-java.jfr}
Started recording 1. No limit specified, using maxsize=250MB as default.

Use jcmd 266044 JFR.dump name=1 to copy recording data to file.
Meh.
[0.354s][info][jfr] JfrStorage::provision_large called, used: 21, requested: 14327.
[0.355s][info][jfr] JfrStorage::provision_large called, used: 14, requested: 17236.
[0.359s][info][jfr] Updated thread sampler for java: 0  ms, native 20 ms
[0.359s][info][jfr] Disenrolling thread sampler
[0.359s][info][jfr] Stopped recording "1" (1). Reason "Dump on exit".
[0.362s][info][jfr] Wrote recording "1" (1) to /tmp/rep/flight-java.jfr
[0.363s][info][jfr] Closed recording "1" (1)
[0.364s][info][jfr] Removed repository /tmp/2021_07_30_13_19_09_266044

Native image run

There is a warning: [warn][jfr,system] Unable to commit. Requested size 10713 too large

$ ./main -XX:+FlightRecorder -XX:StartFlightRecording=filename=flight-native.jfr -Xlog:jfr
KARM EventWriter: startPos: 41782624, maxPos: 41790816, startPosAddress: 41782592
KARM 1: currentPosition: 41790805, requestedSize: 27 , maxPosition: 41790816
KARM 2: currentPosition: 41782641, requestedSize: 27 , maxPosition: 41790816
KARM 1: currentPosition: 41784400, requestedSize: 7863 , maxPosition: 41790816
KARM 2: currentPosition: 41782643, requestedSize: 7863 , maxPosition: 41790816
KARM 1: currentPosition: 41785657, requestedSize: 10713 , maxPosition: 41790816
KARM 2: currentPosition: 41782624, requestedSize: 10713 , maxPosition: 41790816
[warn][jfr,system] Unable to commit. Requested size 10713 too large
KARM 1: currentPosition: 41786771, requestedSize: 5343 , maxPosition: 41790816
KARM 2: currentPosition: 41782648, requestedSize: 5343 , maxPosition: 41790816
Meh.
KARM EventWriter: startPos: 140184846863616, maxPos: 140184846871808, startPosAddress: 140184846863584

The same with GraalVM CE 21.2.0

Open a new terminal window.

1. Build

$ export JAVA_HOME=/home/karm/X/JDKs/graalvm-ce-java11-21.2.0/;export PATH=${JAVA_HOME}/bin:${PATH}
$ native-image --version
GraalVM 21.2.0 Java 11 CE (Java Version 11.0.12+6-jvmci-21.2-b08)
$ javac Main.java
$ native-image -H:+AllowVMInspection Main

2. Run without any huge env var

$  java -XX:+FlightRecorder -XX:StartFlightRecording=filename=flight-java.jfr -Xlog:jfr Main
[0.272s][info][jfr] Flight Recorder initialized
[0.272s][info][jfr] Created repository /tmp/2021_07_30_13_26_38_267750
[0.300s][info][jfr] Creating thread sampler for java:20 ms, native 0 ms
[0.300s][info][jfr] Enrolling thread sampler
[0.300s][info][jfr] Enrolling thread sampler
[0.300s][info][jfr] Updated thread sampler for java: 20  ms, native 0 ms
[0.300s][info][jfr] Updated thread sampler for java: 20  ms, native 0 ms
[0.300s][info][jfr] Updated thread sampler for java: 20  ms, native 20 ms
[0.307s][info][jfr] Started recording "1" (1) {dumponexit=true, filename=/tmp/rep/flight-java.jfr}
Started recording 1. No limit specified, using maxsize=250MB as default.

Use jcmd 267750 JFR.dump name=1 to copy recording data to file.
Meh.
[0.329s][info][jfr] Updated thread sampler for java: 0  ms, native 20 ms
[0.329s][info][jfr] Disenrolling thread sampler
[0.329s][info][jfr] Stopped recording "1" (1). Reason "Dump on exit".
[0.343s][info][jfr] Wrote recording "1" (1) to /tmp/rep/flight-java.jfr
[0.344s][info][jfr] Closed recording "1" (1)
[0.345s][info][jfr] Removed repository /tmp/2021_07_30_13_26_38_267750


$ ./main -XX:+FlightRecorder -XX:StartFlightRecording=filename=flight-native.jfr -Xlog:jfr
Meh.

3. Export a big env var and see the warning Unable to commit. Requested size 10713 too large with native image run:

$ export HUGE_X_VAR=$(eval echo {1..70} | sed "s/[[:digit:]]*/Something very log, perhaps a concatenated path.../g")

$  java -XX:+FlightRecorder -XX:StartFlightRecording=filename=flight-java.jfr -Xlog:jfr Main
[0.317s][info][jfr] Flight Recorder initialized
[0.317s][info][jfr] Created repository /tmp/2021_07_30_13_27_13_268025
[0.352s][info][jfr] Creating thread sampler for java:20 ms, native 0 ms
[0.352s][info][jfr] Enrolling thread sampler
[0.352s][info][jfr] Enrolling thread sampler
[0.352s][info][jfr] Updated thread sampler for java: 20  ms, native 0 ms
[0.352s][info][jfr] Updated thread sampler for java: 20  ms, native 0 ms
[0.352s][info][jfr] Updated thread sampler for java: 20  ms, native 20 ms
[0.361s][info][jfr] Started recording "1" (1) {dumponexit=true, filename=/tmp/rep/flight-java.jfr}
Started recording 1. No limit specified, using maxsize=250MB as default.

Use jcmd 268025 JFR.dump name=1 to copy recording data to file.
Meh.
[0.378s][info][jfr] Updated thread sampler for java: 0  ms, native 20 ms
[0.378s][info][jfr] Disenrolling thread sampler
[0.378s][info][jfr] Stopped recording "1" (1). Reason "Dump on exit".
[0.390s][info][jfr] Wrote recording "1" (1) to /tmp/rep/flight-java.jfr
[0.391s][info][jfr] Closed recording "1" (1)
[0.392s][info][jfr] Removed repository /tmp/2021_07_30_13_27_14_268025


$ ./main -XX:+FlightRecorder -XX:StartFlightRecording=filename=flight-native.jfr -Xlog:jfr
[warn][jfr,system] Unable to commit. Requested size 10713 too large
Meh.

OS

Linux  4.18.0-240.22.1.el8_3.x86_64 (Centos 8 Stream)

Usual suspects: @jiekang

[munishchouhan]

@Karm thanks for reporting the issue, we will check it out and get back to you

[jiekang]

@mcraj017 @Karm Hi! This issue appears because the implementation in Graal Native Image does not currently implement a mechanism for events that are larger than the thread local buffer (default 8192 kb). In HotSpot, the algorithm would either lease a global buffer temporarily for the write, if it can fit, or attempt to allocate a transient buffer (e.g. via malloc) that can fulfill the write request.

At the moment, the expectation is that these events are safely discarded and the program continues to run. The full solution here would be to implement a similar algorithm to support writes of arbitrary size.

If you'd like to see the HotSpot algorithm, you can follow the implementation of this flush method: https://github.com/openjdk/jdk/blob/master/src/hotspot/share/jfr/writers/jfrJavaEventWriter.cpp#L136

[munishchouhan]

@jiekang thanks for the clarification

[munishchouhan]

@Karm @jiekang I have raised the request with Dev team

[christianwimmer]

@jiekang is this something that RedHat can address when keeping up JFR work?

[jiekang]

@christianwimmer I think this is something we can address for a release after 21.3.