Graal: UnsupportedFeatureException with Micronaut and Hibernate/JPA

[ilopmar]

I'm trying to build a native-image for a Micronaut application that uses Hiberate/JPA and the generation of the native image fails.

To reproduce the issue:

• git clone https://github.com/micronaut-graal-tests/micronaut-hibernate-graal
• cd micronaut-hibernate-graal
• Use Graal from master branch (currently rc15-dev)
• ./build-native-image.sh

Error:

[hibernate-graal:652]    classlist:  10,221.09 ms
[hibernate-graal:652]        (cap):   1,926.96 ms
[hibernate-graal:652]        setup:   4,015.99 ms
Warning: class initialization of class org.apache.commons.logging.LogAdapter$Log4jLog failed with exception java.lang.NoClassDefFoundError: org/apache/logging/log4j/LogManager. This class will be initialized at run time because either option --report-unsupported-elements-at-runtime or option --allow-incomplete-classpath is used for image building. Use the option --delay-class-initialization-to-runtime=org.apache.commons.logging.LogAdapter$Log4jLog to explicitly request delayed initialization of this class.
12:29:08.791 [ForkJoinPool-2-worker-2] INFO  org.hibernate.Version - HHH000412: Hibernate Core {[WORKING]}
12:29:08.795 [ForkJoinPool-2-worker-2] INFO  org.hibernate.cfg.Environment - HHH000206: hibernate.properties not found
12:29:16.879 [ForkJoinPool-2-worker-1] INFO  o.h.annotations.common.Version - HCANN000001: Hibernate Commons Annotations {5.1.0.Final}
Warning: class initialization of class org.hibernate.secure.internal.StandardJaccServiceImpl failed with exception java.lang.NoClassDefFoundError: javax/security/jacc/EJBMethodPermission. This class will be initialized at run time because either option --report-unsupported-elements-at-runtime or option --allow-incomplete-classpath is used for image building. Use the option --delay-class-initialization-to-runtime=org.hibernate.secure.internal.StandardJaccServiceImpl to explicitly request delayed initialization of this class.
Warning: class initialization of class org.h2.value.ValueGeometry failed with exception java.lang.NoClassDefFoundError: com/vividsolutions/jts/geom/CoordinateSequenceFilter. This class will be initialized at run time because either option --report-unsupported-elements-at-runtime or option --allow-incomplete-classpath is used for image building. Use the option --delay-class-initialization-to-runtime=org.h2.value.ValueGeometry to explicitly request delayed initialization of this class.
[hibernate-graal:652]     analysis: 151,021.07 ms
Warning: Abort stand-alone image build. unsupported features in 3 methods
Detailed message:
Error: No instances are allowed in the image heap for a class that is initialized or reinitialized at image runtime: java.util.logging.SimpleFormatter
Trace:  object java.util.logging.ConsoleHandler
    object java.lang.Object[]
    object java.util.concurrent.CopyOnWriteArrayList
    object java.util.logging.LogManager$RootLogger
    object java.util.logging.LogManager
    method java.util.logging.LogManager.access$100()
Call path from entry point to java.util.logging.LogManager.access$100(): 
    at java.util.logging.LogManager.access$100(LogManager.java:145)
    at java.util.logging.LogManager$LoggerContext.requiresDefaultLoggers(LogManager.java:637)
    at java.util.logging.LogManager$LoggerContext.addLocalLogger(LogManager.java:758)
    at java.util.logging.LogManager.addLogger(LogManager.java:1162)
    at java.util.logging.LogManager$2.run(LogManager.java:349)
    at com.oracle.svm.core.jdk.Target_java_security_AccessController.doPrivileged(SecuritySubstitutions.java:63)
    at javax.security.auth.Subject$SecureSet.contains(Subject.java:1190)
    at java.util.AbstractCollection.containsAll(AbstractCollection.java:318)
    at java.util.JumboEnumSet.containsAll(JumboEnumSet.java:251)
    at com.oracle.svm.core.amd64.AMD64CPUFeatureAccess.verifyHostSupportsArchitecture(AMD64CPUFeatureAccess.java:172)
    at com.oracle.svm.core.JavaMainWrapper.run(JavaMainWrapper.java:131)
    at com.oracle.svm.core.code.IsolateEnterStub.JavaMainWrapper_run_5087f5482cc9a6abc971913ece43acb471d2631b(generated:0)
Error: com.oracle.graal.pointsto.constraints.UnsupportedFeatureException: Detected a direct/mapped ByteBuffer in the image heap. A direct ByteBuffer has a pointer to unmanaged C memory, and C memory from the image generator is not available at image run time. A mapped ByteBuffer references a file descriptor, which is no longer open and mapped at run time. The object was probably created by a class initializer and is reachable from a static field. By default, all class initialization is done during native image building.You can manually delay class initialization to image run time by using the option --delay-class-initialization-to-runtime=<class-name>. Or you can write your own initialization methods and call them explicitly from your main entry point.
Trace: 
    at parsing org.h2.store.fs.FileNioMemData.changeLength(FilePathNioMem.java:685)
Call path from entry point to org.h2.store.fs.FileNioMemData.changeLength(long): 
    at org.h2.store.fs.FileNioMemData.changeLength(FilePathNioMem.java:677)
    at org.h2.store.fs.FileNioMemData.readWrite(FilePathNioMem.java:712)
    at org.h2.store.fs.FileNioMem.write(FilePathNioMem.java:324)
    at org.h2.store.fs.FileUtils.writeFully(FileUtils.java:372)
    at org.h2.store.fs.FileChannelOutputStream.write(FileChannelOutputStream.java:51)
    at java.util.zip.DeflaterOutputStream.flush(DeflaterOutputStream.java:277)
    at java.io.PrintStream.newLine(PrintStream.java:548)
    at java.io.PrintStream.println(PrintStream.java:807)
    at com.oracle.svm.jni.functions.JNIFunctions.ExceptionDescribe(JNIFunctions.java:757)
    at com.oracle.svm.core.code.IsolateEnterStub.JNIFunctions_ExceptionDescribe_b5412f7570bccae90b000bc37855f00408b2ad73(generated:0)
Error: com.oracle.graal.pointsto.constraints.UnsupportedFeatureException: Detected a direct/mapped ByteBuffer in the image heap. A direct ByteBuffer has a pointer to unmanaged C memory, and C memory from the image generator is not available at image run time. A mapped ByteBuffer references a file descriptor, which is no longer open and mapped at run time. The object was probably created by a class initializer and is reachable from a static field. By default, all class initialization is done during native image building.You can manually delay class initialization to image run time by using the option --delay-class-initialization-to-runtime=<class-name>. Or you can write your own initialization methods and call them explicitly from your main entry point.
Trace: 
    at parsing org.h2.store.fs.FileNioMemData.expandPage(FilePathNioMem.java:600)
Call path from entry point to org.h2.store.fs.FileNioMemData.expandPage(int): 
    at org.h2.store.fs.FileNioMemData.expandPage(FilePathNioMem.java:590)
    at org.h2.store.fs.FileNioMemData.readWrite(FilePathNioMem.java:720)
    at org.h2.store.fs.FileNioMem.write(FilePathNioMem.java:324)
    at org.h2.store.fs.FileUtils.writeFully(FileUtils.java:372)
    at org.h2.store.fs.FileChannelOutputStream.write(FileChannelOutputStream.java:51)
    at java.util.zip.DeflaterOutputStream.flush(DeflaterOutputStream.java:277)
    at java.io.PrintStream.newLine(PrintStream.java:548)
    at java.io.PrintStream.println(PrintStream.java:807)
    at com.oracle.svm.jni.functions.JNIFunctions.ExceptionDescribe(JNIFunctions.java:757)
    at com.oracle.svm.core.code.IsolateEnterStub.JNIFunctions_ExceptionDescribe_b5412f7570bccae90b000bc37855f00408b2ad73(generated:0)

Build on Server(pid: 24836, port: 38209)
[hibernate-graal:24836]    classlist:     212.25 ms
[hibernate-graal:24836]        (cap):   1,163.67 ms
[hibernate-graal:24836]        setup:   1,609.30 ms
[hibernate-graal:24836]   (typeflow):   2,139.16 ms
[hibernate-graal:24836]    (objects):     652.98 ms
[hibernate-graal:24836]   (features):     136.97 ms
[hibernate-graal:24836]     analysis:   3,021.49 ms
[hibernate-graal:24836]     universe:     318.95 ms
[hibernate-graal:24836]      (parse):     313.88 ms
[hibernate-graal:24836]     (inline):     804.67 ms
[hibernate-graal:24836]    (compile):   2,564.03 ms
[hibernate-graal:24836]      compile:   3,988.95 ms
[hibernate-graal:24836]        image:     222.97 ms
[hibernate-graal:24836]        write:      82.31 ms
[hibernate-graal:24836]      [total]:   9,539.04 ms
Warning: Image 'hibernate-graal' is a fallback-image

When the native-image generation fails the process continues and it is able to generate a native-image in "fallback mode" but I'm not sure what is this.

Starting that fallback image works but it takes more time that running the app on the JVM.

[graemerocher]

Doesn't seem related to Hibernate, but to h2 in-memory database

[ilopmar]

As Graeme mentioned it seems related to H2. I've switched to Mysql (the changes are in branch mysql) and the error is:

[hibernate-graal:10785]    classlist:  10,919.22 ms
[hibernate-graal:10785]        (cap):   2,235.37 ms
[hibernate-graal:10785]        setup:   4,976.62 ms
Warning: class initialization of class org.apache.commons.logging.LogAdapter$Log4jLog failed with exception java.lang.NoClassDefFoundError: org/apache/logging/log4j/LogManager. This class will be initialized at run time because either option --report-unsupported-elements-at-runtime or option --allow-incomplete-classpath is used for image building. Use the option --delay-class-initialization-to-runtime=org.apache.commons.logging.LogAdapter$Log4jLog to explicitly request delayed initialization of this class.
12:08:45.796 [ForkJoinPool-2-worker-2] INFO  org.hibernate.Version - HHH000412: Hibernate Core {[WORKING]}
12:08:45.802 [ForkJoinPool-2-worker-2] INFO  org.hibernate.cfg.Environment - HHH000206: hibernate.properties not found
12:08:53.007 [ForkJoinPool-2-worker-3] INFO  o.h.annotations.common.Version - HCANN000001: Hibernate Commons Annotations {5.1.0.Final}
Warning: class initialization of class org.hibernate.secure.internal.StandardJaccServiceImpl failed with exception java.lang.NoClassDefFoundError: javax/security/jacc/EJBMethodPermission. This class will be initialized at run time because either option --report-unsupported-elements-at-runtime or option --allow-incomplete-classpath is used for image building. Use the option --delay-class-initialization-to-runtime=org.hibernate.secure.internal.StandardJaccServiceImpl to explicitly request delayed initialization of this class.
[hibernate-graal:10785]     analysis:  93,460.94 ms
Warning: Abort stand-alone image build. No instances are allowed in the image heap for a class that is initialized or reinitialized at image runtime: java.util.logging.SimpleFormatter
Detailed message:
Trace:  object java.util.logging.ConsoleHandler
    object java.lang.Object[]
    object java.util.concurrent.CopyOnWriteArrayList
    object java.util.logging.LogManager$RootLogger
    object java.util.logging.Logger
    method java.util.logging.LogManager$2.run()
Call path from entry point to java.util.logging.LogManager$2.run(): 
    at java.util.logging.LogManager$2.run(LogManager.java:341)
    at com.oracle.svm.core.jdk.Target_java_security_AccessController.doPrivileged(SecuritySubstitutions.java:63)
    at javax.security.auth.Subject$SecureSet.contains(Subject.java:1190)
    at java.util.AbstractCollection.containsAll(AbstractCollection.java:318)
    at java.util.JumboEnumSet.containsAll(JumboEnumSet.java:251)
    at com.oracle.svm.core.amd64.AMD64CPUFeatureAccess.verifyHostSupportsArchitecture(AMD64CPUFeatureAccess.java:172)
    at com.oracle.svm.core.JavaMainWrapper.run(JavaMainWrapper.java:131)
    at com.oracle.svm.core.code.IsolateEnterStub.JavaMainWrapper_run_5087f5482cc9a6abc971913ece43acb471d2631b(generated:0)

Build on Server(pid: 7450, port: 39753)
[hibernate-graal:7450]    classlist:     354.14 ms
[hibernate-graal:7450]        (cap):   1,369.75 ms
[hibernate-graal:7450]        setup:   2,467.06 ms
[hibernate-graal:7450]   (typeflow):   2,555.56 ms
[hibernate-graal:7450]    (objects):     806.56 ms
[hibernate-graal:7450]   (features):     115.32 ms
[hibernate-graal:7450]     analysis:   3,575.03 ms
[hibernate-graal:7450]     universe:     433.87 ms
[hibernate-graal:7450]      (parse):     433.10 ms
[hibernate-graal:7450]     (inline):   1,150.11 ms
[hibernate-graal:7450]    (compile):   3,611.63 ms
[hibernate-graal:7450]      compile:   5,690.36 ms
[hibernate-graal:7450]        image:     414.36 ms
[hibernate-graal:7450]        write:     349.99 ms
[hibernate-graal:7450]      [total]:  13,450.37 ms
Warning: Image 'hibernate-graal' is a fallback-image

[maffelbaffel]

As a workaround for the error that having a java.util.logging.SimpleFormatter instances on the heap with a ConsoleHandler is not allowed I did the following:

Create a logging Handler class which just forwards log calls to System.out:

public class SoutHandler extends Handler {

    @Override
    public void publish(final LogRecord record) {
        System.out.println(record.getMessage());
    }

    @Override
    public void flush() {
    }

    @Override
    public void close() throws SecurityException {
    }
}

I then register this class as logging Handler in a static fashion in my main class:

public class Application {
    static {
        LogManager.getLogManager().reset();
        final Logger rootLogger = LogManager.getLogManager().getLogger("");
        rootLogger.addHandler(new SoutHandler());
    }

    public static void main(String[] args) {
        ...
    }
}

This way, all logging calls while building the native-image get redirected to System.out.
Before starting the application I then set logging up correctly:

public static void main(String[] args) {
        try {
            LogManager.getLogManager().readConfiguration(Application.class.getClassLoader().getResourceAsStream("logging.properties"));

            Micronaut.run(Application.class);
            // Logger can be used here
            Logger.getLogger(Application.class.getSimpleName()).info("app started.");
        } catch (final IOException e) {
            e.printStackTrace();
        }
    }

[cstancu]

The No instances are allowed in the image heap for a class that is initialized or reinitialized at image runtime: java.util.logging.SimpleFormatter issue was fixed by https://github.com/oracle/graal/commit/73544249ffd462d6b81ba10ac6233d914b7fb064. The fix will be part of RC16.

[ilopmar]

Yeah, it works now! :tada: