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

JFRTest.jfrOptionsSmokeTest fails with latest Mandrel #126

Closed zakkak closed 1 year ago

zakkak commented 1 year ago
Error:  Tests run: 2, Failures: 2, Errors: 0, Skipped: 0, Time elapsed: 267.796 s <<< FAILURE! - in org.graalvm.tests.integration.JFRTest
Error:  jfrOptionsSmokeTest{TestInfo}  Time elapsed: 121.794 s  <<< FAILURE!
org.opentest4j.AssertionFailedError: 
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(23093) ==> expected: <true> but was: <false>
    at org.graalvm.tests.integration.JFRTest.jfrOptionsSmoke(JFRTest.java:331)
    at org.graalvm.tests.integration.JFRTest.jfrOptionsSmokeTest(JFRTest.java:193)

Error:  jfrSmokeTest{TestInfo}  Time elapsed: 146.001 s  <<< FAILURE!
org.opentest4j.AssertionFailedError: 
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(23143) ==> expected: <true> but was: <false>
    at org.graalvm.tests.integration.JFRTest.jfrSmoke(JFRTest.java:171)
    at org.graalvm.tests.integration.JFRTest.jfrSmokeTest(JFRTest.java:107)

See https://github.com/graalvm/mandrel/actions/runs/3415845243/jobs/5688146241#step:10:10111

zakkak commented 1 year ago

This started happening with the transition from 17.0.5-beta+8-202211012300 to 17.0.6-beta+1-202211032300

@roberttoyonaga do you know if this is expected or not? The warning is:

[warn][jfr,system] Exception occurred during execution of period hook for jdk.ContainerConfiguration(23357)
jerboaa commented 1 year ago

Yes, one needs to have JDK 17.0.6+1 with a graal master build in order to reproduce. build-and-run.log looks like this:

[...]
Command: native-image --enable-monitoring -jar target/debug-symbols-smoke.jar target/debug-symbols-smoke
========================================================================================================================
GraalVM Native Image: Generating 'target/debug-symbols-smoke' (executable)...
========================================================================================================================
[1/7] Initializing...                                                                                    (4.8s @ 0.23GB)
 Version info: 'GraalVM 23.0.0-dev Java 17 Mandrel Distribution'
 Java version info: '17.0.6-beta+1-202211032300'
 C compiler: gcc (redhat, x86_64, 12.2.1)
 Garbage collector: Serial GC
[2/7] Performing analysis...  [*****]                                                                   (34.9s @ 1.18GB)
   3,938 (78.48%) of  5,018 types reachable
   4,870 (52.71%) of  9,240 fields reachable
  17,590 (47.35%) of 37,146 methods reachable
      43 types,    11 fields, and   484 methods registered for reflection
      59 types,    59 fields, and    52 methods registered for JNI access
       4 native libraries: dl, pthread, rt, z
[3/7] Building universe...                                                                               (3.5s @ 0.37GB)
[4/7] Parsing methods...      [**]                                                                       (2.9s @ 1.48GB)
[5/7] Inlining methods...     [***]                                                                      (2.0s @ 2.14GB)
[6/7] Compiling methods...    [*****]                                                                   (21.1s @ 1.20GB)
[7/7] Creating image...                                                                                  (4.9s @ 1.92GB)
   5.95MB (35.05%) for code area:     9,947 compilation units
  10.74MB (63.32%) for image heap:  144,647 objects and 5 resources
 283.36KB ( 1.63%) for other data
  16.97MB in total
------------------------------------------------------------------------------------------------------------------------
Top 10 packages in code area:                               Top 10 object types in image heap:
 764.38KB java.util                                            1.40MB byte[] for code metadata
 381.44KB java.lang                                            1.28MB java.lang.String
 340.12KB jdk.jfr.internal                                     1.24MB byte[] for general heap data
 273.05KB java.text                                          895.33KB java.lang.Class
 235.68KB java.util.concurrent                               855.80KB byte[] for java.lang.String
 224.53KB java.util.regex                                    463.31KB java.util.HashMap$Node
 165.91KB java.lang.invoke                                   338.42KB com.oracle.svm.core.hub.DynamicHubCompanion
 163.59KB java.math                                          260.97KB java.util.HashMap$Node[]
 137.03KB jdk.jfr.internal.consumer                          252.14KB java.util.concurrent.ConcurrentHashMap$Node
 130.66KB com.oracle.svm.core.genscavenge                    230.85KB java.lang.String[]
   3.12MB for 170 more packages                                2.57MB for 1130 more object types
------------------------------------------------------------------------------------------------------------------------
                        1.0s (1.3% of total time) in 19 GCs | Peak RSS: 4.74GB | CPU load: 9.14
------------------------------------------------------------------------------------------------------------------------
Produced artifacts:
 /disk/graal/upstream-sources/mandrel-integration-tests/apps/debug-symbols-smoke/target/debug-symbols-smoke (executable)
 /disk/graal/upstream-sources/mandrel-integration-tests/apps/debug-symbols-smoke/target/debug-symbols-smoke.build_artifacts.txt (txt)
========================================================================================================================
Finished generating 'target/debug-symbols-smoke' in 1m 16s.
[0.597s][info][jfr] Flight Recorder initialized
[0.597s][info][jfr] Repository base directory: /tmp
[0.682s][info][jfr] Started recording "1" (1) {dumponexit=true, filename=/disk/graal/upstream-sources/mandrel-integration-tests/apps/debug-symbols-smoke/logs/flight-java.jfr}
[0.682s][info][jfr,startup] Started recording 1. No limit specified, using maxsize=250MB as default.
[0.682s][info][jfr,startup] 
[0.682s][info][jfr,startup] Use jcmd 16761 JFR.dump name=1 to copy recording data to file.
Q to quit
b6951775b0375ea13fc977581e54eb36d483e95ed3bc1e62fcb8da59830f1ef9
[5.189s][info][jfr        ] Stopped recording "1" (1). Reason "Dump on exit".
[5.192s][info][jfr        ] Transferred 366905 bytes from the disk repository
[5.213s][info][jfr        ] Wrote recording "1" (1) to /disk/graal/upstream-sources/mandrel-integration-tests/apps/debug-symbols-smoke/logs/flight-java.jfr
[5.214s][info][jfr        ] Closed recording "1" (1)
[5.215s][info][jfr        ] Removed repository /tmp/2022_11_08_10_51_37_16761
[info][jfr] Added periodic hook for EveryChunkPeriodEvents(12319)
[info][jfr] Added periodic hook for EndChunkPeriodEvents(12322)
[info][jfr] Flight Recorder initialized
[info][jfr] Repository base directory: /tmp
[warn][jfr,system] Exception occurred during execution of period hook for jdk.ContainerConfiguration(23517)
[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
b6951775b0375ea13fc977581e54eb36d483e95ed3bc1e62fcb8da59830f1ef9
[info][jfr       ] Stopped recording "1" (1). Reason "Dump on exit".
[info][jfr       ] Transferred 150472 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/2022_11_08_10_51_43_16828
jerboaa commented 1 year ago

I've instrumented a JVM build with:

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 49aa2bcd3f2..8a0208f6eff 100644
--- a/src/jdk.jfr/share/classes/jdk/jfr/internal/RequestEngine.java
+++ b/src/jdk.jfr/share/classes/jdk/jfr/internal/RequestEngine.java
@@ -76,6 +76,7 @@ public final class RequestEngine {
                     executeSecure();
                 }
             } catch (Throwable e) {
+                e.printStackTrace();
                 // Prevent malicious user to propagate exception callback in the wrong context
                 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());
                     }

And I got this trace when running in native mode:

java.lang.UnsatisfiedLinkError: jdk.internal.platform.CgroupMetrics.getTotalMemorySize0()J [symbol: Java_jdk_internal_platform_CgroupMetrics_getTotalMemorySize0 or Java_jdk_internal_platform_CgroupMetrics_getTotalMemorySize0__]
    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.5-internal/jdk.internal.platform.CgroupMetrics.getTotalMemorySize0(CgroupMetrics.java)
    at java.base@17.0.5-internal/jdk.internal.platform.CgroupMetrics.getMemoryLimit(CgroupMetrics.java:127)
    at jdk.jfr@17.0.5-internal/jdk.jfr.internal.instrument.JDKEvents.emitContainerConfiguration(JDKEvents.java:191)
    at jdk.jfr@17.0.5-internal/jdk.jfr.internal.RequestEngine$RequestHook.execute(RequestEngine.java:68)
    at jdk.jfr@17.0.5-internal/jdk.jfr.internal.RequestEngine.doChunk(RequestEngine.java:188)
    at jdk.jfr@17.0.5-internal/jdk.jfr.internal.RequestEngine.doChunkBegin(RequestEngine.java:181)
    at jdk.jfr@17.0.5-internal/jdk.jfr.internal.PlatformRecorder.start(PlatformRecorder.java:287)
    at jdk.jfr@17.0.5-internal/jdk.jfr.internal.PlatformRecording.start(PlatformRecording.java:120)
    at jdk.jfr@17.0.5-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:147)
    at org.graalvm.nativeimage.builder/com.oracle.svm.core.jdk.RuntimeSupport.initialize(RuntimeSupport.java:92)
    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(23389)
jerboaa commented 1 year ago

I'll get an upstream graal issue filed for this. It's caused by JDK-8292541 which is new in 17.0.6+1.

jerboaa commented 1 year ago

I'll get an upstream graal issue filed for this. It's caused by JDK-8292541 which is new in 17.0.6+1.

https://github.com/oracle/graal/issues/5387 is the upstream issue.

jerboaa commented 1 year ago

Fixed upstream. Closing.