Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Increased compilation times with GraalVM 21.1.0 #18360

Closed
vsevel opened this issue Jul 2, 2021 · 58 comments
Closed

Increased compilation times with GraalVM 21.1.0 #18360

vsevel opened this issue Jul 2, 2021 · 58 comments
Labels
kind/bug Something isn't working

Comments

@vsevel
Copy link
Contributor

vsevel commented Jul 2, 2021

Describe the bug

I am seeing increased graalvm compilation times between 1.13.3 and 2.0
I have launched multiple builds and I see consistency in the results.
I am building both branches on the same host, and with the same command line args.

Here is the output for 1.13:

[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] Running Quarkus native-image plugin on GraalVM Version 21.0.0.2 (Java Version 11.0.10+8-jvmci-21.0-b06)
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] docker run --env LANG=C --user 1796:2033 --rm -v /export/soft/SrvJenkins/workspace/java-ocpdeploy_master/target/ocpdeploy-4.6.2-SNAPSHOT-native-image-source-jar:/project:z quay.io/quarkus/ubi-quarkus-native-image:21.0-java11 -J-Dsun.nio.ch.maxUpdateArraySize=100 -J-Djava.util.logging.manager=org.jboss.logmanager.LogManager -J-Dvertx.logger-delegate-factory-class-name=io.quarkus.vertx.core.runtime.VertxLogDelegateFactory -J-Dvertx.disableDnsResolver=true -J-Dio.netty.leakDetection.level=DISABLED -J-Dio.netty.allocator.maxOrder=1 -J-Duser.language=en -J-Duser.country=US -J-Dfile.encoding=UTF-8 -H:ReflectionConfigurationFiles=reflection-config.json --allow-incomplete-classpath -J-Djavax.net.ssl.trustStore=/project/trustStore -J-Djavax.net.ssl.trustStorePassword=changeit --initialize-at-build-time= -H:InitialCollectionPolicy=com.oracle.svm.core.genscavenge.CollectionPolicy\$BySpaceAndTime -H:+JNI -H:+AllowFoldMethods -jar ocpdeploy-4.6.2-SNAPSHOT-runner.jar -H:FallbackThreshold=0 -H:+ReportExceptionStackTraces -H:-AddAllCharsets -H:EnableURLProtocols=http,https --enable-all-security-services --no-server -H:-UseServiceLoaderFeature -H:+StackTrace ocpdeploy-4.6.2-SNAPSHOT-runner
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]    classlist:   6,189.64 ms,  1.67 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]        (cap):   1,073.61 ms,  1.67 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]        setup:   3,184.67 ms,  1.67 GB
14:51:05,733 INFO  [org.hib.val.int.uti.Version] HV000001: Hibernate Validator 6.2.0.Final
14:52:10,671 INFO  [org.jbo.threads] JBoss Threads version 3.2.0.Final
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]     (clinit):   3,650.85 ms,  3.56 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]   (typeflow):  50,425.96 ms,  3.56 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]    (objects):  84,078.25 ms,  3.56 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]   (features):   4,153.43 ms,  3.56 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]     analysis: 152,901.38 ms,  3.56 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]     universe:   8,103.62 ms,  3.57 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]      (parse):  28,799.10 ms,  4.03 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]     (inline):  31,623.75 ms,  5.42 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]    (compile):  73,604.55 ms,  5.75 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]      compile: 148,436.44 ms,  5.75 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]        image:  38,113.50 ms,  4.97 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]        write:   3,585.95 ms,  4.97 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]      [total]: 361,041.90 ms,  4.97 GB
[WARNING] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] objcopy executable not found in PATH. Debug symbols will not be separated from executable.
[WARNING] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] That will result in a larger native image with debug symbols embedded in it.
[INFO] [io.quarkus.deployment.QuarkusAugmentor] Quarkus augmentation completed in 370296ms

and for 2.0:

[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] Running Quarkus native-image plugin on GraalVM 21.1.0 Java 11 CE (Java Version 11.0.11+8-jvmci-21.1-b05)
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] docker run --env LANG=C --rm --user 1796:2033 -v /export/soft/SrvJenkins/workspace/re_ARTEOCPDEPLOY-157-Quarkus-2-0/target/ocpdeploy-4.6.2-SNAPSHOT-native-image-source-jar:/project:z quay.io/quarkus/ubi-quarkus-native-image:21.1-java11 -J-Djava.util.logging.manager=org.jboss.logmanager.LogManager -J-Dsun.nio.ch.maxUpdateArraySize=100 -J-Dvertx.logger-delegate-factory-class-name=io.quarkus.vertx.core.runtime.VertxLogDelegateFactory -J-Dvertx.disableDnsResolver=true -J-Dio.netty.leakDetection.level=DISABLED -J-Dio.netty.allocator.maxOrder=3 -J-Duser.language=en -J-Duser.country=US -J-Dfile.encoding=UTF-8 -H:ReflectionConfigurationFiles=reflection-config.json --allow-incomplete-classpath -J-Djavax.net.ssl.trustStore=/project/trustStore -J-Djavax.net.ssl.trustStorePassword=changeit --initialize-at-build-time= -H:InitialCollectionPolicy=com.oracle.svm.core.genscavenge.CollectionPolicy\$BySpaceAndTime -H:+JNI -H:+AllowFoldMethods -jar ocpdeploy-4.6.2-SNAPSHOT-runner.jar -H:FallbackThreshold=0 -H:+ReportExceptionStackTraces -H:-AddAllCharsets -H:EnableURLProtocols=http,https -H:-UseServiceLoaderFeature -H:+StackTrace ocpdeploy-4.6.2-SNAPSHOT-runner
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]    classlist:   5,624.79 ms,  1.20 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]        (cap):     953.70 ms,  1.20 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]        setup:   3,256.10 ms,  1.20 GB
15:31:33,342 INFO  [org.hib.val.int.uti.Version] HV000001: Hibernate Validator 6.2.0.Final
15:32:39,664 INFO  [org.jbo.threads] JBoss Threads version 3.4.0.Final
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]     (clinit):   4,228.94 ms,  3.53 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]   (typeflow): 108,242.89 ms,  4.33 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]    (objects):  98,535.85 ms,  4.33 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]   (features):   4,710.55 ms,  4.33 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]     analysis: 230,321.93 ms,  4.33 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]     universe:   7,664.31 ms,  4.33 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]      (parse):  38,355.42 ms,  5.33 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]     (inline):  66,602.14 ms,  5.42 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]    (compile): 461,732.89 ms,  5.42 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]      compile: 579,871.69 ms,  5.42 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]        image:  34,732.90 ms,  5.42 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]        write:   4,362.62 ms,  5.42 GB
# Printing build artifacts to: ocpdeploy-4.6.2-SNAPSHOT-runner.build_artifacts.txt
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]      [total]: 866,380.27 ms,  5.42 GB

the compile phase went from 73 secs to 461 secs.
I am seeing that we have moved from graalvm 21.0 to 21.1.
once the image is built, both versions work identically.
I did not see anything in the migration guide that would require some config change on the graalvm buil.

I am surprised to see that kind of difference. I suppose a lot of people would have noticed. still, since I am using the same host for all quarkus builds, and I do not see anything that could have changed beside the graalvm version.

I have actually restarted a new branch on my project based on my 2.0 quarkus branch, and moved the quarkus version back to 1.13, and just removed all my tests and commented out the compilation errors, and I get back the expected durations:

[ocpdeploy-4.6.2-SNAPSHOT-runner:24]    (compile):  79,745.13 ms,  5.74 GB

I have moved back to quarkus 2.0.0.Alpha1, which uses graalvm 21.0 and got normal performances:

[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] Running Quarkus native-image plugin on GraalVM Version 21.0.0.2 (Java Version 11.0.10+8-jvmci-21.0-b06)
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] docker run --env LANG=C --user 1796:2033 --rm -v /export/soft/SrvJenkins/workspace/java-ocpdeploy_test_graalvm/target/ocpdeploy-4.6.2-SNAPSHOT-native-image-source-jar:/project:z quay.io/quarkus/ubi-quarkus-native-image:21.0-java11 -J-Dsun.nio.ch.maxUpdateArraySize=100 -J-Djava.util.logging.manager=org.jboss.logmanager.LogManager -J-Dvertx.logger-delegate-factory-class-name=io.quarkus.vertx.core.runtime.VertxLogDelegateFactory -J-Dvertx.disableDnsResolver=true -J-Dio.netty.leakDetection.level=DISABLED -J-Dio.netty.allocator.maxOrder=1 -J-Duser.language=en -J-Duser.country=US -J-Dfile.encoding=UTF-8 -H:ReflectionConfigurationFiles=reflection-config.json --allow-incomplete-classpath -J-Djavax.net.ssl.trustStore=/project/trustStore -J-Djavax.net.ssl.trustStorePassword=changeit --initialize-at-build-time= -H:InitialCollectionPolicy=com.oracle.svm.core.genscavenge.CollectionPolicy\$BySpaceAndTime -H:+JNI -H:+AllowFoldMethods -jar ocpdeploy-4.6.2-SNAPSHOT-runner.jar -H:FallbackThreshold=0 -H:+ReportExceptionStackTraces -H:-AddAllCharsets -H:EnableURLProtocols=http,https --enable-all-security-services -H:-UseServiceLoaderFeature -H:+StackTrace ocpdeploy-4.6.2-SNAPSHOT-runner
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]    classlist:   5,863.96 ms,  1.21 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]        (cap):     943.84 ms,  1.21 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]        setup:   3,113.11 ms,  1.21 GB
16:24:21,081 INFO  [org.hib.val.int.uti.Version] HV000001: Hibernate Validator 6.2.0.Final
16:25:18,702 INFO  [org.jbo.threads] JBoss Threads version 3.2.0.Final
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]     (clinit):   3,711.93 ms,  3.44 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]   (typeflow):  47,006.14 ms,  3.44 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]    (objects):  78,164.30 ms,  3.44 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]   (features):   4,067.07 ms,  3.44 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]     analysis: 142,913.89 ms,  3.44 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]     universe:   7,793.34 ms,  3.45 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]      (parse):  27,867.37 ms,  4.21 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]     (inline):  31,133.77 ms,  5.42 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]    (compile):  94,738.96 ms,  5.66 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]      compile: 162,910.80 ms,  5.66 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]        image:  28,686.72 ms,  5.43 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]        write:   4,122.21 ms,  5.43 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]      [total]: 355,931.31 ms,  5.43 GB
[WARNING] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] objcopy executable not found in PATH. Debug symbols will not be separated from executable.
[WARNING] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] That will result in a larger native image with debug symbols embedded in it.
[INFO] [io.quarkus.deployment.QuarkusAugmentor] Quarkus augmentation completed in 366600ms

Expected behavior

similar compilation response time.

Actual behavior

huge increase on the graalvm compilation phase.

To Reproduce

I can reproduce it consistently on my application in my build env. I have not tried to do it on a different simpler app.

Output of uname -a or ver

OS name: "linux", version: "3.10.0-1160.25.1.el7.x86_64", arch: "amd64", family: "unix"

Output of java -version

Java version: 11.0.10, vendor: AdoptOpenJDK, runtime: /opt/java/openjdk

GraalVM version (if different from Java)

Quarkus version or git rev

Build tool (ie. output of mvnw --version or gradlew --version)

Apache Maven 3.6.3 (cecedd343002696d0abb50b32b541b8a6ba2883f)

@vsevel vsevel added the kind/bug Something isn't working label Jul 2, 2021
@gsmet
Copy link
Member

gsmet commented Jul 2, 2021

Can you try to build 2.0.0.Final with GraalVM 21.0? It should work and it would help to understand if Quarkus is the issue or GraalVM.

@vsevel
Copy link
Contributor Author

vsevel commented Jul 2, 2021

2.0.0.Final works with 21.0.0.2, with something in the middle for the duration for the compile phase: 144 secs; compared to 73 secs for 1.13, and 461 secs for 2.0.0.Final + 21.1.
The other difference I see is memory usage. I had to increase quarkus.native.native-image-xmx to get the build to pass.

[INFO] --- quarkus-maven-plugin:2.0.0.Final:build (default) @ ocpdeploy ---
[INFO] [org.jboss.threads] JBoss Threads version 3.4.0.Final
[INFO] [io.quarkus.deployment.pkg.steps.JarResultBuildStep] Building native image source jar: /export/soft/SrvJenkins/workspace/java-ocpdeploy_test_graalvm/target/ocpdeploy-4.6.2-SNAPSHOT-native-image-source-jar/ocpdeploy-4.6.2-SNAPSHOT-runner.jar
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] Building native image from /export/soft/SrvJenkins/workspace/java-ocpdeploy_test_graalvm/target/ocpdeploy-4.6.2-SNAPSHOT-native-image-source-jar/ocpdeploy-4.6.2-SNAPSHOT-runner.jar
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildContainerRunner] Using docker to run the native image builder
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildContainerRunner] Checking image status quay.io/quarkus/ubi-quarkus-native-image:21.0-java11
21.0-java11: Pulling from quarkus/ubi-quarkus-native-image
Digest: sha256:affbd4a26c932fa5e507a529c57802ec76c9dc4e97bf96f85ddc40727d3a91d7
Status: Image is up to date for quay.io/quarkus/ubi-quarkus-native-image:21.0-java11
quay.io/quarkus/ubi-quarkus-native-image:21.0-java11
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] Running Quarkus native-image plugin on GraalVM Version 21.0.0.2 (Java Version 11.0.10+8-jvmci-21.0-b06)
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] docker run --env LANG=C --rm --user 1796:2033 -v /export/soft/SrvJenkins/workspace/java-ocpdeploy_test_graalvm/target/ocpdeploy-4.6.2-SNAPSHOT-native-image-source-jar:/project:z quay.io/quarkus/ubi-quarkus-native-image:21.0-java11 -J-Dsun.nio.ch.maxUpdateArraySize=100 -J-Djava.util.logging.manager=org.jboss.logmanager.LogManager -J-Dvertx.logger-delegate-factory-class-name=io.quarkus.vertx.core.runtime.VertxLogDelegateFactory -J-Dvertx.disableDnsResolver=true -J-Dio.netty.leakDetection.level=DISABLED -J-Dio.netty.allocator.maxOrder=3 -J-Duser.language=en -J-Duser.country=US -J-Dfile.encoding=UTF-8 -H:ReflectionConfigurationFiles=reflection-config.json --allow-incomplete-classpath -J-Djavax.net.ssl.trustStore=/project/trustStore -J-Djavax.net.ssl.trustStorePassword=changeit --initialize-at-build-time= -H:InitialCollectionPolicy=com.oracle.svm.core.genscavenge.CollectionPolicy\$BySpaceAndTime -H:+JNI -H:+AllowFoldMethods -jar ocpdeploy-4.6.2-SNAPSHOT-runner.jar -H:FallbackThreshold=0 -H:+ReportExceptionStackTraces -J-Xmx10g -H:-AddAllCharsets -H:EnableURLProtocols=http,https --enable-all-security-services -H:-UseServiceLoaderFeature -H:+StackTrace ocpdeploy-4.6.2-SNAPSHOT-runner
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]    classlist:   8,534.57 ms,  1.72 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]        (cap):   1,191.70 ms,  1.72 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]        setup:   3,526.51 ms,  1.72 GB
17:46:04,254 INFO  [org.hib.val.int.uti.Version] HV000001: Hibernate Validator 6.2.0.Final
17:47:20,027 INFO  [org.jbo.threads] JBoss Threads version 3.4.0.Final
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]     (clinit):   3,604.59 ms,  4.13 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]   (typeflow):  63,181.07 ms,  4.13 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]    (objects):  83,161.65 ms,  4.13 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]   (features):   4,289.57 ms,  4.13 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]     analysis: 164,319.30 ms,  4.13 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]     universe:   7,996.91 ms,  4.28 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]      (parse):  32,442.05 ms,  5.02 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]     (inline):  41,805.52 ms,  6.25 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]    (compile): 144,450.86 ms,  7.61 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]      compile: 271,857.04 ms,  7.61 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]        image:  55,619.94 ms,  7.22 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]        write:   5,640.86 ms,  7.22 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]      [total]: 518,148.18 ms,  7.22 GB
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] docker run --env LANG=C --rm --user 1796:2033 -v /export/soft/SrvJenkins/workspace/java-ocpdeploy_test_graalvm/target/ocpdeploy-4.6.2-SNAPSHOT-native-image-source-jar:/project:z --entrypoint /bin/bash quay.io/quarkus/ubi-quarkus-native-image:21.0-java11 -c objcopy --strip-debug ocpdeploy-4.6.2-SNAPSHOT-runner
[INFO] [io.quarkus.deployment.QuarkusAugmentor] Quarkus augmentation completed in 536654ms
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS

@gsmet
Copy link
Member

gsmet commented Jul 6, 2021

Can you try to enable quarkus.native.enable-reports=true and compare the two reports with the classes (I would compare the different Quarkus versions with the same version of GraalVM first)?

@gsmet
Copy link
Member

gsmet commented Jul 6, 2021

/cc @zakkak

@zakkak
Copy link
Contributor

zakkak commented Jul 6, 2021

Hi @vsevel @gsmet ,

This is a known GraalVM issue see oracle/graal#3435 and oracle/graal#3427

The increased compilation times appear to be linked to increased heap usage (as reported in oracle/graal#3427), since we have not yet identified the cause of the increased memory usage if you have the resources you may try to increase the max heap size to reduce the GC cycles.

@gsmet
Copy link
Member

gsmet commented Jul 6, 2021

That could explain the regression with GraalVM 21.1 (but, gosh, it's drastic...) but that wouldn't explain the regression we have with both Quarkus versions using 21.0. We need to figure that out.

@vsevel
Copy link
Contributor Author

vsevel commented Jul 6, 2021

I have not been able to configure quarkus.native.enable-reports=true. I have tested with Quarkus 2.0 and GraalVM 21.0 and 21.1, and everytime I get the process killed with:

...
[ocpdeploy-4.6.2-SNAPSHOT-runner:24]     analysis: 287,156.84 ms,  4.40 GB

=== Image generator watchdog detected no activity. This can be a sign of a deadlock during image building. Dumping all stack traces. Current time: Tue Jul 06 12:05:31 GMT 2021
...
=== Memory statistics (in MB):
=== Used heap size: 6246
=== Free heap size: 1528
=== Maximum heap size: 9102
=== Image generator watchdog is aborting image generation. To configure the watchdog, use the options -H:DeadlockWatchdogInterval=10 and -H:+DeadlockWatchdogExitOnTimeout

I tried with -H:DeadlockWatchdogInterval=30, but that failed also.
I am still using quarkus.native.native-image-xmx=10g

I have deactivated the report, and kept a 10g heap. Now I can pass the build with (compile): 155,307.60 ms, 7.96 GB compared to (compile): 73,604.55 ms, 5.75 GB when I created the issue. So a large heap does improve things.

@gsmet
Copy link
Member

gsmet commented Jul 6, 2021

Can you try doing it locally instead of doing it on OpenShift?

@galderz
Copy link
Member

galderz commented Jul 8, 2021

Bonjour @vsevel!

As @gsmet said, it would help to run this locally somewhere with enough heap (16GB or more) so that native image reports successfully complete. If this is not successful, we can build some byteman rules that could enable to get a better understanding on what's causing the differences.

Could you give us a list of quarkus extensions that you're using?

@vsevel
Copy link
Contributor Author

vsevel commented Jul 8, 2021

hello @galderz yes definitely, I am still planing to do this. it has been taken more time than I wanted. I will let you know.
in the meantime, here are the extensions we are currently using: cdi, config-yaml, freemarker, hibernate-validator, kubernetes-client, openshift-client, rest-client, restclient-jackson, vault (plus internal extensions for SMBJ and our internal centralized logging system).

@vsevel
Copy link
Contributor Author

vsevel commented Jul 13, 2021

hello, I have managed to get some results. I have created a host with 16 Gb and 8 cores. I built the native executable with a mix of Quarkus 1.13/2.0, GraalVM 21.0/21.1 and docker yes/no. The source code is the same, the host is not running anything else, and I have used a -J-Xmx10g
Here is for each configuration the total amount of time in seconds and the max amount of memory consumed by the native-image tool:

Quarkus GraalVM docker [total] (s) max mem (GB)
1.13 21.0 no 245 7.11
2.0 21.0 no 275 7.51
2.0 21.1 no 320 8.03
1.13 21.0 yes 295 7.05
2.0 21.0 yes 301 7.46
2.0 21.1 yes 345 8.00

I have the detailed log for each run (if needed), plus a the GraalVM reports for the 2.0/21.1 configuration.

@vsevel
Copy link
Contributor Author

vsevel commented Jul 13, 2021

detail for all runs:

quarkus 2.0 graalvm 21.1
-------------------------

[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] Running Quarkus native-image plugin on GraalVM 21.1.0 Java 11 CE (Java Version 11.0.11+8-jvmci-21.1-b05)
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] /home/sevel/graalvm-ce-java11-21.1.0/bin/native-image -J-Dsun.nio.ch.maxUpdateArraySize=100 -J-Djava.util.logging.manager=org.jboss.logmanager.LogManager -J-Dvertx.logger-delegate-factory-class-name=io.quarkus.vertx.core.runtime.VertxLogDelegateFactory -J-Dvertx.disableDnsResolver=true -J-Dio.netty.leakDetection.level=DISABLED -J-Dio.netty.allocator.maxOrder=3 -J-Duser.language=en -J-Duser.country=US -J-Dfile.encoding=UTF-8 -H:ReflectionConfigurationFiles=reflection-config.json --allow-incomplete-classpath -J-Djavax.net.ssl.trustStore=LODHCAs.jks -J-Djavax.net.ssl.trustStorePassword=changeit -H:DeadlockWatchdogInterval=30 -J-Djava.io.tmpdir=/home/sevel/tmpdir --initialize-at-build-time= -H:InitialCollectionPolicy=com.oracle.svm.core.genscavenge.CollectionPolicy\$BySpaceAndTime -H:+JNI -H:+AllowFoldMethods -jar ocpdeploy-4.6.2-SNAPSHOT-runner.jar -H:FallbackThreshold=0 -H:+ReportExceptionStackTraces -J-Xmx10g -H:-AddAllCharsets -H:EnableURLProtocols=http,https -H:-UseServiceLoaderFeature -H:+StackTrace ocpdeploy-4.6.2-SNAPSHOT-runner
[ocpdeploy-4.6.2-SNAPSHOT-runner:67722]    classlist:   5,734.63 ms,  1.71 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:67722]        (cap):     627.89 ms,  1.71 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:67722]        setup:   2,703.41 ms,  1.71 GB
15:39:06,832 INFO  [org.hib.val.int.uti.Version] HV000001: Hibernate Validator 6.2.0.Final
15:40:05,652 INFO  [org.jbo.threads] JBoss Threads version 3.4.0.Final
[ocpdeploy-4.6.2-SNAPSHOT-runner:67722]     (clinit):   3,384.22 ms,  4.52 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:67722]   (typeflow):  58,408.88 ms,  4.52 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:67722]    (objects):  84,493.17 ms,  4.52 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:67722]   (features):   4,161.86 ms,  4.52 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:67722]     analysis: 159,454.09 ms,  4.52 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:67722]     universe:   6,282.59 ms,  4.52 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:67722]      (parse):  38,950.45 ms,  5.32 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:67722]     (inline):  21,298.25 ms,  7.50 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:67722]    (compile):  52,409.56 ms,  8.03 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:67722]      compile: 120,740.31 ms,  8.03 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:67722]        image:  22,159.02 ms,  7.56 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:67722]        write:   2,338.77 ms,  7.56 GB
# Printing build artifacts to: ocpdeploy-4.6.2-SNAPSHOT-runner.build_artifacts.txt
[ocpdeploy-4.6.2-SNAPSHOT-runner:67722]      [total]: 320,012.17 ms,  7.56 GB
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] objcopy --strip-debug ocpdeploy-4.6.2-SNAPSHOT-runner
[INFO] [io.quarkus.deployment.QuarkusAugmentor] Quarkus augmentation completed in 324554ms


quarkus 2.0 GraalVM CE 21.0.0.2
-------------------------

[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] Running Quarkus native-image plugin on GraalVM Version 21.0.0.2 (Java Version 11.0.10+8-jvmci-21.0-b06)
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] /home/sevel/graalvm-ce-java11-21.0.0.2/bin/native-image -J-Dsun.nio.ch.maxUpdateArraySize=100 -J-Djava.util.logging.manager=org.jboss.logmanager.LogManager -J-Dvertx.logger-delegate-factory-class-name=io.quarkus.vertx.core.runtime.VertxLogDelegateFactory -J-Dvertx.disableDnsResolver=true -J-Dio.netty.leakDetection.level=DISABLED -J-Dio.netty.allocator.maxOrder=3 -J-Duser.language=en -J-Duser.country=US -J-Dfile.encoding=UTF-8 -H:ReflectionConfigurationFiles=reflection-config.json --allow-incomplete-classpath -J-Djavax.net.ssl.trustStore=LODHCAs.jks -J-Djavax.net.ssl.trustStorePassword=changeit -H:DeadlockWatchdogInterval=30 -J-Djava.io.tmpdir=/home/sevel/tmpdir --initialize-at-build-time= -H:InitialCollectionPolicy=com.oracle.svm.core.genscavenge.CollectionPolicy\$BySpaceAndTime -H:+JNI -H:+AllowFoldMethods -jar ocpdeploy-4.6.2-SNAPSHOT-runner.jar -H:FallbackThreshold=0 -H:+ReportExceptionStackTraces -J-Xmx10g -H:-AddAllCharsets -H:EnableURLProtocols=http,https --enable-all-security-services -H:-UseServiceLoaderFeature -H:+StackTrace ocpdeploy-4.6.2-SNAPSHOT-runner
[ocpdeploy-4.6.2-SNAPSHOT-runner:69971]    classlist:   5,558.49 ms,  1.68 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:69971]        (cap):     711.48 ms,  1.68 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:69971]        setup:   2,649.55 ms,  1.68 GB
15:57:10,783 INFO  [org.hib.val.int.uti.Version] HV000001: Hibernate Validator 6.2.0.Final
15:58:09,656 INFO  [org.jbo.threads] JBoss Threads version 3.4.0.Final
[ocpdeploy-4.6.2-SNAPSHOT-runner:69971]     (clinit):   3,371.90 ms,  4.72 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:69971]   (typeflow):  46,578.97 ms,  4.72 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:69971]    (objects):  70,089.26 ms,  4.72 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:69971]   (features):   3,892.13 ms,  4.72 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:69971]     analysis: 133,324.53 ms,  4.72 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:69971]     universe:   6,400.18 ms,  4.72 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:69971]      (parse):  35,615.54 ms,  5.95 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:69971]     (inline):  13,537.59 ms,  7.05 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:69971]    (compile):  50,313.21 ms,  7.51 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:69971]      compile: 106,839.08 ms,  7.51 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:69971]        image:  17,752.75 ms,  7.51 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:69971]        write:   2,157.06 ms,  7.51 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:69971]      [total]: 275,171.34 ms,  7.51 GB
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] objcopy --strip-debug ocpdeploy-4.6.2-SNAPSHOT-runner
[INFO] [io.quarkus.deployment.QuarkusAugmentor] Quarkus augmentation completed in 279038ms


quarkus 1.13 GraalVM CE 21.0.0.2
-------------------------

[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] Running Quarkus native-image plugin on GraalVM Version 21.0.0.2 (Java Version 11.0.10+8-jvmci-21.0-b06)
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] /home/sevel/graalvm-ce-java11-21.0.0.2/bin/native-image -J-Dsun.nio.ch.maxUpdateArraySize=100 -J-Djava.util.logging.manager=org.jboss.logmanager.LogManager -J-Dvertx.logger-delegate-factory-class-name=io.quarkus.vertx.core.runtime.VertxLogDelegateFactory -J-Dvertx.disableDnsResolver=true -J-Dio.netty.leakDetection.level=DISABLED -J-Dio.netty.allocator.maxOrder=1 -J-Duser.language=en -J-Duser.country=US -J-Dfile.encoding=UTF-8 -H:ReflectionConfigurationFiles=reflection-config.json --allow-incomplete-classpath -J-Djavax.net.ssl.trustStore=LODHCAs.jks -J-Djavax.net.ssl.trustStorePassword=changeit -H:DeadlockWatchdogInterval=30 -J-Djava.io.tmpdir=/home/sevel/tmpdir --initialize-at-build-time= -H:InitialCollectionPolicy=com.oracle.svm.core.genscavenge.CollectionPolicy\$BySpaceAndTime -H:+JNI -H:+AllowFoldMethods -jar ocpdeploy-4.6.2-SNAPSHOT-runner.jar -H:FallbackThreshold=0 -H:+ReportExceptionStackTraces -J-Xmx10g -H:-AddAllCharsets -H:EnableURLProtocols=http,https --enable-all-security-services --no-server -H:-UseServiceLoaderFeature -H:+StackTrace ocpdeploy-4.6.2-SNAPSHOT-runner
[ocpdeploy-4.6.2-SNAPSHOT-runner:75264]    classlist:   5,596.29 ms,  1.70 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:75264]        (cap):     630.35 ms,  1.70 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:75264]        setup:   2,450.79 ms,  1.70 GB
17:24:55,246 INFO  [org.hib.val.int.uti.Version] HV000001: Hibernate Validator 6.2.0.Final
17:25:48,314 INFO  [org.jbo.threads] JBoss Threads version 3.2.0.Final
[ocpdeploy-4.6.2-SNAPSHOT-runner:75264]     (clinit):   3,188.47 ms,  4.40 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:75264]   (typeflow):  41,938.01 ms,  4.40 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:75264]    (objects):  63,857.25 ms,  4.40 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:75264]   (features):   3,473.14 ms,  4.40 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:75264]     analysis: 120,871.21 ms,  4.40 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:75264]     universe:   6,047.85 ms,  4.54 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:75264]      (parse):  26,802.04 ms,  5.44 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:75264]     (inline):  13,223.80 ms,  6.68 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:75264]    (compile):  44,538.76 ms,  7.11 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:75264]      compile:  91,517.04 ms,  6.98 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:75264]        image:  16,663.21 ms,  6.58 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:75264]        write:   2,065.07 ms,  6.58 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:75264]      [total]: 245,702.57 ms,  6.58 GB
[INFO] [io.quarkus.deployment.QuarkusAugmentor] Quarkus augmentation completed in 249235ms


quarkus 1.13 GraalVM CE 21.0.0.2 (docker)
-------------------------

[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] Running Quarkus native-image plugin on GraalVM Version 21.0.0.2 (Java Version 11.0.10+8-jvmci-21.0-b06)
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] docker run --env LANG=C --user 2002:2002 --rm -v /export/soft/appl/java-ocpdeploy/target/ocpdeploy-4.6.2-SNAPSHOT-native-image-source-jar:/project:z quay.io/quarkus/ubi-quarkus-native-image:21.0-java11 -J-Djava.util.logging.manager=org.jboss.logmanager.LogManager -J-Dsun.nio.ch.maxUpdateArraySize=100 -J-Dvertx.logger-delegate-factory-class-name=io.quarkus.vertx.core.runtime.VertxLogDelegateFactory -J-Dvertx.disableDnsResolver=true -J-Dio.netty.leakDetection.level=DISABLED -J-Dio.netty.allocator.maxOrder=1 -J-Duser.language=en -J-Duser.country=US -J-Dfile.encoding=UTF-8 -H:ReflectionConfigurationFiles=reflection-config.json --allow-incomplete-classpath -J-Djavax.net.ssl.trustStore=/project/trustStore -J-Djavax.net.ssl.trustStorePassword=changeit -H:DeadlockWatchdogInterval=30 --initialize-at-build-time= -H:InitialCollectionPolicy=com.oracle.svm.core.genscavenge.CollectionPolicy\$BySpaceAndTime -H:+JNI -H:+AllowFoldMethods -jar ocpdeploy-4.6.2-SNAPSHOT-runner.jar -H:FallbackThreshold=0 -H:+ReportExceptionStackTraces -J-Xmx10g -H:-AddAllCharsets -H:EnableURLProtocols=http,https --enable-all-security-services --no-server -H:-UseServiceLoaderFeature -H:+StackTrace ocpdeploy-4.6.2-SNAPSHOT-runner
[ocpdeploy-4.6.2-SNAPSHOT-runner:26]    classlist:   6,291.09 ms,  1.20 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:26]        (cap):     836.34 ms,  1.20 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:26]        setup:   2,827.55 ms,  1.20 GB
09:37:42,539 INFO  [org.hib.val.int.uti.Version] HV000001: Hibernate Validator 6.2.0.Final
09:38:39,521 INFO  [org.jbo.threads] JBoss Threads version 3.2.0.Final
[ocpdeploy-4.6.2-SNAPSHOT-runner:26]     (clinit):   3,469.83 ms,  4.38 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:26]   (typeflow):  40,820.58 ms,  4.38 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:26]    (objects):  88,916.38 ms,  4.38 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:26]   (features):   3,862.86 ms,  4.38 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:26]     analysis: 146,422.60 ms,  4.38 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:26]     universe:   7,894.44 ms,  4.53 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:26]      (parse):  35,929.47 ms,  5.39 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:26]     (inline):  17,010.81 ms,  6.64 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:26]    (compile):  49,471.14 ms,  7.05 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:26]      compile: 109,715.78 ms,  7.03 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:26]        image:  19,085.25 ms,  6.46 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:26]        write:   2,426.20 ms,  6.46 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:26]      [total]: 295,136.77 ms,  6.46 GB
[INFO] [io.quarkus.deployment.QuarkusAugmentor] Quarkus augmentation completed in 302265ms


quarkus 2.0 GraalVM Version 21.0.0.2 (docker image quay.io/quarkus/ubi-quarkus-native-image:21.0-java11)
-------------------------

[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] Running Quarkus native-image plugin on GraalVM Version 21.0.0.2 (Java Version 11.0.10+8-jvmci-21.0-b06)
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] docker run --env LANG=C --rm --user 2002:2002 -v /export/soft/appl/java-ocpdeploy/target/ocpdeploy-4.6.2-SNAPSHOT-native-image-source-jar:/project:z quay.io/quarkus/ubi-quarkus-native-image:21.0-java11 -J-Dsun.nio.ch.maxUpdateArraySize=100 -J-Djava.util.logging.manager=org.jboss.logmanager.LogManager -J-Dvertx.logger-delegate-factory-class-name=io.quarkus.vertx.core.runtime.VertxLogDelegateFactory -J-Dvertx.disableDnsResolver=true -J-Dio.netty.leakDetection.level=DISABLED -J-Dio.netty.allocator.maxOrder=3 -J-Duser.language=en -J-Duser.country=US -J-Dfile.encoding=UTF-8 -H:ReflectionConfigurationFiles=reflection-config.json --allow-incomplete-classpath -J-Djavax.net.ssl.trustStore=/project/trustStore -J-Djavax.net.ssl.trustStorePassword=changeit -H:DeadlockWatchdogInterval=30 --initialize-at-build-time= -H:InitialCollectionPolicy=com.oracle.svm.core.genscavenge.CollectionPolicy\$BySpaceAndTime -H:+JNI -H:+AllowFoldMethods -jar ocpdeploy-4.6.2-SNAPSHOT-runner.jar -H:FallbackThreshold=0 -H:+ReportExceptionStackTraces -J-Xmx10g -H:-AddAllCharsets -H:EnableURLProtocols=http,https --enable-all-security-services -H:-UseServiceLoaderFeature -H:+StackTrace ocpdeploy-4.6.2-SNAPSHOT-runner
[ocpdeploy-4.6.2-SNAPSHOT-runner:25]    classlist:   6,266.49 ms,  1.70 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:25]        (cap):     958.48 ms,  1.70 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:25]        setup:   3,337.74 ms,  1.70 GB
09:54:52,145 INFO  [org.hib.val.int.uti.Version] HV000001: Hibernate Validator 6.2.0.Final
09:55:54,974 INFO  [org.jbo.threads] JBoss Threads version 3.4.0.Final
[ocpdeploy-4.6.2-SNAPSHOT-runner:25]     (clinit):   3,295.47 ms,  4.02 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:25]   (typeflow):  46,486.08 ms,  4.02 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:25]    (objects):  86,260.07 ms,  4.02 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:25]   (features):   3,865.47 ms,  4.02 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:25]     analysis: 148,979.25 ms,  4.02 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:25]     universe:   6,957.66 ms,  4.20 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:25]      (parse):  35,647.83 ms,  4.95 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:25]     (inline):  14,977.32 ms,  6.09 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:25]    (compile):  57,364.48 ms,  7.36 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:25]      compile: 115,389.44 ms,  7.46 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:25]        image:  18,307.42 ms,  7.04 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:25]        write:   2,208.40 ms,  7.04 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:25]      [total]: 301,955.96 ms,  7.04 GB
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] docker run --env LANG=C --rm --user 2002:2002 -v /export/soft/appl/java-ocpdeploy/target/ocpdeploy-4.6.2-SNAPSHOT-native-image-source-jar:/project:z --entrypoint /bin/bash quay.io/quarkus/ubi-quarkus-native-image:21.0-java11 -c objcopy --strip-debug ocpdeploy-4.6.2-SNAPSHOT-runner
[INFO] [io.quarkus.deployment.QuarkusAugmentor] Quarkus augmentation completed in 309235ms


quarkus 2.0 GraalVM Version 21.1 (docker)
-------------------------

[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] Running Quarkus native-image plugin on GraalVM 21.1.0 Java 11 CE (Java Version 11.0.11+8-jvmci-21.1-b05)
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] docker run --env LANG=C --rm --user 2002:2002 -v /export/soft/appl/java-ocpdeploy/target/ocpdeploy-4.6.2-SNAPSHOT-native-image-source-jar:/project:z quay.io/quarkus/ubi-quarkus-native-image:21.1-java11 -J-Dsun.nio.ch.maxUpdateArraySize=100 -J-Djava.util.logging.manager=org.jboss.logmanager.LogManager -J-Dvertx.logger-delegate-factory-class-name=io.quarkus.vertx.core.runtime.VertxLogDelegateFactory -J-Dvertx.disableDnsResolver=true -J-Dio.netty.leakDetection.level=DISABLED -J-Dio.netty.allocator.maxOrder=3 -J-Duser.language=en -J-Duser.country=US -J-Dfile.encoding=UTF-8 -H:ReflectionConfigurationFiles=reflection-config.json --allow-incomplete-classpath -J-Djavax.net.ssl.trustStore=/project/trustStore -J-Djavax.net.ssl.trustStorePassword=changeit -H:DeadlockWatchdogInterval=30 --initialize-at-build-time= -H:InitialCollectionPolicy=com.oracle.svm.core.genscavenge.CollectionPolicy\$BySpaceAndTime -H:+JNI -H:+AllowFoldMethods -jar ocpdeploy-4.6.2-SNAPSHOT-runner.jar -H:FallbackThreshold=0 -H:+ReportExceptionStackTraces -J-Xmx10g -H:-AddAllCharsets -H:EnableURLProtocols=http,https -H:-UseServiceLoaderFeature -H:+StackTrace ocpdeploy-4.6.2-SNAPSHOT-runner
[ocpdeploy-4.6.2-SNAPSHOT-runner:26]    classlist:   6,828.57 ms,  1.69 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:26]        (cap):     750.35 ms,  1.69 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:26]        setup:   3,077.12 ms,  1.69 GB
10:01:25,701 INFO  [org.hib.val.int.uti.Version] HV000001: Hibernate Validator 6.2.0.Final
10:02:29,978 INFO  [org.jbo.threads] JBoss Threads version 3.4.0.Final
[ocpdeploy-4.6.2-SNAPSHOT-runner:26]     (clinit):   3,597.92 ms,  4.34 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:26]   (typeflow):  62,096.83 ms,  4.34 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:26]    (objects):  98,396.99 ms,  4.34 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:26]   (features):   4,292.26 ms,  4.34 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:26]     analysis: 177,948.75 ms,  4.34 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:26]     universe:   6,755.01 ms,  4.34 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:26]      (parse):  39,479.90 ms,  5.29 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:26]     (inline):  22,901.98 ms,  7.44 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:26]    (compile):  53,836.38 ms,  8.00 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:26]      compile: 124,294.53 ms,  8.00 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:26]        image:  23,701.33 ms,  7.57 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:26]        write:   2,608.13 ms,  7.57 GB
# Printing build artifacts to: ocpdeploy-4.6.2-SNAPSHOT-runner.build_artifacts.txt
[ocpdeploy-4.6.2-SNAPSHOT-runner:26]      [total]: 345,748.80 ms,  7.57 GB
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] docker run --env LANG=C --rm --user 2002:2002 -v /export/soft/appl/java-ocpdeploy/target/ocpdeploy-4.6.2-SNAPSHOT-native-image-source-jar:/project:z --entrypoint /bin/bash quay.io/quarkus/ubi-quarkus-native-image:21.1-java11 -c objcopy --strip-debug ocpdeploy-4.6.2-SNAPSHOT-runner
[INFO] [io.quarkus.deployment.QuarkusAugmentor] Quarkus augmentation completed in 386531ms

@vsevel
Copy link
Contributor Author

vsevel commented Jul 13, 2021

here is the case where the reports have been attached: https://access.redhat.com/support/cases/#/case/02987371

@stuartwdouglas
Copy link
Member

I am guessing that this is something to do with reflection registration for the kube API.
Can you attach reports for both 21.0 and 21.1 so we can compare them and see if there are additional classes being included (not sure which version the attached reports are)?

@vsevel
Copy link
Contributor Author

vsevel commented Jul 14, 2021

Hello @stuartwdouglas I have attached the following files to the case:

  • quarkus_1.13.7_graalvm_21.0.tar.gz
  • quarkus_2.0_graalvm_21.0.tar.gz
  • quarkus_2.0_graalvm_21.1.tar.gz

@stuartwdouglas
Copy link
Member

Between 21.1 and 21.0 the main difference seems to be a lot of these (almost 700 extra):

> com.oracle.svm.reflect.BoundMethodHandle$Species_LLIILLLLLLLL_argL1_8cbc57215dd70b6e79151961413d63724f6c6e9f
> com.oracle.svm.reflect.BoundMethodHandle$Species_LLIILLLLLLLL_argL4_e4a90c521bc32d642210059eb2cc17a7c5f69a60
> com.oracle.svm.reflect.BoundMethodHandle$Species_LLIILLLLLLLL_argL5_8e774d24c336718dd5058f95e8cb1f2c8d524de9
> com.oracle.svm.reflect.BoundMethodHandle$Species_LLIILLLLLLLL_argL6_1f2df249962f5b26c5dc82905c3c72374f125678
> com.oracle.svm.reflect.BoundMethodHandle$Species_LLIILLLLLLLL_argL7_b1110fee766756c52fb456adc3f4e0a9329fef91

@stuartwdouglas
Copy link
Member

Between 1.13 and 2.0 it appears way more of the kube API's get registered for reflection.

@vsevel
Copy link
Contributor Author

vsevel commented Jul 14, 2021

do you think this is going to increase with new apis getting supported?
we have fabric8io/kubernetes-client#2930 coming up with 5.5.
/cc @iocanel

@galderz
Copy link
Member

galderz commented Jul 14, 2021

@vsevel I've been looking at the discrepancies between GraalVM 21.1 and 21.0 and in particular those MethodHandle reflection registrations that @stuartwdouglas talked about. Looking at the call tree, it would seem to me that your code is using MethodHandles directly, can you confirm?

If that is the case, could you find a way to not use MethodHandles nor Reflection? We have plenty of experience in Quarkus in moving away from those, since they have a considerable cost. @stuartwdouglas and others can explain strategies that Quarkus uses to avoid the need for these, depending on the use case.

Do MethodHandles functionality work as expected in both 21.1 and 21.0 for your use case? I'm also trying to see what's exactly made them more expensive between these two versions.

@vsevel
Copy link
Contributor Author

vsevel commented Jul 14, 2021

your code is using MethodHandles directly

hi @galderz, that is not the case. in the smbj extension I wrote, I had to enable reflection for: SpnegoAuthenticator, Session, Connection, SMBClient, Pooled and ReflectiveHandlerInvocation for mbassador (used by smbj, which may be suspicious). for the other extension I wrote for logging, there is just one class used for configuration that does reflection.
then we have the few directives that we wrote for freemarker
we had to add java.util.Map in reflection-config.json for param -H:ReflectionConfigurationFiles (I do not remember why this was needed).

other than that we are using quarkus extensions only. we are using extensively fabric8 to deploy our openshift components to the cluster.

I am not sure anything matches your definition of using MethodHandle directly. I can share the complete code if needed. or I can start removing some dependencies and check how much it improves performance.

@iocanel
Copy link
Contributor

iocanel commented Jul 15, 2021

do you think this is going to increase with new apis getting supported?
we have fabric8io/kubernetes-client#2930 coming up with 5.5.
/cc @iocanel

The extension that are being added to the kubernetes-client are not included in the kubernetes-client extension. So, I don't see this been a problem.

@iocanel
Copy link
Contributor

iocanel commented Jul 15, 2021

Between 1.13 and 2.0 it appears way more of the kube API's get registered for reflection.

With a quick glimpse I only see some CustomResource related stuff. Is there something additional?

@vsevel
Copy link
Contributor Author

vsevel commented Jul 15, 2021

I have started commenting out code in the application, and ran multiple native builds on Quarkus 2.0 and GraalVM 21.1. I executed 2 builds for each code base (still I see some inconsistencies in some of the results; although the vm is the same and nothing else is running on it - I am going to another pass).

without toString means I commented out the toString() methods on all MP config objects. smbj and logserver are our extensions.

It seems there is some impact on the XConfig.toString() and an even bigger one on using fabric8. I wanted to share those early results, that need to be confirmed by another run.

base                [total]: 383,303.46 ms,  8.42 GB
                    [total]: 361,040.15 ms,  8.38 GB
without toString    [total]: 304,968.79 ms,  7.19 GB
                    [total]: 303,133.30 ms,  6.88 GB
remove smbj         [total]: 298,433.67 ms,  7.25 GB
                    [total]: 327,328.25 ms,  7.23 GB
remove logserver    [total]: 330,118.14 ms,  7.11 GB
                    [total]: 356,075.85 ms,  6.94 GB
remove fabric8      [total]: 116,685.15 ms,  6.12 GB
                    [total]: 111,834.35 ms,  5.15 GB

@galderz
Copy link
Member

galderz commented Jul 15, 2021

@vsevel Indeed your code does not use MethodHandles (sorry for the confusion). I think what is happening here is that you have some long String + concatenations, which in Java 11 can result in the JVM converting those to method handles calls (this article explains it). In 21.1 those seem to become heavier compared to 21.0. I'm building a reproducer to experiment with. @Sanne and @geoand are also seeing if there's other things Quarkus can do to improve things.

@galderz
Copy link
Member

galderz commented Jul 15, 2021

FYI: the JEP that brought the improvements to String concatenation.

@vsevel
Copy link
Contributor Author

vsevel commented Jul 15, 2021

here is the 2nd run:

base                [total]: 385,364.00 ms,  7.03 GB
                    [total]: 350,904.29 ms,  7.66 GB
without toString    [total]: 303,735.37 ms,  6.69 GB
                    [total]: 295,150.54 ms,  6.80 GB
remove smbj         [total]: 283,243.19 ms,  6.66 GB
                    [total]: 285,734.68 ms,  6.68 GB
remove logserver    [total]: 285,303.74 ms,  7.09 GB
                    [total]: 292,041.72 ms,  6.55 GB
remove fabric8      [total]: 110,944.92 ms,  5.98 GB
                    [total]: 109,655.26 ms,  5.83 GB

@vsevel
Copy link
Contributor Author

vsevel commented Jul 15, 2021

I think what is happening here is that you have some long String + concatenations, which in Java 11 can result in the JVM converting those to method handles calls

@galderz good point. would a StringBuilder be more appropriate? that is what people were doing in the old days. then concatenation was supposed to be as efficient (probably thanks to this JEP you are reffering to). but may be that is an anti-pattern in GraalV :(

@galderz
Copy link
Member

galderz commented Jul 15, 2021

@vsevel Yeah, it would be an anti-pattern and would likely perform worse on JVM mode, aside from being a pain having to change all those + to StringBuilder. We're definitely not asking your or any Quarkus user to do that. We're discussing options on Zulip (see the dev chat for this issue for ramblings on the topic).

@Sanne
Copy link
Member

Sanne commented Jul 16, 2021

Is it possible the Graal analysis is included classes in the result that implement an interface that is used, but it is not actually possible to instantiate them?

This is most likely triggered because all ResourceHandler s are being registered for reflection in KubernetesClientProcessor. Would be nice if it was possible to fine-tune this to only register the ones actually needed (and maybe this is?) or avoid reflection altogether.

@geoand
Copy link
Contributor

geoand commented Jul 16, 2021

Is it possible the Graal analysis is included classes in the result that implement an interface that is used, but it is not actually possible to instantiate them?

This is most likely triggered because all ResourceHandler s are being registered for reflection in KubernetesClientProcessor. Would be nice if it was possible to fine-tune this to only register the ones actually needed (and maybe this is?) or avoid reflection altogether.

I actually don't see us doing that in the processor

@Sanne
Copy link
Member

Sanne commented Jul 16, 2021

oh I confused ResourceEventHandler with ResourceHandler, sorry.

So I was looking for those, because of what Stuart said made me curious: I've never seen GraalVM include extra code just because it's implementing an interface w/o some specific reason; most often code is included only if the constructor is reacheable, or the class is registered for reflection.

But it's an interesting theory, we certainly have seen it become a little more sloppy with dead code elmination for the sake of making more code work OOB.

@stuartwdouglas
Copy link
Member

It's also possible the code I am using to do the analysis of the file has a bug, but I don't think so.

I am thinking about polishing it a bit and adding it to Dev UI, to hopefully allow you to do this sort of analysis in the browser.

@Sanne
Copy link
Member

Sanne commented Jul 16, 2021

Remember also that GraalVM is able to automatically register for reflection a class when the code is straight forward to analyze.

So for example if you just do load a class by class reference - and the parameter is a constant, or a trivial enough function which evaluates to a constant, it will register the class for reflection without us needing to do so explicitly.

This might be relevant, because when a class is registered for reflection then it seems to lose the context: the registered class becomes a "possible reasonable candidate" in every call point of its interfaces are invoked on - such as like @stuartwdouglas notices in this case.

Might be useful to look into the source code to find possible cases which trigger the automatic reflection? Or trace the reflective registrations, but include the ones automatically registered by GraalVM. I had done such things by blatantly adding some system.out lines to GraalVM but it's been a while.

In summary, in such cases we need to trace why the constructor is reachable (either by direct invocation somewhere, or reflections - automatic or implicit).

@stuartwdouglas
Copy link
Member

I don't think it is registered for reflection though, I can't see it in the report.

@Sanne
Copy link
Member

Sanne commented Jul 16, 2021

@stuartwdouglas which report are you looking at?

@vsevel
Copy link
Contributor Author

vsevel commented Jul 16, 2021

If this of any interest for this discussion, I did again the builds with 1.13/2.0, 21.0/21.1 and with the original code (i.e. full test) vs without the fabric8 code (which is a decent part of the app).
We can see that on the original codebase we go from 293 secs to 324. And without fabric8 openshift client there might be a bit of increase as well, but that is more subtle.
All tests were done with the string concatenation inlining option.

Quarkus 1.13 GraalVM 21.0

full test              [total]: 293,009.63 ms,  7.13 GB
without fabric8        [total]: 119,756.76 ms,  5.96 GB
without fabric8 (run2)[total]   127,779.39 ms,  5.97 GB

Quarkus 2.0 GraalVM 21.0

full test              [total]: 305,623.92 ms,  6.90 GB
without fabric8        [total]  117,790.62 ms,  6.04 GB
without fabric8 (run2) [total]  119,223.38 ms,  5.37 GB

Quarkus 2.0 GraalVM 21.1

full test              [total]: 324,427.19 ms,  7.33 GB
without fabric8        [total]  124,484.74 ms,  5.94 GB
without fabric8 (run2) [total]  128,329.16 ms,  6.10 GB

If you need me to produce a report for a given configuration, I will be happy to do so.

@vsevel
Copy link
Contributor Author

vsevel commented Jul 16, 2021

I forgot to mention that with the -XDstringConcat=inline and some extra RAM on 2.0, it is getting me roughly where I was with 1.13. so I consider my issue solved. I am happy to help out if I can however.

@Sanne
Copy link
Member

Sanne commented Jul 16, 2021

thanks @vsevel , great feedback.

We'll keep watching this and see what can be improved further; in particular we'll talk with the GraalVM team about the extra overhead caused by methodhandles but I'm not sure if they can do something about it. What Stuart mentiones is also interesting and we'll keep digging, but it's good to know that it's not critically urgent for you.

@Sanne
Copy link
Member

Sanne commented Jul 16, 2021

I guess an open question that we'll need to discuss is if Quarkus releases should be built with -XDstringConcat=inline across the board on all modules.

@galderz
Copy link
Member

galderz commented Jul 16, 2021

@vsevel @Sanne Re: string concat - I created a small reproducer and was able to get about 322 instances of the com.oracle.svm.reflect.BoundMethodHandle classes in it. I had a quick go with 21.2 (not yet released) and that's down to 41. So, I think -XDstringConcat=inline might be a temporary thing for 21.1 only, so maybe something @vsevel can temporarily use. 21.2 should be out on the 20th July.

@galderz
Copy link
Member

galderz commented Jul 16, 2021

FYI: Quarkus 2.1.x will use GraalVM 21.2 (see @gsmet's comment below)

@gsmet
Copy link
Member

gsmet commented Jul 16, 2021

Quarkus 2.1.x will use GraalVM 21.2

That's not a done thing. We build the Core artifacts on July 22nd so it will depend how fast we can build the images and get everything merged.

@galderz
Copy link
Member

galderz commented Jul 16, 2021

Also, some caveats about GraalVM 21.2. A few weeks back we discovered that it can increase compilation times and memory usage on memory constrained envs (see the great detective work by @zakkak here). @Foivos has added a patch to Quarkus in this respect (see here). As a result, if you want to try GraalVM 21.2, it's best to use a more recent version than Quarkus 2.0.x.

@zakkak
Copy link
Contributor

zakkak commented Jul 16, 2021

That's not a done thing. We build the Core artifacts on July 22nd so it will depend how fast we can build the images and get everything merged.

Agreed, it's highly unlikely to have everything in place on the 22nd.
Ideally we would like to bump to GraalVM 21.2 in Quarkus 2.1.1 or 2.1.2 to avoid having to wait for 2.2.x.
Note, however, that users should still be able to use GraalVM 21.2 the moment it gets released with Quarkus 2.1.0, it would just not be the default.

@vsevel
Copy link
Contributor Author

vsevel commented Jul 19, 2021

a quick note about the initial results I posted when I opened the issue: the test on 2.0 was especially bad because, I am convinced, the host was actually swapping. It was configured with 8Gb of RAM. and this was good enough for a single build on 1.13. But on 2.0, RAM usage increased slightly, which got us probably just above what was available given the other processes (e.g. maven, docker).
the other results I posted afterward did not suffer from this bias, because the new dedicated host I created for the tests had 16Gb right from the beginning. I applied this RAM config to the official CI host as well. That plus the -XDstringConcat=inline were the 2 things that got me back to the level of build time I had before.
I only realized that when I applied the -XDstringConcat=inline param on the official build on the CI host, and still was not able to to get the performances I was seeing on my test machine.
kind of treacherous.
thanks all for your investigations and help.

@galderz
Copy link
Member

galderz commented Jul 20, 2021

Also, some caveats about GraalVM 21.2. A few weeks back we discovered that it can increase compilation times and memory usage on memory constrained envs (see the great detective work by @zakkak here). @Foivos has added a patch to Quarkus in this respect (see here). As a result, if you want to try GraalVM 21.2, it's best to use a more recent version than Quarkus 2.0.x.

GraalVM 21.2.0 was just released. I was wondering if you could try your application with Quarkus 2.0.x and compare the results of time and memory with 21.2.0 and 21.1.0? One caveat: I'm unsure if Quarkus 2.0.x will work with 21.2.0. As mentioned above, support for GraalVM 21.2.x is expected for Quarkus 2.1.x.

@vsevel
Copy link
Contributor Author

vsevel commented Jul 21, 2021

I removed the -XDstringConcat=inline param. I executed 2 runs for each graalvm version. it seems there is an improvement for memory consumption (going from 6Gb to 5). for compilation time there may be an improvement, but it is less obvious: I got 146 and 137 secs for 21.1, and 128 and 138 secs for 21.2.

note: I did not test the app. I just compiled it.

run 1 GraalVM 21.1:

[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] Running Quarkus native-image plugin on GraalVM 21.1.0 Java 11 CE (Java Version 11.0.11+8-jvmci-21.1-b05)
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] /home/sevel/graalvm-ce-java11-21.1.0/bin/native-image -J-Dsun.nio.ch.maxUpdateArraySize=100 -J-Djava.util.logging.manager=org.jboss.logmanager.LogManager -J-Dvertx.logger-delegate-factory-class-name=io.quarkus.vertx.core.runtime.VertxLogDelegateFactory -J-Dvertx.disableDnsResolver=true -J-Dio.netty.leakDetection.level=DISABLED -J-Dio.netty.allocator.maxOrder=3 -J-Duser.language=en -J-Duser.country=US -J-Dfile.encoding=UTF-8 -H:ReflectionConfigurationFiles=reflection-config.json --allow-incomplete-classpath -J-Djavax.net.ssl.trustStore=LODHCAs.jks -J-Djavax.net.ssl.trustStorePassword=changeit -J-Djava.io.tmpdir=/home/sevel/tmpdir --initialize-at-build-time= -H:InitialCollectionPolicy=com.oracle.svm.core.genscavenge.CollectionPolicy\$BySpaceAndTime -H:+JNI -H:+AllowFoldMethods -jar ocpdeploy-4.6.2-SNAPSHOT-runner.jar -H:FallbackThreshold=0 -H:+ReportExceptionStackTraces -J-Xmx10g -H:-AddAllCharsets -H:EnableURLProtocols=http,https -H:-UseServiceLoaderFeature -H:+StackTrace ocpdeploy-4.6.2-SNAPSHOT-runner
[ocpdeploy-4.6.2-SNAPSHOT-runner:59550]    classlist:   4,879.20 ms,  1.18 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:59550]        (cap):     665.37 ms,  1.18 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:59550]        setup:   2,972.11 ms,  1.18 GB
18:38:19,068 INFO  [org.hib.val.int.uti.Version] HV000001: Hibernate Validator 6.2.0.Final
18:38:43,011 INFO  [org.jbo.threads] JBoss Threads version 3.4.0.Final
[ocpdeploy-4.6.2-SNAPSHOT-runner:59550]     (clinit):   1,642.39 ms,  4.32 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:59550]   (typeflow):  23,405.46 ms,  4.32 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:59550]    (objects):  34,951.35 ms,  4.32 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:59550]   (features):   1,926.31 ms,  4.32 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:59550]     analysis:  65,496.62 ms,  4.32 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:59550]     universe:   2,935.00 ms,  4.32 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:59550]      (parse):   5,892.88 ms,  4.34 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:59550]     (inline):  11,439.02 ms,  5.95 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:59550]    (compile):  33,511.46 ms,  6.08 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:59550]      compile:  55,803.00 ms,  6.08 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:59550]        image:   9,365.80 ms,  6.07 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:59550]        write:   1,162.99 ms,  6.07 GB
# Printing build artifacts to: ocpdeploy-4.6.2-SNAPSHOT-runner.build_artifacts.txt
[ocpdeploy-4.6.2-SNAPSHOT-runner:59550]      [total]: 143,059.44 ms,  6.07 GB
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] objcopy --strip-debug ocpdeploy-4.6.2-SNAPSHOT-runner
[INFO] [io.quarkus.deployment.QuarkusAugmentor] Quarkus augmentation completed in 146694ms

run 2 GraalVM 21.1:

[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] Running Quarkus native-image plugin on GraalVM 21.1.0 Java 11 CE (Java Version 11.0.11+8-jvmci-21.1-b05)
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] /home/sevel/graalvm-ce-java11-21.1.0/bin/native-image -J-Dsun.nio.ch.maxUpdateArraySize=100 -J-Djava.util.logging.manager=org.jboss.logmanager.LogManager -J-Dvertx.logger-delegate-factory-class-name=io.quarkus.vertx.core.runtime.VertxLogDelegateFactory -J-Dvertx.disableDnsResolver=true -J-Dio.netty.leakDetection.level=DISABLED -J-Dio.netty.allocator.maxOrder=3 -J-Duser.language=en -J-Duser.country=US -J-Dfile.encoding=UTF-8 -H:ReflectionConfigurationFiles=reflection-config.json --allow-incomplete-classpath -J-Djavax.net.ssl.trustStore=LODHCAs.jks -J-Djavax.net.ssl.trustStorePassword=changeit -J-Djava.io.tmpdir=/home/sevel/tmpdir --initialize-at-build-time= -H:InitialCollectionPolicy=com.oracle.svm.core.genscavenge.CollectionPolicy\$BySpaceAndTime -H:+JNI -H:+AllowFoldMethods -jar ocpdeploy-4.6.2-SNAPSHOT-runner.jar -H:FallbackThreshold=0 -H:+ReportExceptionStackTraces -J-Xmx10g -H:-AddAllCharsets -H:EnableURLProtocols=http,https -H:-UseServiceLoaderFeature -H:+StackTrace ocpdeploy-4.6.2-SNAPSHOT-runner
[ocpdeploy-4.6.2-SNAPSHOT-runner:60062]    classlist:   3,997.54 ms,  1.19 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:60062]        (cap):     640.34 ms,  1.19 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:60062]        setup:   3,073.63 ms,  1.19 GB
18:41:44,221 INFO  [org.hib.val.int.uti.Version] HV000001: Hibernate Validator 6.2.0.Final
18:42:06,831 INFO  [org.jbo.threads] JBoss Threads version 3.4.0.Final
[ocpdeploy-4.6.2-SNAPSHOT-runner:60062]     (clinit):   1,571.91 ms,  4.31 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:60062]   (typeflow):  23,438.80 ms,  4.31 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:60062]    (objects):  32,466.26 ms,  4.31 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:60062]   (features):   1,957.83 ms,  4.31 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:60062]     analysis:  62,278.03 ms,  4.31 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:60062]     universe:   2,852.71 ms,  4.34 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:60062]      (parse):   6,092.76 ms,  4.34 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:60062]     (inline):  11,479.59 ms,  5.98 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:60062]    (compile):  29,366.42 ms,  6.10 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:60062]      compile:  51,341.73 ms,  6.10 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:60062]        image:   9,373.72 ms,  6.06 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:60062]        write:   1,158.31 ms,  6.06 GB
# Printing build artifacts to: ocpdeploy-4.6.2-SNAPSHOT-runner.build_artifacts.txt
[ocpdeploy-4.6.2-SNAPSHOT-runner:60062]      [total]: 134,502.54 ms,  6.06 GB
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] objcopy --strip-debug ocpdeploy-4.6.2-SNAPSHOT-runner
[INFO] [io.quarkus.deployment.QuarkusAugmentor] Quarkus augmentation completed in 137927ms



----

run 1 GraalVM 21.2:

[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] Running Quarkus native-image plugin on GraalVM 21.2.0 Java 11 CE (Java Version 11.0.12+6-jvmci-21.2-b08)
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] /home/sevel/graalvm-ce-java11-21.2.0/bin/native-image -J-Dsun.nio.ch.maxUpdateArraySize=100 -J-Djava.util.logging.manager=org.jboss.logmanager.LogManager -J-Dvertx.logger-delegate-factory-class-name=io.quarkus.vertx.core.runtime.VertxLogDelegateFactory -J-Dvertx.disableDnsResolver=true -J-Dio.netty.leakDetection.level=DISABLED -J-Dio.netty.allocator.maxOrder=3 -J-Duser.language=en -J-Duser.country=US -J-Dfile.encoding=UTF-8 -H:ReflectionConfigurationFiles=reflection-config.json --allow-incomplete-classpath -J-Djavax.net.ssl.trustStore=LODHCAs.jks -J-Djavax.net.ssl.trustStorePassword=changeit -J-Djava.io.tmpdir=/home/sevel/tmpdir --initialize-at-build-time= -H:InitialCollectionPolicy=com.oracle.svm.core.genscavenge.CollectionPolicy\$BySpaceAndTime -H:+JNI -H:+AllowFoldMethods -jar ocpdeploy-4.6.2-SNAPSHOT-runner.jar -H:FallbackThreshold=0 -H:+ReportExceptionStackTraces -J-Xmx10g -H:-AddAllCharsets -H:EnableURLProtocols=http,https -H:-UseServiceLoaderFeature -H:+StackTrace ocpdeploy-4.6.2-SNAPSHOT-runner
[ocpdeploy-4.6.2-SNAPSHOT-runner:59085]    classlist:   4,192.41 ms,  1.19 GB
--initialize-at-build-time without arguments has been deprecated and will be removed in GraalVM 22.0.
[ocpdeploy-4.6.2-SNAPSHOT-runner:59085]        (cap):     638.71 ms,  1.19 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:59085]        setup:   2,706.60 ms,  1.19 GB
The bundle named: ContributorValidationMessages, has not been found. If the bundle is part of a module, verify the bundle name is a fully qualified class name. Otherwise verify the bundle path is accessible in the classpath.
The bundle named: ValidationMessages, has not been found. If the bundle is part of a module, verify the bundle name is a fully qualified class name. Otherwise verify the bundle path is accessible in the classpath.
18:35:27,024 INFO  [org.hib.val.int.uti.Version] HV000001: Hibernate Validator 6.2.0.Final
18:35:47,553 INFO  [org.jbo.threads] JBoss Threads version 3.4.0.Final
[ocpdeploy-4.6.2-SNAPSHOT-runner:59085]     (clinit):   1,686.62 ms,  4.86 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:59085]   (typeflow):  29,305.58 ms,  4.86 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:59085]    (objects):  20,202.25 ms,  4.86 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:59085]   (features):   1,925.02 ms,  4.86 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:59085]     analysis:  55,839.34 ms,  4.86 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:59085]     universe:   4,300.88 ms,  4.97 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:59085]      (parse):   5,028.17 ms,  4.79 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:59085]     (inline):   4,489.71 ms,  4.88 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:59085]    (compile):  32,976.19 ms,  4.91 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:59085]      compile:  46,634.45 ms,  4.91 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:59085]        image:   9,297.23 ms,  4.93 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:59085]        write:   1,033.58 ms,  4.93 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:59085]      [total]: 124,484.13 ms,  4.93 GB
# Printing build artifacts to: /export/soft/appl/java-ocpdeploy/target/ocpdeploy-4.6.2-SNAPSHOT-native-image-source-jar/ocpdeploy-4.6.2-SNAPSHOT-runner.build_artifacts.txt
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] objcopy --strip-debug ocpdeploy-4.6.2-SNAPSHOT-runner
[INFO] [io.quarkus.deployment.QuarkusAugmentor] Quarkus augmentation completed in 128005ms

run 2 GraalVM 21.2:

[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] Running Quarkus native-image plugin on GraalVM 21.2.0 Java 11 CE (Java Version 11.0.12+6-jvmci-21.2-b08)
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] /home/sevel/graalvm-ce-java11-21.2.0/bin/native-image -J-Dsun.nio.ch.maxUpdateArraySize=100 -J-Djava.util.logging.manager=org.jboss.logmanager.LogManager -J-Dvertx.logger-delegate-factory-class-name=io.quarkus.vertx.core.runtime.VertxLogDelegateFactory -J-Dvertx.disableDnsResolver=true -J-Dio.netty.leakDetection.level=DISABLED -J-Dio.netty.allocator.maxOrder=3 -J-Duser.language=en -J-Duser.country=US -J-Dfile.encoding=UTF-8 -H:ReflectionConfigurationFiles=reflection-config.json --allow-incomplete-classpath -J-Djavax.net.ssl.trustStore=LODHCAs.jks -J-Djavax.net.ssl.trustStorePassword=changeit -J-Djava.io.tmpdir=/home/sevel/tmpdir --initialize-at-build-time= -H:InitialCollectionPolicy=com.oracle.svm.core.genscavenge.CollectionPolicy\$BySpaceAndTime -H:+JNI -H:+AllowFoldMethods -jar ocpdeploy-4.6.2-SNAPSHOT-runner.jar -H:FallbackThreshold=0 -H:+ReportExceptionStackTraces -J-Xmx10g -H:-AddAllCharsets -H:EnableURLProtocols=http,https -H:-UseServiceLoaderFeature -H:+StackTrace ocpdeploy-4.6.2-SNAPSHOT-runner
[ocpdeploy-4.6.2-SNAPSHOT-runner:60563]    classlist:   5,020.41 ms,  1.18 GB
--initialize-at-build-time without arguments has been deprecated and will be removed in GraalVM 22.0.
[ocpdeploy-4.6.2-SNAPSHOT-runner:60563]        (cap):     727.93 ms,  1.18 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:60563]        setup:   3,253.23 ms,  1.18 GB
The bundle named: ContributorValidationMessages, has not been found. If the bundle is part of a module, verify the bundle name is a fully qualified class name. Otherwise verify the bundle path is accessible in the classpath.
The bundle named: ValidationMessages, has not been found. If the bundle is part of a module, verify the bundle name is a fully qualified class name. Otherwise verify the bundle path is accessible in the classpath.
18:44:47,952 INFO  [org.hib.val.int.uti.Version] HV000001: Hibernate Validator 6.2.0.Final
18:45:11,466 INFO  [org.jbo.threads] JBoss Threads version 3.4.0.Final
[ocpdeploy-4.6.2-SNAPSHOT-runner:60563]     (clinit):   1,530.19 ms,  4.89 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:60563]   (typeflow):  33,851.95 ms,  4.89 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:60563]    (objects):  24,316.09 ms,  4.89 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:60563]   (features):   1,938.34 ms,  4.89 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:60563]     analysis:  64,775.57 ms,  4.89 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:60563]     universe:   4,404.02 ms,  5.08 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:60563]      (parse):   2,186.69 ms,  5.08 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:60563]     (inline):   6,726.74 ms,  4.77 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:60563]    (compile):  33,185.76 ms,  5.02 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:60563]      compile:  46,217.29 ms,  5.02 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:60563]        image:   9,070.72 ms,  5.08 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:60563]        write:   1,113.03 ms,  5.08 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:60563]      [total]: 134,403.00 ms,  5.08 GB
# Printing build artifacts to: /export/soft/appl/java-ocpdeploy/target/ocpdeploy-4.6.2-SNAPSHOT-native-image-source-jar/ocpdeploy-4.6.2-SNAPSHOT-runner.build_artifacts.txt
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] objcopy --strip-debug ocpdeploy-4.6.2-SNAPSHOT-runner
[INFO] [io.quarkus.deployment.QuarkusAugmentor] Quarkus augmentation completed in 138301ms

@stuartwdouglas
Copy link
Member

Any chance you could test out this PR: #19115

It should help a lot (assuming it actually works, but the kube client tests passed for me locally).

With the integration tests it halved the binary size and more than halved the compile time.

@vsevel
Copy link
Contributor Author

vsevel commented Jul 30, 2021

hello @stuartwdouglas . here are the results. all tests done with -XDstringConcat=inline and GraalVM 21.1.0 Java 11 CE (Java Version 11.0.11+8-jvmci-21.1-b05)

---
Quarkus 2.1.0

run1

[INFO] --- quarkus-maven-plugin:2.1.0.Final:build (default) @ ocpdeploy ---
[INFO] [org.jboss.threads] JBoss Threads version 3.4.0.Final
[WARNING] [io.quarkus.arc.deployment.SplitPackageProcessor] Detected a split package usage which is considered a bad practice and should be avoided. Following packages were detected in multiple archives:
- "io.fabric8.openshift.api.model" found in [io.fabric8:openshift-model, io.fabric8:openshift-model-operator]
[INFO] [io.quarkus.deployment.pkg.steps.JarResultBuildStep] Building native image source jar: /export/soft/appl/java-ocpdeploy/target/ocpdeploy-4.6.2-SNAPSHOT-native-image-source-jar/ocpdeploy-4.6.2-SNAPSHOT-runner.jar
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] Building native image from /export/soft/appl/java-ocpdeploy/target/ocpdeploy-4.6.2-SNAPSHOT-native-image-source-jar/ocpdeploy-4.6.2-SNAPSHOT-runner.jar
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] Running Quarkus native-image plugin on GraalVM 21.1.0 Java 11 CE (Java Version 11.0.11+8-jvmci-21.1-b05)
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] /home/sevel/graalvm-ce-java11-21.1.0/bin/native-image -J-Dsun.nio.ch.maxUpdateArraySize=100 -J-Djava.util.logging.manager=org.jboss.logmanager.LogManager -J-Dvertx.logger-delegate-factory-class-name=io.quarkus.vertx.core.runtime.VertxLogDelegateFactory -J-Dvertx.disableDnsResolver=true -J-Dio.netty.leakDetection.level=DISABLED -J-Dio.netty.allocator.maxOrder=3 -J-Duser.language=en -J-Duser.country=US -J-Dfile.encoding=UTF-8 -H:ReflectionConfigurationFiles=reflection-config.json --allow-incomplete-classpath -J-Djavax.net.ssl.trustStore=LODHCAs.jks -J-Djavax.net.ssl.trustStorePassword=changeit -J-Djava.io.tmpdir=/home/sevel/tmpdir/ -H:InitialCollectionPolicy=com.oracle.svm.core.genscavenge.CollectionPolicy\$BySpaceAndTime -H:+JNI -H:+AllowFoldMethods -jar ocpdeploy-4.6.2-SNAPSHOT-runner.jar -H:FallbackThreshold=0 -H:+ReportExceptionStackTraces -J-Xmx10g -H:-AddAllCharsets -H:EnableURLProtocols=http,https -H:-UseServiceLoaderFeature -H:+StackTrace ocpdeploy-4.6.2-SNAPSHOT-runner
[ocpdeploy-4.6.2-SNAPSHOT-runner:14714]    classlist:   6,216.84 ms,  1.49 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:14714]        (cap):     641.81 ms,  1.49 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:14714]        setup:   3,028.75 ms,  1.49 GB
17:29:23,302 INFO  [org.hib.val.int.uti.Version] HV000001: Hibernate Validator 6.2.0.Final
17:30:41,951 INFO  [org.jbo.threads] JBoss Threads version 3.4.0.Final
[ocpdeploy-4.6.2-SNAPSHOT-runner:14714]     (clinit):   5,491.14 ms,  4.62 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:14714]   (typeflow):  65,642.06 ms,  4.62 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:14714]    (objects): 144,395.87 ms,  4.62 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:14714]   (features):   6,307.85 ms,  4.62 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:14714]     analysis: 238,641.83 ms,  4.62 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:14714]     universe:  11,447.45 ms,  4.65 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:14714]      (parse):  62,387.32 ms,  5.40 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:14714]     (inline):  19,201.57 ms,  6.81 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:14714]    (compile):  58,408.67 ms,  8.57 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:14714]      compile: 148,868.46 ms,  8.57 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:14714]        image:  30,385.63 ms,  8.38 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:14714]        write:   2,442.00 ms,  8.38 GB
# Printing build artifacts to: ocpdeploy-4.6.2-SNAPSHOT-runner.build_artifacts.txt
[ocpdeploy-4.6.2-SNAPSHOT-runner:14714]      [total]: 441,593.76 ms,  8.38 GB
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] objcopy --strip-debug ocpdeploy-4.6.2-SNAPSHOT-runner
[INFO] [io.quarkus.deployment.QuarkusAugmentor] Quarkus augmentation completed in 446158ms

run2

[INFO] --- quarkus-maven-plugin:2.1.0.Final:build (default) @ ocpdeploy ---
[INFO] [org.jboss.threads] JBoss Threads version 3.4.0.Final
[WARNING] [io.quarkus.arc.deployment.SplitPackageProcessor] Detected a split package usage which is considered a bad practice and should be avoided. Following packages were detected in multiple archives:
- "io.fabric8.openshift.api.model" found in [io.fabric8:openshift-model, io.fabric8:openshift-model-operator]
[INFO] [io.quarkus.deployment.pkg.steps.JarResultBuildStep] Building native image source jar: /export/soft/appl/java-ocpdeploy/target/ocpdeploy-4.6.2-SNAPSHOT-native-image-source-jar/ocpdeploy-4.6.2-SNAPSHOT-runner.jar
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] Building native image from /export/soft/appl/java-ocpdeploy/target/ocpdeploy-4.6.2-SNAPSHOT-native-image-source-jar/ocpdeploy-4.6.2-SNAPSHOT-runner.jar
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] Running Quarkus native-image plugin on GraalVM 21.1.0 Java 11 CE (Java Version 11.0.11+8-jvmci-21.1-b05)
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] /home/sevel/graalvm-ce-java11-21.1.0/bin/native-image -J-Dsun.nio.ch.maxUpdateArraySize=100 -J-Djava.util.logging.manager=org.jboss.logmanager.LogManager -J-Dvertx.logger-delegate-factory-class-name=io.quarkus.vertx.core.runtime.VertxLogDelegateFactory -J-Dvertx.disableDnsResolver=true -J-Dio.netty.leakDetection.level=DISABLED -J-Dio.netty.allocator.maxOrder=3 -J-Duser.language=en -J-Duser.country=US -J-Dfile.encoding=UTF-8 -H:ReflectionConfigurationFiles=reflection-config.json --allow-incomplete-classpath -J-Djavax.net.ssl.trustStore=LODHCAs.jks -J-Djavax.net.ssl.trustStorePassword=changeit -J-Djava.io.tmpdir=/home/sevel/tmpdir/ -H:InitialCollectionPolicy=com.oracle.svm.core.genscavenge.CollectionPolicy\$BySpaceAndTime -H:+JNI -H:+AllowFoldMethods -jar ocpdeploy-4.6.2-SNAPSHOT-runner.jar -H:FallbackThreshold=0 -H:+ReportExceptionStackTraces -J-Xmx10g -H:-AddAllCharsets -H:EnableURLProtocols=http,https -H:-UseServiceLoaderFeature -H:+StackTrace ocpdeploy-4.6.2-SNAPSHOT-runner
[ocpdeploy-4.6.2-SNAPSHOT-runner:15589]    classlist:   6,661.07 ms,  1.70 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:15589]        (cap):     624.42 ms,  1.70 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:15589]        setup:   2,987.99 ms,  1.70 GB
17:37:51,273 INFO  [org.hib.val.int.uti.Version] HV000001: Hibernate Validator 6.2.0.Final
17:39:02,195 INFO  [org.jbo.threads] JBoss Threads version 3.4.0.Final
[ocpdeploy-4.6.2-SNAPSHOT-runner:15589]     (clinit):   4,371.57 ms,  4.65 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:15589]   (typeflow):  61,885.56 ms,  4.65 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:15589]    (objects): 105,599.21 ms,  4.65 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:15589]   (features):   5,227.62 ms,  4.65 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:15589]     analysis: 188,662.41 ms,  4.65 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:15589]     universe:   8,390.53 ms,  4.63 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:15589]      (parse):  58,398.97 ms,  5.69 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:15589]     (inline):  18,383.00 ms,  7.15 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:15589]    (compile):  54,423.37 ms,  7.71 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:15589]      compile: 139,810.08 ms,  7.72 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:15589]        image:  30,039.82 ms,  6.65 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:15589]        write:   2,410.60 ms,  6.68 GB
# Printing build artifacts to: ocpdeploy-4.6.2-SNAPSHOT-runner.build_artifacts.txt
[ocpdeploy-4.6.2-SNAPSHOT-runner:15589]      [total]: 379,509.13 ms,  6.68 GB
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] objcopy --strip-debug ocpdeploy-4.6.2-SNAPSHOT-runner
[INFO] [io.quarkus.deployment.QuarkusAugmentor] Quarkus augmentation completed in 384172ms

-rwxrwx---. 1 sevel sevel 180417584 Jul 30 17:44 ocpdeploy-4.6.2-SNAPSHOT-runner


---
Quarkus999-SNAPSHOT weak-reflection


run1

[INFO] --- quarkus-maven-plugin:999-SNAPSHOT:build (default) @ ocpdeploy ---
[INFO] [org.jboss.threads] JBoss Threads version 3.4.0.Final
[WARNING] [io.quarkus.arc.deployment.SplitPackageProcessor] Detected a split package usage which is considered a bad practice and should be avoided. Following packages were detected in multiple archives:
- "io.fabric8.openshift.api.model" found in [io.fabric8:openshift-model-operator::jar, io.fabric8:openshift-model::jar]
[INFO] [io.quarkus.deployment.pkg.steps.JarResultBuildStep] Building native image source jar: /export/soft/appl/java-ocpdeploy/target/ocpdeploy-4.6.2-SNAPSHOT-native-image-source-jar/ocpdeploy-4.6.2-SNAPSHOT-runner.jar
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] Building native image from /export/soft/appl/java-ocpdeploy/target/ocpdeploy-4.6.2-SNAPSHOT-native-image-source-jar/ocpdeploy-4.6.2-SNAPSHOT-runner.jar
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] Running Quarkus native-image plugin on GraalVM 21.1.0 Java 11 CE (Java Version 11.0.11+8-jvmci-21.1-b05)
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] /home/sevel/graalvm-ce-java11-21.1.0/bin/native-image -J-Dsun.nio.ch.maxUpdateArraySize=100 -J-Djava.util.logging.manager=org.jboss.logmanager.LogManager -J-Dvertx.logger-delegate-factory-class-name=io.quarkus.vertx.core.runtime.VertxLogDelegateFactory -J-Dvertx.disableDnsResolver=true -J-Dio.netty.leakDetection.level=DISABLED -J-Dio.netty.allocator.maxOrder=3 -J-Duser.language=en -J-Duser.country=US -J-Dfile.encoding=UTF-8 -H:ReflectionConfigurationFiles=reflection-config.json --allow-incomplete-classpath -J-Djavax.net.ssl.trustStore=LODHCAs.jks -J-Djavax.net.ssl.trustStorePassword=changeit -J-Djava.io.tmpdir=/home/sevel/tmpdir/ -H:InitialCollectionPolicy=com.oracle.svm.core.genscavenge.CollectionPolicy\$BySpaceAndTime -H:+JNI -H:+AllowFoldMethods -jar ocpdeploy-4.6.2-SNAPSHOT-runner.jar -H:FallbackThreshold=0 -H:+ReportExceptionStackTraces -J-Xmx10g -H:-AddAllCharsets -H:EnableURLProtocols=http,https -H:-UseServiceLoaderFeature -H:+StackTrace ocpdeploy-4.6.2-SNAPSHOT-runner
[ocpdeploy-4.6.2-SNAPSHOT-runner:12791]    classlist:   6,111.54 ms,  1.69 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:12791]        (cap):     837.45 ms,  1.69 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:12791]        setup:   3,321.63 ms,  1.69 GB
17:13:40,731 INFO  [org.hib.val.int.uti.Version] HV000001: Hibernate Validator 6.2.0.Final
17:14:11,028 INFO  [org.jbo.threads] JBoss Threads version 3.4.0.Final
[ocpdeploy-4.6.2-SNAPSHOT-runner:12791]     (clinit):   4,952.00 ms,  4.49 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:12791]   (typeflow):  45,662.54 ms,  4.49 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:12791]    (objects):  90,881.26 ms,  4.49 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:12791]   (features):   4,809.52 ms,  4.49 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:12791]     analysis: 157,267.76 ms,  4.49 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:12791]     universe:   8,606.57 ms,  4.49 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:12791]      (parse):  50,846.27 ms,  5.35 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:12791]     (inline):  18,911.82 ms,  6.91 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:12791]    (compile):  53,764.64 ms,  7.38 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:12791]      compile: 131,984.22 ms,  7.38 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:12791]        image:  27,970.90 ms,  7.17 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:12791]        write:   2,417.74 ms,  7.17 GB
# Printing build artifacts to: ocpdeploy-4.6.2-SNAPSHOT-runner.build_artifacts.txt
[ocpdeploy-4.6.2-SNAPSHOT-runner:12791]      [total]: 338,346.86 ms,  7.17 GB
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] objcopy --strip-debug ocpdeploy-4.6.2-SNAPSHOT-runner
[INFO] [io.quarkus.deployment.QuarkusAugmentor] Quarkus augmentation completed in 343315ms


run2

[INFO] --- quarkus-maven-plugin:999-SNAPSHOT:build (default) @ ocpdeploy ---
[INFO] [org.jboss.threads] JBoss Threads version 3.4.0.Final
[WARNING] [io.quarkus.arc.deployment.SplitPackageProcessor] Detected a split package usage which is considered a bad practice and should be avoided. Following packages were detected in multiple archives:
- "io.fabric8.openshift.api.model" found in [io.fabric8:openshift-model-operator::jar, io.fabric8:openshift-model::jar]
[INFO] [io.quarkus.deployment.pkg.steps.JarResultBuildStep] Building native image source jar: /export/soft/appl/java-ocpdeploy/target/ocpdeploy-4.6.2-SNAPSHOT-native-image-source-jar/ocpdeploy-4.6.2-SNAPSHOT-runner.jar
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] Building native image from /export/soft/appl/java-ocpdeploy/target/ocpdeploy-4.6.2-SNAPSHOT-native-image-source-jar/ocpdeploy-4.6.2-SNAPSHOT-runner.jar
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] Running Quarkus native-image plugin on GraalVM 21.1.0 Java 11 CE (Java Version 11.0.11+8-jvmci-21.1-b05)
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] /home/sevel/graalvm-ce-java11-21.1.0/bin/native-image -J-Djava.util.logging.manager=org.jboss.logmanager.LogManager -J-Dsun.nio.ch.maxUpdateArraySize=100 -J-Dvertx.logger-delegate-factory-class-name=io.quarkus.vertx.core.runtime.VertxLogDelegateFactory -J-Dvertx.disableDnsResolver=true -J-Dio.netty.leakDetection.level=DISABLED -J-Dio.netty.allocator.maxOrder=3 -J-Duser.language=en -J-Duser.country=US -J-Dfile.encoding=UTF-8 -H:ReflectionConfigurationFiles=reflection-config.json --allow-incomplete-classpath -J-Djavax.net.ssl.trustStore=LODHCAs.jks -J-Djavax.net.ssl.trustStorePassword=changeit -J-Djava.io.tmpdir=/home/sevel/tmpdir/ -H:InitialCollectionPolicy=com.oracle.svm.core.genscavenge.CollectionPolicy\$BySpaceAndTime -H:+JNI -H:+AllowFoldMethods -jar ocpdeploy-4.6.2-SNAPSHOT-runner.jar -H:FallbackThreshold=0 -H:+ReportExceptionStackTraces -J-Xmx10g -H:-AddAllCharsets -H:EnableURLProtocols=http,https -H:-UseServiceLoaderFeature -H:+StackTrace ocpdeploy-4.6.2-SNAPSHOT-runner
[ocpdeploy-4.6.2-SNAPSHOT-runner:13549]    classlist:   6,215.18 ms,  1.71 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:13549]        (cap):     679.29 ms,  1.71 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:13549]        setup:   3,082.10 ms,  1.71 GB
17:20:26,545 INFO  [org.hib.val.int.uti.Version] HV000001: Hibernate Validator 6.2.0.Final
17:20:56,585 INFO  [org.jbo.threads] JBoss Threads version 3.4.0.Final
[ocpdeploy-4.6.2-SNAPSHOT-runner:13549]     (clinit):   4,058.54 ms,  4.59 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:13549]   (typeflow):  44,187.27 ms,  4.59 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:13549]    (objects):  85,681.54 ms,  4.59 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:13549]   (features):   7,091.97 ms,  4.59 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:13549]     analysis: 151,597.97 ms,  4.59 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:13549]     universe:   8,404.22 ms,  4.58 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:13549]      (parse):  48,885.92 ms,  5.35 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:13549]     (inline):  23,184.45 ms,  7.41 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:13549]    (compile):  51,893.42 ms,  7.81 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:13549]      compile: 132,231.50 ms,  7.81 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:13549]        image:  27,206.16 ms,  7.46 GB
[ocpdeploy-4.6.2-SNAPSHOT-runner:13549]        write:   2,348.91 ms,  7.46 GB
# Printing build artifacts to: ocpdeploy-4.6.2-SNAPSHOT-runner.build_artifacts.txt
[ocpdeploy-4.6.2-SNAPSHOT-runner:13549]      [total]: 331,691.72 ms,  7.46 GB
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] objcopy --strip-debug ocpdeploy-4.6.2-SNAPSHOT-runner
[INFO] [io.quarkus.deployment.QuarkusAugmentor] Quarkus augmentation completed in 336438ms


-rwxrwx---. 1 sevel sevel 175690800 Jul 30 17:19 ocpdeploy-4.6.2-SNAPSHOT-runner

@stuartwdouglas
Copy link
Member

So not as big a gain as we have seen elsewhere, but still a nice win.

@galderz
Copy link
Member

galderz commented Aug 16, 2021

I've been doing some benchmarking of Quarkus getting started app (the HTTP REST one) with different GraalVM versions, including latest master commits, and while I was away graalvm master appears to have made considerably improvements to memory consumption:

21.3-dev looks like this today:
Screen Shot 2021-08-16 at 12 31 21

Compared with 21.2.0:
Screen Shot 2021-08-16 at 12 32 07

The memory consumption is still higher than 20.3.3, but 21.3-dev is (in an unconstrained env), the fastest version for building Quarkus getting started app:

Screen Shot 2021-08-16 at 12 34 51

21.3-dev was not looking this good before I went away, so I'll be combing through the commits to see what's changed. I'm sure @Sanne will enjoy the gory details :)

@galderz
Copy link
Member

galderz commented Aug 16, 2021

One more detail from the screenshots above: my testing corroborates the big regression found by @vsevel above with 21.1.0, which is the slowest version of the ones I compared.

@geoand
Copy link
Contributor

geoand commented Nov 9, 2021

Is this still an issue? Especially now that GraalVM has moved to 21.3.

@vsevel
Copy link
Contributor Author

vsevel commented Nov 9, 2021

probably not. question is: should I remove <compilerArgument>-XDstringConcat=inline</compilerArgument>?
let me run a few builds, and check that build time does not increase again. I am in 2.4.1, so Running Quarkus native-image plugin on GraalVM 21.2.0 Java 11 CE (Java Version 11.0.12+6-jvmci-21.2-b08)
or should I wait for 2.5?

@zakkak
Copy link
Contributor

zakkak commented Nov 10, 2021

let me run a few builds, and check that build time does not increase again

That would be nice, especially using GraalVM 21.3

or should I wait for 2.5?

If you don't want to wait for 2.5 you could give 2.4.1 a go with 21.3, just make sure you use -Dquarkus.native.builder-image=quay.io/quarkus/ubi-quarkus-native-image:21.3-java11 and -Dquarkus.native.additional-build-args=-H:-ParseOnce (see #21018 for more details).

@vsevel
Copy link
Contributor Author

vsevel commented Nov 10, 2021

I did as you suggested. with 21.3, I see the same build time with or without option <compilerArgument>-XDstringConcat=inline</compilerArgument>:

  • without the option: 3min26s, 3min26s, 3min28s for the native part
  • with the option: 4min16s, 3min22s, 3min27s, 3min15s

builds were done using Running Quarkus native-image plugin on GraalVM 21.3.0 Java 11 CE (Java Version 11.0.13+7-jvmci-21.3-b05).
I am closing this issue. Thanks all for the work around this topic.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
kind/bug Something isn't working
Projects
None yet
Development

No branches or pull requests

8 participants