[GraalVM for JDK 25] JFR tests fail due to warning about setting certain symbols (JDK 25+26)

[jerboaa]

In CI we see new JFR tests fail with JDK 25+26 based builds:

 Error:    JFRTest.jfrOptionsSmokeTest:784->jfrOptionsSmoke:922 build-and-run.log log should not contain error or warning lines that are not whitelisted. See /home/runner/work/mandrel/mandrel/mandrel-integration-tests/testsuite/target/archived-logs/org.graalvm.tests.integration.JFRTest/jfrOptionsSmokeTest/build-and-run.log and check these offending 2 lines: 
[warn][jfr,system ] Exception occurred during execution of event jdk.MethodTiming(13364). jdk.jfr.internal.JVM.drainStaleMethodTracerIds()[J [symbol: Java_jdk_jfr_internal_JVM_drainStaleMethodTracerIds or Java_jdk_jfr_internal_JVM_drainStaleMethodTracerIds__]
[warn][jfr,setting] Exception occurred when setting value "false". jdk.jfr.internal.JVM.setCPUThrottle(DZ)V [symbol: Java_jdk_jfr_internal_JVM_setCPUThrottle or Java_jdk_jfr_internal_JVM_setCPUThrottle__DZ] ==> expected: <true> but was: <false>

This is likely related to the integration of the following JEPs in JDK 25:
JEP 518: JFR Cooperative Sampling
JEP 520: JFR Method Timing & Tracing
JEP 509: JFR CPU-Time Profiling (Experimental)

For example this implementation bug got added in JDK 25+26. Similar this bug: https://bugs.openjdk.org/browse/JDK-8352738 from JEP 520.

See this failure from a CI run:
https://github.com/graalvm/mandrel/actions/runs/15598778230/job/43936113803#step:11:10009

[jerboaa]

/cc @roberttoyonaga

[jerboaa]

Steps to reproduce:

export JAVA_HOME="/path/to/jdk/17"
export GRAALVM_HOME=/path/to/mandrel-for-jdk-25+26
export PATH=$GRAALVM_HOME/bin:$PATH
mvn clean verify -Ptestsuite -Dtest=JFRTest#jfrOptionsSmokeTest

Fails with:

2025-06-12 14:40:44.077 INFO  [o.g.t.i.u.Commands$ProcessRunner] (run) Command: [native-image, --enable-monitoring=jfr, -jar, target/timezones.jar, target/timezones]
========================================================================================================================
GraalVM Native Image: Generating 'timezones' (executable)...
========================================================================================================================
For detailed information and explanations on the build output, visit:
https://github.com/oracle/graal/blob/master/docs/reference-manual/native-image/BuildOutput.md
------------------------------------------------------------------------------------------------------------------------
[1/8] Initializing...                                                                                    (2.4s @ 0.24GB)
 Java version: 25-beta+26-ea, vendor version: Mandrel-25.0.0-dev
 Graal compiler: optimization level: 2, target machine: x86-64-v3
 C compiler: gcc (redhat, x86_64, 14.3.1)
 Garbage collector: Serial GC (max heap size: 80% of RAM)
 1 user-specific feature(s):
 - com.oracle.svm.thirdparty.gson.GsonFeature
------------------------------------------------------------------------------------------------------------------------
Build resources:
 - 28.45GB of memory (42.6% of system memory, using available memory)
 - 23 thread(s) (104.5% of 22 available processor(s), determined at start)
[2/8] Performing analysis...  [******]                                                                   (7.1s @ 0.55GB)
    4,992 types,   5,658 fields, and  22,129 methods found reachable
    1,501 types,      66 fields, and     511 methods registered for reflection
       59 types,      60 fields, and      52 methods registered for JNI access
        0 downcalls and 0 upcalls registered for foreign access
        5 native libraries: dl, m, pthread, rt, z
[3/8] Building universe...                                                                               (1.2s @ 0.54GB)
[4/8] Parsing methods...      [*]                                                                        (1.0s @ 0.64GB)
[5/8] Inlining methods...     [***]                                                                      (0.3s @ 0.71GB)
[6/8] Compiling methods...    [***]                                                                      (5.9s @ 0.88GB)
[7/8] Laying out methods...   [*]                                                                        (1.5s @ 0.95GB)
[8/8] Creating image...       [*]                                                                        (1.4s @ 1.05GB)
   7.95MB (36.82%) for code area:    12,652 compilation units
  11.93MB (55.27%) for image heap:  146,873 objects and 56 resources
   1.71MB ( 7.92%) for other data
  21.58MB in total image size, 20.38MB in total file size
------------------------------------------------------------------------------------------------------------------------
Top 10 origins of code area:                                Top 10 object types in image heap:
   5.12MB java.base                                            2.25MB byte[] for code metadata
   1.11MB jdk.jfr                                              2.14MB byte[] for java.lang.String
   1.09MB svm.jar (Native Image)                               1.38MB java.lang.String
 110.81kB java.logging                                       998.40kB com.oracle.svm.core.hub.DynamicHubCompanion
 108.35kB jdk.proxy1                                         646.32kB java.lang.Class
  90.80kB org.graalvm.nativeimage.base                       507.42kB heap alignment
  49.16kB jdk.proxy2                                         331.39kB java.util.HashMap$Node
  28.03kB jdk.internal.vm.ci                                 323.47kB java.lang.Object[]
  20.07kB org.graalvm.collections                            291.65kB byte[] for general heap data
  12.04kB jdk.proxy3                                         263.95kB java.lang.String[]
  14.94kB for 8 more packages                                  2.79MB for 1408 more object types
------------------------------------------------------------------------------------------------------------------------
Recommendations:
 FUTR: Use '--future-defaults=all' to prepare for future releases.
 HEAP: Set max heap for improved and more predictable memory usage.
 CPU:  Enable more CPU features with '-march=native' for improved performance.
------------------------------------------------------------------------------------------------------------------------
                       0.9s (4.0% of total time) in 179 GCs | Peak RSS: 1.82GB | CPU load: 14.69
------------------------------------------------------------------------------------------------------------------------
Build artifacts:
 /disk/graal/upstream-sources/mandrel-integration-tests/apps/timezones/target/timezones (executable)
========================================================================================================================
Finished generating 'timezones' in 21.4s.
2025-06-12 14:41:07.711 INFO  [o.g.t.i.u.Commands] (runCommand) Command: [./target/timezones, -XX:+FlightRecorder, -XX:StartFlightRecording=maxsize=10000,delay=1000000000ns,filename=logs/flight-native.jfr, -XX:FlightRecorderLogging=jfr]
2025-06-12 14:41:08.730 INFO  [o.g.t.i.u.Commands] (runCommand) Command: [./target/timezones, -XX:+FlightRecorder, -XX:StartFlightRecording=maxsize=10k,filename=logs/flight-native.jfr, -XX:FlightRecorderLogging=jfr]
2025-06-12 14:41:09.760 INFO  [o.g.t.i.u.Commands] (runCommand) Command: [./target/timezones, -XX:+FlightRecorder, -XX:StartFlightRecording=maxsize=10M,filename=logs/flight-native.jfr, -XX:FlightRecorderLogging=jfr]
2025-06-12 14:41:10.791 INFO  [o.g.t.i.u.Commands] (runCommand) Command: [./target/timezones, -XX:+FlightRecorder, -XX:StartFlightRecording=maxsize=10000,maxage=10000ns,filename=logs/flight-native.jfr, -XX:FlightRecorderLogging=jfr]
2025-06-12 14:41:11.827 INFO  [o.g.t.i.u.Commands] (runCommand) Command: [./target/timezones, -XX:+FlightRecorder, -XX:StartFlightRecording=maxsize=10000,delay=5s,filename=logs/flight-native.jfr, -XX:FlightRecorderLogging=jfr]
2025-06-12 14:41:12.845 INFO  [o.g.t.i.u.Commands] (runCommand) Command: [./target/timezones, -XX:+FlightRecorder, -XX:StartFlightRecording=maxsize=10000,maxage=30s,filename=logs/flight-native.jfr, -XX:FlightRecorderLogging=jfr]
2025-06-12 14:41:13.878 INFO  [o.g.t.i.u.Commands] (runCommand) Command: [./target/timezones, -XX:+FlightRecorder, -XX:StartFlightRecording=maxsize=10000,maxage=10m,filename=logs/flight-native.jfr, -XX:FlightRecorderLogging=jfr]
2025-06-12 14:41:14.913 INFO  [o.g.t.i.u.Commands] (runCommand) Command: [./target/timezones, -XX:+FlightRecorder, -XX:StartFlightRecording=maxsize=10000,filename=logs/flight-native.jfr, -XX:FlightRecorderLogging=jfr]
2025-06-12 14:41:15.947 INFO  [o.g.t.i.u.Commands] (runCommand) Command: [./target/timezones, -XX:+FlightRecorder, -XX:StartFlightRecording=maxsize=10000,maxage=11h,filename=logs/flight-native.jfr, -XX:FlightRecorderLogging=jfr]
2025-06-12 14:41:16.977 INFO  [o.g.t.i.u.Commands] (runCommand) Command: [./target/timezones, -XX:+FlightRecorder, -XX:StartFlightRecording=maxsize=10000,delay=5m,filename=logs/flight-native.jfr, -XX:FlightRecorderLogging=jfr]
2025-06-12 14:41:17.997 INFO  [o.g.t.i.u.Commands] (runCommand) Command: [./target/timezones, -XX:+FlightRecorder, -XX:StartFlightRecording=maxsize=10000,delay=5d,filename=logs/flight-native.jfr, -XX:FlightRecorderLogging=jfr]
2025-06-12 14:41:19.015 INFO  [o.g.t.i.u.Commands] (runCommand) Command: [./target/timezones, -XX:+FlightRecorder, -XX:StartFlightRecording=maxsize=10000,filename=logs/flight-native.jfr, -XX:FlightRecorderLogging=jfr]
2025-06-12 14:41:20.048 INFO  [o.g.t.i.u.Commands] (runCommand) Command: [./target/timezones, -XX:+FlightRecorder, -XX:StartFlightRecording=maxsize=10000,delay=5h,filename=logs/flight-native.jfr, -XX:FlightRecorderLogging=jfr]
2025-06-12 14:41:21.067 INFO  [o.g.t.i.u.Commands] (runCommand) Command: [./target/timezones, -XX:+FlightRecorder, -XX:StartFlightRecording=maxsize=10m,filename=logs/flight-native.jfr, -XX:FlightRecorderLogging=jfr]
2025-06-12 14:41:22.101 INFO  [o.g.t.i.u.Commands] (runCommand) Command: [./target/timezones, -XX:+FlightRecorder, -XX:StartFlightRecording=maxsize=10g,filename=logs/flight-native.jfr, -XX:FlightRecorderLogging=jfr]
[ERROR] Tests run: 1, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 39.957 s <<< FAILURE! - in org.graalvm.tests.integration.JFRTest
[ERROR] jfrOptionsSmokeTest{TestInfo}  Time elapsed: 39.427 s  <<< FAILURE!
org.opentest4j.AssertionFailedError: 
build-and-run.log log should not contain error or warning lines that are not whitelisted. See /disk/graal/upstream-sources/mandrel-integration-tests/testsuite/target/archived-logs/org.graalvm.tests.integration.JFRTest/jfrOptionsSmokeTest/build-and-run.log and check these offending 2 lines: 
[warn][jfr,setting] Exception occurred when setting value "false". jdk.jfr.internal.JVM.setCPUThrottle(DZ)V [symbol: Java_jdk_jfr_internal_JVM_setCPUThrottle or Java_jdk_jfr_internal_JVM_setCPUThrottle__DZ]
[warn][jfr,system ] Exception occurred during execution of event jdk.MethodTiming(9316). jdk.jfr.internal.JVM.drainStaleMethodTracerIds()[J [symbol: Java_jdk_jfr_internal_JVM_drainStaleMethodTracerIds or Java_jdk_jfr_internal_JVM_drainStaleMethodTracerIds__] ==> expected: <true> but was: <false>
	at org.graalvm.tests.integration.JFRTest.jfrOptionsSmoke(JFRTest.java:922)
	at org.graalvm.tests.integration.JFRTest.jfrOptionsSmokeTest(JFRTest.java:784)

[INFO] 
[INFO] Results:
[INFO] 
[ERROR] Failures: 
[ERROR]   JFRTest.jfrOptionsSmokeTest:784->jfrOptionsSmoke:922 build-and-run.log log should not contain error or warning lines that are not whitelisted. See /disk/graal/upstream-sources/mandrel-integration-tests/testsuite/target/archived-logs/org.graalvm.tests.integration.JFRTest/jfrOptionsSmokeTest/build-and-run.log and check these offending 2 lines: 
[warn][jfr,setting] Exception occurred when setting value "false". jdk.jfr.internal.JVM.setCPUThrottle(DZ)V [symbol: Java_jdk_jfr_internal_JVM_setCPUThrottle or Java_jdk_jfr_internal_JVM_setCPUThrottle__DZ]
[warn][jfr,system ] Exception occurred during execution of event jdk.MethodTiming(9316). jdk.jfr.internal.JVM.drainStaleMethodTracerIds()[J [symbol: Java_jdk_jfr_internal_JVM_drainStaleMethodTracerIds or Java_jdk_jfr_internal_JVM_drainStaleMethodTracerIds__] ==> expected: <true> but was: <false>
[INFO] 
[ERROR] Tests run: 1, Failures: 1, Errors: 0, Skipped: 0
[INFO] 
[INFO] ------------------------------------------------------------------------
[INFO] Reactor Summary for Native image integration TS 1.0.0-SNAPSHOT:
[INFO] 
[INFO] Native image integration TS ........................ SUCCESS [  0.077 s]
[INFO] testsuite .......................................... FAILURE [ 42.413 s]
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time:  42.542 s
[INFO] Finished at: 2025-06-12T14:41:22+02:00
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal org.apache.maven.plugins:maven-surefire-plugin:2.22.2:test (default-test) on project testsuite: There are test failures.
[ERROR] 
[ERROR] Please refer to /disk/graal/upstream-sources/mandrel-integration-tests/testsuite/target/surefire-reports for the individual test results.
[ERROR] Please refer to dump files (if any exist) [date].dump, [date]-jvmRun[N].dump and [date].dumpstream.
[ERROR] -> [Help 1]
[ERROR] 
[ERROR] To see the full stack trace of the errors, re-run Maven with the -e switch.
[ERROR] Re-run Maven using the -X switch to enable full debug logging.
[ERROR] 
[ERROR] For more information about the errors and possible solutions, please read the following articles:
[ERROR] [Help 1] http://cwiki.apache.org/confluence/display/MAVEN/MojoFailureException
[ERROR] 
[ERROR] After correcting the problems, you can resume the build with the command
[ERROR]   mvn <args> -rf :testsuite

[jerboaa]

Looking at build-and-run.log I see that at least this particular invocation of the native image triggers the exception being thrown:

Command: ./target/timezones -XX:+FlightRecorder -XX:StartFlightRecording=maxsize=10k,filename=logs/flight-native.jfr -XX:FlightRecorderLogging=jfr

[roberttoyonaga]

Yes, these are related to the new JFR features in JDK 25+26. SubstrateVM needs a couple new substitutions to fix this.

[roberttoyonaga]

I've been talking to Christian H. about this. I'm waiting for the latest Labs JDK update PR to be posted. I think it should already have the substitutions we need. If not, I plan to make my own PR covering them.

[jerboaa]

I've been talking to Christian H. about this. I'm waiting for the latest Labs JDK update PR to be posted. I think it should already have the substitutions we need. If not, I plan to make my own PR covering them.

Latest as in JDK 25+26? That's this one and is merged: oracle/graal#11374

[roberttoyonaga]

I didn't realized it was already made. I'm going to check it over now.

[roberttoyonaga]

Ok it looks like the substitutions for JVM.setCPUThrottle and JVM.drainStaleMethodTracerIds were missed in the JDK update PR. I'll make a PR upstream adding them. Thank you for pointing this out.

[jerboaa]

OK, assigned the issue to you.

[roberttoyonaga]

Thanks!

I've opened a PR here: oracle/graal#11400
That should get rid of the new warnings and prevent these tests from failing.

[jerboaa]

Should be fixed with the upstream merge of oracle/graal#11403. I'll close once we see it passing in the next run.

[jerboaa]

This is fixed. See this run of a Mandrel build with 25+28:
https://github.com/graalvm/mandrel/actions/runs/15800887386/job/44588891891#step:11:9253