search

Karm / mandrel-integration-tests

Integration tests for GraalVM and its Mandrel distribution. Runs Quarkus, Helidon and Micronaut applications and small targeted reproducers. The focus is solely on native-image utility and compilation of Java applications into native executables.
Apache License 2.0
5 stars 3 forks source link

[23.0] JFRTest.jfrOptionsSmokeTest test failing with latest JDK 17.0.12 #271

Closed jerboaa closed 2 weeks ago

jerboaa commented 3 weeks ago

We've probably seen this for a while, but there is a JFR related issue showing up on integration tests for the 23.0 train (JDK 17 based):

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 /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 lines: 
[warn][jfr,system] Exception occurred during execution of period hook for jdk.ContainerConfiguration(21984) ==> expected: <true> but was: <false>
Error:    JFRTest.jfrPerfTest:185->jfrPerfTestRun:234 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/jfrPerfTest/build-and-run.log and check these offending lines: 
[warn][jfr,system] Exception occurred during execution of period hook for jdk.ContainerConfiguration(34142)
Warning:  [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] You are using an older version of GraalVM or Mandrel : 23.0.4.2-dev29022ff4. Quarkus currently supports 23.1.0. Please upgrade to this version. ==> expected: <true> but was: <false>
Error:    JFRTest.jfrSmokeTest:151->jfrSmoke:722 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/jfrSmokeTest/build-and-run.log and check these offending lines: 
[warn][jfr,system] Exception occurred during execution of period hook for jdk.ContainerConfiguration(22130) ==> expected: <true> but was: <false>

The JDK version in use is: 17.0.12-beta+6-ea

See https://github.com/graalvm/mandrel/actions/runs/9815025073/job/27103947971#step:11:21633

jerboaa commented 3 weeks ago

Steps to reproduce:

  1. build Mandrel 23.0 from the release tree with JDK 17.0.12:
  2. export JAVA_HOME=/path/to/mandrel; export GRAALVM_HOME=$JAVA_HOME; export PATH=$JAVA_HOME/bin:$PATH; mvn clean verify -Dquarkus.version=999-SNAPSHOT -Ptestsuite -Dtest=JFRTest#jfrSmokeTest
jerboaa commented 3 weeks ago

With this patch to the base JDK 17 we get more info as to what's happening:

$ git diff
diff --git a/src/jdk.jfr/share/classes/jdk/jfr/internal/RequestEngine.java b/src/jdk.jfr/share/classes/jdk/jfr/internal/RequestEngine.java
index 964b7438759..489cdfbe9e8 100644
--- a/src/jdk.jfr/share/classes/jdk/jfr/internal/RequestEngine.java
+++ b/src/jdk.jfr/share/classes/jdk/jfr/internal/RequestEngine.java
@@ -77,6 +77,7 @@ public final class RequestEngine {
                 }
             } catch (Throwable e) {
                 // Prevent malicious user to propagate exception callback in the wrong context
+               e.printStackTrace();
                 Logger.log(LogTag.JFR_SYSTEM, LogLevel.WARN, "Exception occurred during execution of period hook for " + type.getLogName());
             }
         }
@@ -92,6 +93,7 @@ public final class RequestEngine {
                             Logger.log(LogTag.JFR_EVENT, LogLevel.DEBUG, "Executed periodic hook for " + type.getLogName());
                         }
                     } catch (Throwable t) {
+                       t.printStackTrace();
                         // Prevent malicious user to propagate exception callback in the wrong context
                         Logger.log(LogTag.JFR_EVENT, LogLevel.WARN, "Exception occurred during execution of period hook for " + type.getLogName());
                     }

It's actually the backport of https://bugs.openjdk.org/browse/JDK-8299858 (new in 17.0.12), which causes it:

$ ./target/debug-symbols-smoke -XX:+FlightRecorder -XX:StartFlightRecording=filename=logs/flight-native.jfr -XX:FlightRecorderLogging=jfr
[info][jfr] Added periodic hook for EveryChunkPeriodEvents(10470)
[info][jfr] Added periodic hook for EndChunkPeriodEvents(10472)
[info][jfr] Flight Recorder initialized
[info][jfr] Repository base directory: /tmp
java.lang.UnsatisfiedLinkError: jdk.internal.platform.CgroupMetrics.getTotalSwapSize0()J [symbol: Java_jdk_internal_platform_CgroupMetrics_getTotalSwapSize0 or Java_jdk_internal_platform_CgroupMetrics_getTotalSwapSize0__]
    at org.graalvm.nativeimage.builder/com.oracle.svm.core.jni.access.JNINativeLinkage.getOrFindEntryPoint(JNINativeLinkage.java:152)
    at org.graalvm.nativeimage.builder/com.oracle.svm.core.jni.JNIGeneratedMethodSupport.nativeCallAddress(JNIGeneratedMethodSupport.java:53)
    at java.base@17.0.12-internal/jdk.internal.platform.CgroupMetrics.getTotalSwapSize0(Native Method)
    at java.base@17.0.12-internal/jdk.internal.platform.CgroupMetrics.getMemoryAndSwapLimit(CgroupMetrics.java:147)
    at jdk.jfr@17.0.12-internal/jdk.jfr.internal.instrument.JDKEvents.emitContainerConfiguration(JDKEvents.java:200)
    at jdk.jfr@17.0.12-internal/jdk.jfr.internal.RequestEngine$RequestHook.execute(RequestEngine.java:68)
    at jdk.jfr@17.0.12-internal/jdk.jfr.internal.RequestEngine.doChunk(RequestEngine.java:188)
    at jdk.jfr@17.0.12-internal/jdk.jfr.internal.RequestEngine.doChunkBegin(RequestEngine.java:181)
    at jdk.jfr@17.0.12-internal/jdk.jfr.internal.PlatformRecorder.start(PlatformRecorder.java:288)
    at jdk.jfr@17.0.12-internal/jdk.jfr.internal.PlatformRecording.start(PlatformRecording.java:123)
    at jdk.jfr@17.0.12-internal/jdk.jfr.Recording.start(Recording.java:184)
    at org.graalvm.nativeimage.builder/com.oracle.svm.core.jfr.JfrManager.initRecording(JfrManager.java:246)
    at org.graalvm.nativeimage.builder/com.oracle.svm.core.jfr.JfrManager.lambda$startupHook$0(JfrManager.java:91)
    at org.graalvm.nativeimage.builder/com.oracle.svm.core.jdk.RuntimeSupport.executeHooks(RuntimeSupport.java:161)
    at org.graalvm.nativeimage.builder/com.oracle.svm.core.jdk.RuntimeSupport.initialize(RuntimeSupport.java:98)
    at org.graalvm.sdk/org.graalvm.nativeimage.VMRuntime.initialize(VMRuntime.java:65)
[warn][jfr,system] Exception occurred during execution of period hook for jdk.ContainerConfiguration(22282)
[info][jfr       ] Started recording "1" (1) {dumponexit=true, filename=/disk/graal/upstream-sources/mandrel-integration-tests/apps/debug-symbols-smoke/logs/flight-native.jfr}
Q to quit
Q
e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
[info][jfr       ] Stopped recording "1" (1). Reason "Dump on exit".
[info][jfr       ] Transferred 120499 bytes from the disk repository
[info][jfr       ] Wrote recording "1" (1) to /disk/graal/upstream-sources/mandrel-integration-tests/apps/debug-symbols-smoke/logs/flight-native.jfr
[info][jfr       ] Closed recording "1" (1)
[info][jfr       ] Removed repository /tmp/2024_07_12_17_46_08_189092
jerboaa commented 3 weeks ago

It looks like this will need a backport of https://github.com/oracle/graal/pull/6751. That took way longer than needed to figure that out. Anyway, working on it now.

jerboaa commented 3 weeks ago

https://github.com/graalvm/mandrel/pull/768 is the PR fixing this:

2024-07-15 16:42:53.847 INFO  [o.g.t.i.u.Commands$ProcessRunner] (run) Command: [unzip, test_data.txt.zip, -d, target]
Archive:  test_data.txt.zip
  inflating: target/test_data.txt    
2024-07-15 16:42:54.117 INFO  [o.g.t.i.u.Commands$ProcessRunner] (run) Command: [native-image, --enable-monitoring=jfr, -jar, target/debug-symbols-smoke.jar, target/debug-symbols-smoke]
========================================================================================================================
GraalVM Native Image: Generating 'debug-symbols-smoke' (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.5s @ 0.14GB)
 Java version: 17.0.12-internal+0-adhoc.sgehwolf.jdk17u, vendor version: Mandrel-23.0.5-dev
 Graal compiler: optimization level: 2, target machine: x86-64-v3
 C compiler: gcc (redhat, x86_64, 13.3.1)
 Garbage collector: Serial GC (max heap size: 80% of RAM)
[2/8] Performing analysis...  [***]                                                                     (16.4s @ 0.38GB)
   3,893 (77.15%) of  5,046 types reachable
   4,889 (52.37%) of  9,335 fields reachable
  17,847 (47.53%) of 37,545 methods reachable
   1,138 types,    18 fields, and   532 methods registered for reflection
      59 types,    61 fields, and    52 methods registered for JNI access
       4 native libraries: dl, pthread, rt, z
[3/8] Building universe...                                                                               (3.4s @ 0.33GB)
[4/8] Parsing methods...      [*]                                                                        (1.6s @ 0.48GB)
[5/8] Inlining methods...     [***]                                                                      (1.1s @ 0.47GB)
[6/8] Compiling methods...    [****]                                                                    (15.8s @ 0.49GB)
[7/8] Layouting methods...    [*]                                                                        (1.8s @ 0.56GB)
[8/8] Creating image...       [**]                                                                       (3.1s @ 0.60GB)
   6.25MB (36.98%) for code area:    10,129 compilation units
   9.59MB (56.70%) for image heap:  130,948 objects and 5 resources
   1.07MB ( 6.31%) for other data
  16.91MB in total
------------------------------------------------------------------------------------------------------------------------
Top 10 origins of code area:                                Top 10 object types in image heap:
   4.20MB java.base                                            1.41MB byte[] for code metadata
1003.22kB svm.jar (Native Image)                               1.20MB java.lang.String
 630.03kB jdk.jfr                                              1.03MB byte[] for general heap data
 113.35kB java.logging                                       923.59kB byte[] for java.lang.String
  93.69kB jdk.proxy1                                         894.04kB java.lang.Class
  67.26kB org.graalvm.nativeimage.base                       334.55kB com.oracle.svm.core.hub.DynamicHubCompanion
  45.13kB jdk.proxy3                                         314.11kB java.util.HashMap$Node
  24.15kB jdk.internal.vm.ci                                 244.58kB java.lang.Object[]
  23.72kB org.graalvm.sdk                                    237.88kB java.lang.String[]
  11.42kB jdk.proxy2                                         167.11kB java.util.concurrent.ConcurrentHashMap$Node
  14.40kB for 5 more packages                                  2.21MB for 1117 more object types
------------------------------------------------------------------------------------------------------------------------
Recommendations:
 HEAP: Set max heap for improved and more predictable memory usage.
 CPU:  Enable more CPU features with '-march=native' for improved performance.
------------------------------------------------------------------------------------------------------------------------
                        1.0s (2.2% of total time) in 137 GCs | Peak RSS: 1.05GB | CPU load: 9.59
------------------------------------------------------------------------------------------------------------------------
Produced artifacts:
 /disk/graal/upstream-sources/mandrel-integration-tests/apps/debug-symbols-smoke/target/debug-symbols-smoke (executable)
========================================================================================================================
Finished generating 'debug-symbols-smoke' in 46.2s.
2024-07-15 16:43:41.374 INFO  [o.g.t.i.JFRTest] (jfrSmoke) Running JVM mode...
2024-07-15 16:43:42.378 INFO  [o.g.t.i.u.Commands] (runCommand) Command: [java, -jar, ./target/debug-symbols-smoke.jar]
2024-07-15 16:43:45.685 INFO  [o.g.t.i.JFRTest] (jfrSmoke) Running JVM JFR mode...
2024-07-15 16:43:46.687 INFO  [o.g.t.i.u.Commands] (runCommand) Command: [java, -XX:StartFlightRecording=filename=logs/flight-java.jfr, -Xlog:jfr, -jar, ./target/debug-symbols-smoke.jar]
2024-07-15 16:43:50.527 INFO  [o.g.t.i.JFRTest] (jfrSmoke) Running Native mode...
2024-07-15 16:43:50.528 INFO  [o.g.t.i.u.Commands] (runCommand) Command: [./target/debug-symbols-smoke]
2024-07-15 16:43:57.796 INFO  [o.g.t.i.JFRTest] (jfrSmoke) Running Native mode JFR...
2024-07-15 16:43:58.799 INFO  [o.g.t.i.u.Commands] (runCommand) Command: [./target/debug-symbols-smoke, -XX:+FlightRecorder, -XX:StartFlightRecording=filename=logs/flight-native.jfr, -XX:FlightRecorderLogging=jfr]
2024-07-15 16:44:06.519 INFO  [o.g.t.i.u.Commands] (pidKiller) Killing PID: 69598, forcefully: false
2024-07-15 16:44:06.542 INFO  [o.g.t.i.u.Logs] (logMeasurements) 
App,timeToFinishMs
JFR_SMOKE_JVM,4311
2024-07-15 16:44:06.542 INFO  [o.g.t.i.u.Logs] (logMeasurements) 
App,timeToFinishMs
JFR_SMOKE_NATIVE,7269
2024-07-15 16:44:06.542 INFO  [o.g.t.i.u.Logs] (logMeasurements) 
App,timeToFinishMs
JFR_SMOKE_JVM_JFR,4842
2024-07-15 16:44:06.543 INFO  [o.g.t.i.u.Logs] (logMeasurements) 
App,timeToFinishMs
JFR_SMOKE_NATIVE_JFR,8704
2024-07-15 16:44:06.555 INFO  [o.g.t.i.u.Commands] (pidKiller) Killing PID: 69598, forcefully: true
[INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 75.718 s - in org.graalvm.tests.integration.JFRTest
[INFO] 
[INFO] Results:
[INFO] 
[INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0
[INFO] 
[INFO] 
[INFO] --- jar:3.3.0:jar (default-jar) @ testsuite ---
[INFO] Building jar: /disk/graal/upstream-sources/mandrel-integration-tests/testsuite/target/testsuite-1.0.0-SNAPSHOT.jar
[INFO] 
[INFO] --- failsafe:2.22.2:integration-test (default) @ testsuite ---
[WARNING] Parameter 'localRepository' is deprecated core expression; Avoid use of ArtifactRepository type. If you need access to local repository, switch to '${repositorySystemSession}' expression and get LRM from it instead.
[INFO] 
[INFO] --- failsafe:2.22.2:verify (default) @ testsuite ---
[INFO] ------------------------------------------------------------------------
[INFO] Reactor Summary for Native image integration TS 1.0.0-SNAPSHOT:
[INFO] 
[INFO] Native image integration TS ........................ SUCCESS [  0.127 s]
[INFO] testsuite .......................................... SUCCESS [01:19 min]
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time:  01:19 min
[INFO] Finished at: 2024-07-15T16:44:07+02:00
[INFO] ------------------------------------------------------------------------
zakkak commented 3 weeks ago

It looks like this will need a backport of oracle/graal#6751. That took way longer than needed to figure that out. Anyway, working on it now.

Too bad it didn't ring any bells to me :/

jerboaa commented 2 weeks ago

Issue is closed with https://github.com/graalvm/mandrel/pull/768