Building native-image with Micronaut Data JDBC, Oracle and JDK11 uses more memory than before

[ilopmar]

Describe GraalVM and your environment:

• GraalVM version or commit id if built from source: 351f064
• CE or EE: CE
• Build Time or run time failure: build time
• JDK version: JDK11

Have you verified this issue still happens when using the latest snapshot?
Yes, trying with master branch.

Describe the issue
I've noticed that starting on commit 351f064c8d62989bb4592a3e4928c782e4bbe212 it seems that building native images with jdk 11 takes more memory than before.
Our Micronaut test application for Micronaut Data JDBC and Oracle has started to fail consistently after the mentioned commit with OOM exceptions.
The last successful build was with the commit d0421f791a1f24626729b90cc21b309780675dc1.

As you know we use Gitlab CI for the testing and it has some memory constraints but at to this point everything has worked.

Please also keep in mind that this works properly with JDK8.

Steps to reproduce the issue

This is how to reproduce the issue, but keep in mind that only happens because of the memory constraints of Gitlab CI. I was able to build it on my laptop and everything works without issues.

• git clone https://github.com/micronaut-graal-tests/micronaut-data-jdbc-graal
• cd micronaut-data-jdbc-graal
• git checkout oracle
• Use latest GraalVM JDK11 from master branch.
• ./build-native-image.sh

Expected behavior

It should be possible to generate the native image.

Additional context

This is the job detail of the failure: https://gitlab.com/micronaut-projects/micronaut-graal-tests/-/jobs/432151581

The error also points to Fatal error: com.oracle.graal.pointsto.util.AnalysisError$ParsingError: Error encountered while parsing oracle.jdbc.driver.OracleSqlReadOnly.<clinit>() but I'm not really sure if it's related to this or just happened while processing this class.

Details

 Fatal error: com.oracle.graal.pointsto.util.AnalysisError$ParsingError: Error encountered while parsing oracle.jdbc.driver.OracleSqlReadOnly.<clinit>() 
 Parsing context: <no parsing context available> 
 	at com.oracle.graal.pointsto.util.AnalysisError.parsingError(AnalysisError.java:138)
 	at com.oracle.graal.pointsto.flow.MethodTypeFlow.doParse(MethodTypeFlow.java:327)
 	at com.oracle.graal.pointsto.flow.MethodTypeFlow.ensureParsed(MethodTypeFlow.java:300)
 	at com.oracle.graal.pointsto.flow.MethodTypeFlow.addContext(MethodTypeFlow.java:107)
 	at com.oracle.graal.pointsto.BigBang$1.run(BigBang.java:385)
 	at com.oracle.graal.pointsto.util.CompletionExecutor.lambda$execute$0(CompletionExecutor.java:171)
 	at java.base/java.util.concurrent.ForkJoinTask$RunnableExecuteAction.exec(ForkJoinTask.java:1426)
 	at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290)
 	at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1020)
 	at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1656)
 	at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1594)
 	at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:177)
 Caused by: java.lang.OutOfMemoryError: GC overhead limit exceeded
 	at java.base/java.util.HashMap.newNode(HashMap.java:1797)
 	at java.base/java.util.HashMap.putVal(HashMap.java:637)
 	at java.base/java.util.HashMap.putMapEntries(HashMap.java:510)
 	at java.base/java.util.HashMap.<init>(HashMap.java:485)
 	at com.oracle.graal.pointsto.flow.MethodTypeFlowBuilder$TypeFlowsOfNodes.<init>(MethodTypeFlowBuilder.java:470)
 	at com.oracle.graal.pointsto.flow.MethodTypeFlowBuilder$TypeFlowsOfNodes.clone(MethodTypeFlowBuilder.java:577)
 	at com.oracle.graal.pointsto.flow.MethodTypeFlowBuilder$TypeFlowsOfNodes.clone(MethodTypeFlowBuilder.java:461)
 	at jdk.internal.vm.compiler/org.graalvm.compiler.phases.graph.PostOrderNodeIterator.nextQueuedNode(PostOrderNodeIterator.java:165)
 	at jdk.internal.vm.compiler/org.graalvm.compiler.phases.graph.PostOrderNodeIterator.apply(PostOrderNodeIterator.java:118)
 	at com.oracle.graal.pointsto.flow.MethodTypeFlowBuilder.apply(MethodTypeFlowBuilder.java:421)
 	at com.oracle.graal.pointsto.flow.MethodTypeFlow.doParse(MethodTypeFlow.java:310)
 	at com.oracle.graal.pointsto.flow.MethodTypeFlow.ensureParsed(MethodTypeFlow.java:300)
 	at com.oracle.graal.pointsto.flow.MethodTypeFlow.addContext(MethodTypeFlow.java:107)
 	at com.oracle.graal.pointsto.BigBang$1.run(BigBang.java:385)
 	at com.oracle.graal.pointsto.util.CompletionExecutor.lambda$execute$0(CompletionExecutor.java:171)
 	at com.oracle.graal.pointsto.util.CompletionExecutor$$Lambda$347/0x00000007c17d5c40.run(Unknown Source)
 	... 6 more

[ilopmar]

Just a little bit more of information. This is the first commit in which I've seen it fail on CI: 5751bb15989ec55126c7dcd83cd697490216d14a

https://gitlab.com/micronaut-projects/micronaut-graal-tests/pipelines/116467455

[cstancu]

@pejovica it looks like turning on the ParallelGC for Native Image in 5751bb1 generation increases memory usage on JDK 11.

@ilopmar In 92d44c1 we merged a feature that improves the Native Image analysis performance: it significantly reduces both memory footprint and analysis time at the cost of a slight accuracy loss. This feature will be part of the 20.1.0 release but it is disabled by default; it can be enabled using -H:+RemoveSaturatedTypeFlows. The reduced analysis accuracy means that the number of methods/types included in the image can increase. You can print these numbers with -H:+PrintAnalysisStatistics. Please try it and report any bugs. The plan is to turn the feature on by default as soon as we make sure it doesn't negativelly impact downstream projects.

[ilopmar]

@cstancu Thanks for the explanation. I've been doing some tests with the same test application and this is the output.

Tests only with -H:+PrintAnalysisStatistics

Take 1

[mn-data-jdbc-graal-oracle:8468]    classlist:   7,669.82 ms,  0.96 GB
[mn-data-jdbc-graal-oracle:8468]        (cap):   1,007.16 ms,  0.94 GB
[mn-data-jdbc-graal-oracle:8468]        setup:   2,608.56 ms,  0.94 GB
[mn-data-jdbc-graal-oracle:8468]     (clinit):   1,854.57 ms,  5.17 GB
[mn-data-jdbc-graal-oracle:8468]   (typeflow):  67,829.72 ms,  5.17 GB
[mn-data-jdbc-graal-oracle:8468]    (objects):  56,434.85 ms,  5.17 GB
[mn-data-jdbc-graal-oracle:8468]   (features):   4,966.50 ms,  5.17 GB
[mn-data-jdbc-graal-oracle:8468]     analysis: 138,768.90 ms,  5.17 GB
[mn-data-jdbc-graal-oracle:8468]     universe:   3,651.27 ms,  5.09 GB
[mn-data-jdbc-graal-oracle:8468]      (parse):  10,360.48 ms,  5.09 GB
[mn-data-jdbc-graal-oracle:8468]     (inline):  12,753.66 ms,  5.54 GB
[mn-data-jdbc-graal-oracle:8468]    (compile):  92,289.71 ms,  6.29 GB
[mn-data-jdbc-graal-oracle:8468]      compile: 119,718.96 ms,  6.29 GB
[mn-data-jdbc-graal-oracle:8468]        image:   8,878.59 ms,  6.38 GB
[mn-data-jdbc-graal-oracle:8468]        write:   1,208.98 ms,  6.38 GB
[mn-data-jdbc-graal-oracle:8468]      [total]: 282,968.56 ms,  6.38 GB

Analysis Results Statistics
Total reachable types             13606 
App reachable types                7357 
Total reachable methods           87936 
App reachable methods             44509 
Total type checks                 25159 
Total removable type checks        6024 
App type checks                   15309 
App removable type checks          3535 

Image size: 81861752

Take 2

[mn-data-jdbc-graal-oracle:13561]    classlist:   6,707.61 ms,  0.96 GB
[mn-data-jdbc-graal-oracle:13561]        (cap):     742.85 ms,  0.96 GB
[mn-data-jdbc-graal-oracle:13561]        setup:   2,444.75 ms,  0.96 GB
[mn-data-jdbc-graal-oracle:13561]     (clinit):   2,546.53 ms,  5.20 GB
[mn-data-jdbc-graal-oracle:13561]   (typeflow):  72,218.60 ms,  5.20 GB
[mn-data-jdbc-graal-oracle:13561]    (objects):  59,486.29 ms,  5.20 GB
[mn-data-jdbc-graal-oracle:13561]   (features):   5,048.58 ms,  5.20 GB
[mn-data-jdbc-graal-oracle:13561]     analysis: 147,219.15 ms,  5.20 GB
[mn-data-jdbc-graal-oracle:13561]     universe:   3,677.75 ms,  5.20 GB
[mn-data-jdbc-graal-oracle:13561]      (parse):  15,574.04 ms,  5.44 GB
[mn-data-jdbc-graal-oracle:13561]     (inline):   8,202.43 ms,  5.16 GB
[mn-data-jdbc-graal-oracle:13561]    (compile):  96,993.81 ms,  6.22 GB
[mn-data-jdbc-graal-oracle:13561]      compile: 125,304.17 ms,  6.22 GB
[mn-data-jdbc-graal-oracle:13561]        image:   9,238.41 ms,  6.31 GB
[mn-data-jdbc-graal-oracle:13561]        write:   1,345.92 ms,  6.31 GB
[mn-data-jdbc-graal-oracle:13561]      [total]: 296,446.96 ms,  6.31 GB

Analysis Results Statistics
Total reachable types             13606 
App reachable types                7357 
Total reachable methods           87936 
App reachable methods             44509 
Total type checks                 25159 
Total removable type checks        6024 
App type checks                   15309 
App removable type checks          3535

Take 3

[mn-data-jdbc-graal-oracle:14267]    classlist:   7,239.23 ms,  0.96 GB
[mn-data-jdbc-graal-oracle:14267]        (cap):     864.93 ms,  0.96 GB
[mn-data-jdbc-graal-oracle:14267]        setup:   2,464.18 ms,  0.96 GB
[mn-data-jdbc-graal-oracle:14267]     (clinit):   2,141.46 ms,  5.25 GB
[mn-data-jdbc-graal-oracle:14267]   (typeflow):  73,636.89 ms,  5.25 GB
[mn-data-jdbc-graal-oracle:14267]    (objects):  59,511.78 ms,  5.25 GB
[mn-data-jdbc-graal-oracle:14267]   (features):   4,235.01 ms,  5.25 GB
[mn-data-jdbc-graal-oracle:14267]     analysis: 147,321.06 ms,  5.25 GB
[mn-data-jdbc-graal-oracle:14267]     universe:   3,777.24 ms,  5.25 GB
[mn-data-jdbc-graal-oracle:14267]      (parse):  11,290.72 ms,  5.14 GB
[mn-data-jdbc-graal-oracle:14267]     (inline):  12,490.80 ms,  5.89 GB
[mn-data-jdbc-graal-oracle:14267]    (compile):  77,748.77 ms,  5.03 GB
[mn-data-jdbc-graal-oracle:14267]      compile: 106,226.00 ms,  5.03 GB
[mn-data-jdbc-graal-oracle:14267]        image:   8,961.31 ms,  5.96 GB
[mn-data-jdbc-graal-oracle:14267]        write:   1,219.16 ms,  5.96 GB
[mn-data-jdbc-graal-oracle:14267]      [total]: 277,693.98 ms,  5.96 GB

Analysis Results Statistics
Total reachable types             13606 
App reachable types                7357 
Total reachable methods           87936 
App reachable methods             44509 
Total type checks                 25159 
Total removable type checks        6024 
App type checks                   15309 
App removable type checks          3535 

Take 4

[mn-data-jdbc-graal-oracle:16298]    classlist:   7,056.35 ms,  0.96 GB
[mn-data-jdbc-graal-oracle:16298]        (cap):     664.82 ms,  0.96 GB
[mn-data-jdbc-graal-oracle:16298]        setup:   2,182.58 ms,  0.96 GB
[mn-data-jdbc-graal-oracle:16298]     (clinit):   2,046.83 ms,  5.22 GB
[mn-data-jdbc-graal-oracle:16298]   (typeflow):  70,354.42 ms,  5.22 GB
[mn-data-jdbc-graal-oracle:16298]    (objects):  68,332.68 ms,  5.22 GB
[mn-data-jdbc-graal-oracle:16298]   (features):   4,928.80 ms,  5.22 GB
[mn-data-jdbc-graal-oracle:16298]     analysis: 153,370.62 ms,  5.22 GB
[mn-data-jdbc-graal-oracle:16298]     universe:   3,688.21 ms,  5.21 GB
[mn-data-jdbc-graal-oracle:16298]      (parse):  14,825.94 ms,  5.51 GB
[mn-data-jdbc-graal-oracle:16298]     (inline):   8,345.74 ms,  5.25 GB
[mn-data-jdbc-graal-oracle:16298]    (compile):  87,265.17 ms,  6.29 GB
[mn-data-jdbc-graal-oracle:16298]      compile: 115,132.36 ms,  6.29 GB
[mn-data-jdbc-graal-oracle:16298]        image:   8,881.08 ms,  6.32 GB
[mn-data-jdbc-graal-oracle:16298]        write:   1,134.09 ms,  6.32 GB
[mn-data-jdbc-graal-oracle:16298]      [total]: 291,923.09 ms,  6.32 GB

Analysis Results Statistics
Total reachable types             13606 
App reachable types                7357 
Total reachable methods           87936 
App reachable methods             44509 
Total type checks                 25159 
Total removable type checks        6024 
App type checks                   15309 
App removable type checks          3535 

Tests with -H:+RemoveSaturatedTypeFlow and -H:+PrintAnalysisStatistics

Take 1

[mn-data-jdbc-graal-oracle:10062]    classlist:   6,824.06 ms,  0.96 GB
[mn-data-jdbc-graal-oracle:10062]        (cap):     777.22 ms,  0.96 GB
[mn-data-jdbc-graal-oracle:10062]        setup:   2,443.25 ms,  0.96 GB
[mn-data-jdbc-graal-oracle:10062]     (clinit):   2,208.58 ms,  5.60 GB
[mn-data-jdbc-graal-oracle:10062]   (typeflow):  40,676.47 ms,  5.60 GB
[mn-data-jdbc-graal-oracle:10062]    (objects):  60,360.51 ms,  5.60 GB
[mn-data-jdbc-graal-oracle:10062]   (features):   4,664.47 ms,  5.60 GB
[mn-data-jdbc-graal-oracle:10062]     analysis: 111,415.07 ms,  5.60 GB
[mn-data-jdbc-graal-oracle:10062]     universe:   3,611.81 ms,  5.60 GB
[mn-data-jdbc-graal-oracle:10062]      (parse):  10,866.89 ms,  5.60 GB
[mn-data-jdbc-graal-oracle:10062]     (inline):  13,491.93 ms,  7.07 GB
[mn-data-jdbc-graal-oracle:10062]    (compile):  80,039.09 ms,  7.75 GB
[mn-data-jdbc-graal-oracle:10062]      compile: 109,004.92 ms,  7.68 GB
[mn-data-jdbc-graal-oracle:10062]        image:   9,184.48 ms,  7.68 GB
[mn-data-jdbc-graal-oracle:10062]        write:   1,192.02 ms,  7.68 GB
[mn-data-jdbc-graal-oracle:10062]      [total]: 244,138.35 ms,  7.68 GB

Analysis Results Statistics
Total reachable types             13678 
App reachable types                7382 
Total reachable methods           89191 
App reachable methods             45015 
Total type checks                 25402 
Total removable type checks        5597 
App type checks                   15364 
App removable type checks          3219 

Image size 84262256 (+2 MB)

Take 2

[mn-data-jdbc-graal-oracle:11196]    classlist:   6,975.18 ms,  0.96 GB
[mn-data-jdbc-graal-oracle:11196]        (cap):     753.29 ms,  0.96 GB
[mn-data-jdbc-graal-oracle:11196]        setup:   2,348.22 ms,  0.96 GB
[mn-data-jdbc-graal-oracle:11196]     (clinit):   2,093.66 ms,  5.62 GB
[mn-data-jdbc-graal-oracle:11196]   (typeflow):  38,864.15 ms,  5.62 GB
[mn-data-jdbc-graal-oracle:11196]    (objects):  58,127.57 ms,  5.62 GB
[mn-data-jdbc-graal-oracle:11196]   (features):   4,294.56 ms,  5.62 GB
[mn-data-jdbc-graal-oracle:11196]     analysis: 106,782.76 ms,  5.62 GB
[mn-data-jdbc-graal-oracle:11196]     universe:   3,648.92 ms,  5.65 GB
[mn-data-jdbc-graal-oracle:11196]      (parse):  11,553.79 ms,  5.65 GB
[mn-data-jdbc-graal-oracle:11196]     (inline):  15,581.63 ms,  7.12 GB
[mn-data-jdbc-graal-oracle:11196]    (compile):  82,811.48 ms,  6.51 GB
[mn-data-jdbc-graal-oracle:11196]      compile: 114,448.45 ms,  6.51 GB
[mn-data-jdbc-graal-oracle:11196]        image:   9,167.88 ms,  6.50 GB
[mn-data-jdbc-graal-oracle:11196]        write:   1,210.37 ms,  6.50 GB
[mn-data-jdbc-graal-oracle:11196]      [total]: 245,068.87 ms,  6.50 GB

Analysis Results Statistics
Total reachable types             13678 
App reachable types                7382 
Total reachable methods           89192 
App reachable methods             45016 
Total type checks                 25402 
Total removable type checks        5611 
App type checks                   15364 
App removable type checks          3229 

Take 3

[mn-data-jdbc-graal-oracle:12277]    classlist:   7,381.31 ms,  0.96 GB
[mn-data-jdbc-graal-oracle:12277]        (cap):     741.91 ms,  0.96 GB
[mn-data-jdbc-graal-oracle:12277]        setup:   2,489.05 ms,  0.96 GB
[mn-data-jdbc-graal-oracle:12277]     (clinit):   1,999.76 ms,  5.66 GB
[mn-data-jdbc-graal-oracle:12277]   (typeflow):  43,211.22 ms,  5.66 GB
[mn-data-jdbc-graal-oracle:12277]    (objects):  64,613.73 ms,  5.66 GB
[mn-data-jdbc-graal-oracle:12277]   (features):   4,672.72 ms,  5.66 GB
[mn-data-jdbc-graal-oracle:12277]     analysis: 118,110.81 ms,  5.66 GB
[mn-data-jdbc-graal-oracle:12277]     universe:   4,111.04 ms,  5.59 GB
[mn-data-jdbc-graal-oracle:12277]      (parse):  11,891.16 ms,  5.59 GB
[mn-data-jdbc-graal-oracle:12277]     (inline):  15,314.04 ms,  6.28 GB
[mn-data-jdbc-graal-oracle:12277]    (compile):  83,940.72 ms,  6.44 GB
[mn-data-jdbc-graal-oracle:12277]      compile: 116,092.39 ms,  6.44 GB
[mn-data-jdbc-graal-oracle:12277]        image:  10,237.40 ms,  5.91 GB
[mn-data-jdbc-graal-oracle:12277]        write:   1,395.45 ms,  5.91 GB
[mn-data-jdbc-graal-oracle:12277]      [total]: 260,445.72 ms,  5.91 GB

Analysis Results Statistics
Total reachable types             13678 
App reachable types                7382 
Total reachable methods           89191 
App reachable methods             45015 
Total type checks                 25402 
Total removable type checks        5597 
App type checks                   15364 
App removable type checks          3217

Take 4

[mn-data-jdbc-graal-oracle:12831]    classlist:   7,223.94 ms,  0.96 GB
[mn-data-jdbc-graal-oracle:12831]        (cap):     745.81 ms,  0.96 GB
[mn-data-jdbc-graal-oracle:12831]        setup:   2,703.69 ms,  0.96 GB
[mn-data-jdbc-graal-oracle:12831]     (clinit):   2,102.39 ms,  5.60 GB
[mn-data-jdbc-graal-oracle:12831]   (typeflow):  41,364.77 ms,  5.60 GB
[mn-data-jdbc-graal-oracle:12831]    (objects):  60,577.58 ms,  5.60 GB
[mn-data-jdbc-graal-oracle:12831]   (features):   4,651.73 ms,  5.60 GB
[mn-data-jdbc-graal-oracle:12831]     analysis: 112,292.09 ms,  5.60 GB
[mn-data-jdbc-graal-oracle:12831]     universe:   4,216.02 ms,  5.60 GB
[mn-data-jdbc-graal-oracle:12831]      (parse):  10,663.19 ms,  5.60 GB
[mn-data-jdbc-graal-oracle:12831]     (inline):  14,918.22 ms,  6.13 GB
[mn-data-jdbc-graal-oracle:12831]    (compile):  78,955.84 ms,  6.11 GB
[mn-data-jdbc-graal-oracle:12831]      compile: 109,414.65 ms,  6.11 GB
[mn-data-jdbc-graal-oracle:12831]        image:   9,907.54 ms,  6.38 GB
[mn-data-jdbc-graal-oracle:12831]        write:   1,291.71 ms,  6.38 GB
[mn-data-jdbc-graal-oracle:12831]      [total]: 247,684.79 ms,  6.38 GB

Analysis Results Statistics
Total reachable types             13678 
App reachable types                7382 
Total reachable methods           89191 
App reachable methods             45015 
Total type checks                 25402 
Total removable type checks        5585 
App type checks                   15364 
App removable type checks          3215 

As you can see the results vary too much with the same options, so I'm not really sure what to expect. Hopefully the output makes more sense to you.

I'm happy to try more things with other flags and configuration options if you need it.

[cstancu]

Yes, the output is as expected. You need to focus on the (typeflow) step of the analysis phase. It looks like it is consistently reduced from ~70s to ~40s. I created an issue with more details about this feature #2384. The memory numbers in the native-image output are not very useful, it is the total amount of memory in the JVM as reported by Runtime.getRuntime().totalMemory() . A more useful memory analysis tool would be to use -H:DumpHeap=after-analysis which will give you a .hprof file with the live objects at the end of the analysis phase.

[ilopmar]

Thank you very much for the explanation :)

[binoysankar]

I am using Micronaut + Java 11 + Redis Cache + native-image, when deployed to k8s I can see the memory consumed per pod is between 45-55 Mi when ideal.
When compiled with Java 8 the same application is only utilizing 15-20 Mi during ideal.

[cstancu]

-H:+RemoveSaturatedTypeFlows has been the default for a while now.