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.

Sign up for GitHub

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

Jump to bottom

Mandrel slower than corresponding GraalVM CE #288

Closed
zakkak opened this issue Sep 17, 2021 · 15 comments
Closed

Mandrel slower than corresponding GraalVM CE #288

zakkak opened this issue Sep 17, 2021 · 15 comments
Labels
enhancement New feature or request not-Stale

Comments

@zakkak
Copy link
Collaborator

zakkak commented Sep 17, 2021 •
edited
Loading

Description

Mandrel 21.2.0.0-Final appears to be slower than GraalVM 21.2.0 (311s vs 229s)

How To Reproduce

Steps to reproduce the behavior:

GRAALVM_HOME=/opt/jvms/mandrel-java11-21.2.0.0-Final ./mvnw -B --settings .github/mvn-settings.xml --fail-at-end  -DfailIfNoTests=false -Dnative -Dnative.surefire.skip -Dformat.skip -Dno-descriptor-tests -DskipDocs -Dquarkus.container-image.build=false -pl integration-tests/main verify

GRAALVM_HOME=/opt/jvms/graalvm-ce-java11-21.2.0 ./mvnw -B --settings .github/mvn-settings.xml --fail-at-end  -DfailIfNoTests=false -Dnative -Dnative.surefire.skip -Dformat.skip -Dno-descriptor-tests -DskipDocs -Dquarkus.container-image.build=false -pl integration-tests/main verify

Configuration:

  • OS: Fedora 34]
  • Architecture: AMD64
  • Mandrel version: 21.2.0.0-Final
  • JDK version: OpenJDK 11.0.12+7

Expected behavior

Compilation times should be similar.

Additional context

The output of the first command (Mandrel) is:

[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] Building native image from /home/zakkak/code/quarkus/integration-tests/main/target/quarkus-integration-test-main-999-SNAPSHOT-native-image-source-jar/quarkus-integration-test-main-999-SNAPSHOT-runner.jar
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] Running Quarkus native-image plugin on native-image 21.2.0.0-Final Mandrel Distribution (Java Version 11.0.12+7)
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] /opt/jvms/mandrel-java11-21.2.0.0-Final/bin/native-image -J-Dsun.nio.ch.maxUpdateArraySize=100 -J-Djava.util.logging.manager=org.jboss.logmanager.LogManager -J-DCoordinatorEnvironmentBean.transactionStatusManagerEnable=false -J-Dcom.sun.xml.bind.v2.bytecode.ClassTailor.noOptimize=true -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=IE -J-Dfile.encoding=UTF-8 -H:ReflectionConfigurationFiles=reflection-config.json -H:InitialCollectionPolicy=com.oracle.svm.core.genscavenge.CollectionPolicy\$BySpaceAndTime -H:+JNI -H:+AllowFoldMethods -H:FallbackThreshold=0 -H:+ReportExceptionStackTraces -H:+AddAllCharsets -H:EnableURLProtocols=http -H:NativeLinkerOption=-no-pie -H:-UseServiceLoaderFeature -H:+StackTrace -H:-ParseOnce quarkus-integration-test-main-999-SNAPSHOT-runner -jar quarkus-integration-test-main-999-SNAPSHOT-runner.jar
[quarkus-integration-test-main-999-SNAPSHOT-runner:177475]    classlist:  16,873.43 ms,  2.31 GB
[quarkus-integration-test-main-999-SNAPSHOT-runner:177475]        (cap):     548.36 ms,  3.25 GB
[quarkus-integration-test-main-999-SNAPSHOT-runner:177475]        setup:   3,408.61 ms,  3.25 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.
The bundle named: messages, 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.
15:04:21,004 INFO  [org.hib.val.int.uti.Version] HV000001: Hibernate Validator 6.2.0.Final
15:04:21,181 INFO  [org.hib.Version] HHH000412: Hibernate ORM core version 5.6.0.Beta1
15:04:21,187 INFO  [org.hib.ann.com.Version] HCANN000001: Hibernate Commons Annotations {5.1.2.Final}
15:04:21,232 INFO  [org.hib.dia.Dialect] HHH000400: Using dialect: org.hibernate.dialect.PostgreSQL95Dialect
15:04:21,319 INFO  [io.und.websockets] UT026003: Adding annotated server endpoint class io.quarkus.it.websocket.RecodingSocket for path /recoder
15:04:21,321 INFO  [io.und.websockets] UT026003: Adding annotated server endpoint class io.quarkus.it.websocket.WebSocketOpenEndpoint for path /wsopen
15:04:21,321 INFO  [io.und.websockets] UT026003: Adding annotated server endpoint class io.quarkus.it.websocket.EchoSocket for path /echo
15:04:21,322 INFO  [io.und.websockets] UT026004: Adding annotated client endpoint class io.quarkus.it.websocket.CodingClient
15:04:22,999 WARNING [org.apa.tik.par.PDFParser] J2KImageReader not loaded. JPEG2000 files will not be processed.
See https://pdfbox.apache.org/2.0/dependencies.html#jai-image-io
for optional dependencies.

15:04:23,007 WARNING [org.apa.tik.par.ocr.TesseractOCRParser] Tesseract OCR is installed and will be automatically applied to image files unless
you've excluded the TesseractOCRParser from the default parser.
Tesseract may dramatically slow down content extraction (TIKA-2359).
As of Tika 1.15 (and prior versions), Tesseract is automatically called.
In future versions of Tika, users may need to turn the TesseractOCRParser on via TikaConfig.
15:04:23,034 INFO  [io.und.websockets] UT026005: Adding programmatic server endpoint class io.quarkus.it.websocket.AddWebSocketHandler$WebSocketEndpoint for path /added-dynamic
15:05:12,280 INFO  [org.jbo.threads] JBoss Threads version 3.4.2.Final
[quarkus-integration-test-main-999-SNAPSHOT-runner:177475]     (clinit):   1,690.93 ms,  6.07 GB
[quarkus-integration-test-main-999-SNAPSHOT-runner:177475]   (typeflow):  62,559.09 ms,  6.07 GB
[quarkus-integration-test-main-999-SNAPSHOT-runner:177475]    (objects):  60,629.69 ms,  6.07 GB
[quarkus-integration-test-main-999-SNAPSHOT-runner:177475]   (features):   3,203.98 ms,  6.07 GB
[quarkus-integration-test-main-999-SNAPSHOT-runner:177475]     analysis: 131,736.20 ms,  6.07 GB
[quarkus-integration-test-main-999-SNAPSHOT-runner:177475]     universe:   5,593.85 ms,  6.07 GB
[quarkus-integration-test-main-999-SNAPSHOT-runner:177475]      (parse):  15,934.57 ms,  6.09 GB
[quarkus-integration-test-main-999-SNAPSHOT-runner:177475]     (inline):  18,287.54 ms,  6.18 GB
[quarkus-integration-test-main-999-SNAPSHOT-runner:177475]    (compile):  95,243.41 ms,  7.40 GB
[quarkus-integration-test-main-999-SNAPSHOT-runner:177475]      compile: 134,187.23 ms,  7.41 GB
[quarkus-integration-test-main-999-SNAPSHOT-runner:177475]        image:  16,202.11 ms,  7.52 GB
[quarkus-integration-test-main-999-SNAPSHOT-runner:177475]        write:   1,728.17 ms,  7.52 GB
[quarkus-integration-test-main-999-SNAPSHOT-runner:177475]      [total]: 311,351.87 ms,  7.52 GB

The output of the second command (GraalVM) is:

INFO] [io.quarkus.deployment.pkg.steps.JarResultBuildStep] Building native image source jar: /home/zakkak/code/quarkus/integration-tests/main/target/quarkus-integration-test-main-999-SNAPSHOT-native-image-source-jar/quarkus-integration-test-main-999-SNAPSHOT-runner.jar
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] Building native image from /home/zakkak/code/quarkus/integration-tests/main/target/quarkus-integration-test-main-999-SNAPSHOT-native-image-source-jar/quarkus-integration-test-main-999-SNAPSHOT-runner.jar
[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] /opt/jvms/graalvm-ce-java11-21.2.0/bin/native-image -J-Dcom.sun.xml.bind.v2.bytecode.ClassTailor.noOptimize=true -J-Dsun.nio.ch.maxUpdateArraySize=100 -J-DCoordinatorEnvironmentBean.transactionStatusManagerEnable=false -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=IE -J-Dfile.encoding=UTF-8 -H:ReflectionConfigurationFiles=reflection-config.json -H:InitialCollectionPolicy=com.oracle.svm.core.genscavenge.CollectionPolicy\$BySpaceAndTime -H:+JNI -H:+AllowFoldMethods -H:FallbackThreshold=0 -H:+ReportExceptionStackTraces -H:+AddAllCharsets -H:EnableURLProtocols=http -H:NativeLinkerOption=-no-pie -H:-UseServiceLoaderFeature -H:+StackTrace -H:-ParseOnce quarkus-integration-test-main-999-SNAPSHOT-runner -jar quarkus-integration-test-main-999-SNAPSHOT-runner.jar
[quarkus-integration-test-main-999-SNAPSHOT-runner:178571]    classlist:  13,091.09 ms,  2.70 GB
[quarkus-integration-test-main-999-SNAPSHOT-runner:178571]        (cap):     474.16 ms,  2.70 GB
[quarkus-integration-test-main-999-SNAPSHOT-runner:178571]        setup:   3,509.55 ms,  2.70 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.
The bundle named: messages, 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.
15:10:18,426 INFO  [org.hib.val.int.uti.Version] HV000001: Hibernate Validator 6.2.0.Final
15:10:18,619 INFO  [org.hib.Version] HHH000412: Hibernate ORM core version 5.6.0.Beta1
15:10:18,625 INFO  [org.hib.ann.com.Version] HCANN000001: Hibernate Commons Annotations {5.1.2.Final}
15:10:18,669 INFO  [org.hib.dia.Dialect] HHH000400: Using dialect: org.hibernate.dialect.PostgreSQL95Dialect
15:10:18,761 INFO  [io.und.websockets] UT026003: Adding annotated server endpoint class io.quarkus.it.websocket.WebSocketOpenEndpoint for path /wsopen
15:10:18,763 INFO  [io.und.websockets] UT026004: Adding annotated client endpoint class io.quarkus.it.websocket.CodingClient
15:10:18,766 INFO  [io.und.websockets] UT026003: Adding annotated server endpoint class io.quarkus.it.websocket.RecodingSocket for path /recoder
15:10:18,767 INFO  [io.und.websockets] UT026003: Adding annotated server endpoint class io.quarkus.it.websocket.EchoSocket for path /echo
15:10:19,423 WARNING [org.apa.tik.par.PDFParser] J2KImageReader not loaded. JPEG2000 files will not be processed.
See https://pdfbox.apache.org/2.0/dependencies.html#jai-image-io
for optional dependencies.

15:10:19,431 WARNING [org.apa.tik.par.ocr.TesseractOCRParser] Tesseract OCR is installed and will be automatically applied to image files unless
you've excluded the TesseractOCRParser from the default parser.
Tesseract may dramatically slow down content extraction (TIKA-2359).
As of Tika 1.15 (and prior versions), Tesseract is automatically called.
In future versions of Tika, users may need to turn the TesseractOCRParser on via TikaConfig.
15:10:19,455 INFO  [io.und.websockets] UT026005: Adding programmatic server endpoint class io.quarkus.it.websocket.AddWebSocketHandler$WebSocketEndpoint for path /added-dynamic
15:10:52,782 INFO  [org.jbo.threads] JBoss Threads version 3.4.2.Final
[quarkus-integration-test-main-999-SNAPSHOT-runner:178571]     (clinit):   1,586.60 ms,  6.06 GB
[quarkus-integration-test-main-999-SNAPSHOT-runner:178571]   (typeflow):  45,695.57 ms,  6.06 GB
[quarkus-integration-test-main-999-SNAPSHOT-runner:178571]    (objects):  44,458.65 ms,  6.06 GB
[quarkus-integration-test-main-999-SNAPSHOT-runner:178571]   (features):   2,503.66 ms,  6.06 GB
[quarkus-integration-test-main-999-SNAPSHOT-runner:178571]     analysis:  97,672.51 ms,  6.06 GB
[quarkus-integration-test-main-999-SNAPSHOT-runner:178571]     universe:   4,290.03 ms,  6.06 GB
[quarkus-integration-test-main-999-SNAPSHOT-runner:178571]      (parse):  11,002.55 ms,  6.11 GB
[quarkus-integration-test-main-999-SNAPSHOT-runner:178571]     (inline):  15,538.43 ms,  6.67 GB
[quarkus-integration-test-main-999-SNAPSHOT-runner:178571]    (compile):  63,691.70 ms,  7.57 GB
[quarkus-integration-test-main-999-SNAPSHOT-runner:178571]      compile:  95,437.04 ms,  7.57 GB
[quarkus-integration-test-main-999-SNAPSHOT-runner:178571]        image:  12,573.18 ms,  7.69 GB
[quarkus-integration-test-main-999-SNAPSHOT-runner:178571]        write:   1,156.36 ms,  7.69 GB
[quarkus-integration-test-main-999-SNAPSHOT-runner:178571]      [total]: 229,302.43 ms,  7.69 GB
@zakkak zakkak added the bug Something isn't working label Sep 17, 2021
@zakkak
Copy link
Collaborator Author

zakkak commented Sep 17, 2021

The issue is possibly related to oracle#3697

@zakkak
Copy link
Collaborator Author

zakkak commented Sep 17, 2021

After some more runs it looks like the difference is closer to 270s vs220s which is still significant. And the issue is reproducible with Mandrel 21.0.0.1-Final as well.

@jerboaa
Copy link
Collaborator

jerboaa commented Sep 17, 2021

Note the difference in heap space. Shorter runs use more heap.

@zakkak
Copy link
Collaborator Author

zakkak commented Sep 21, 2021 •
edited
Loading

After some more experimentation it looks like this is related to the fact that Mandrel is not using libgraal.
To explore that, I performed a number of runs with GraalVM CE 21.2 disabling libgraal (-XX:-UseJVMCINativeLibrary) and the Graal JIT (-XX:-UseJVMCICompiler).

The results are listed in the table bellow (3 runs of each configuration):

Run Mandrel 21.2.0.0-Final GraalVM CE 21.2.0 GraalVM CE -XX:-UseJVMCINativeLibrary GraalVM CE -XX:-UseJVMCINativeLibrary -XX:-UseJVMCICompiler
1 270,740.46 ms
7.75 GB		 219,455.65 ms
7.65 GB		 299,634.69 ms
7.63 GB		 251,934.78 ms
7.89 GB
2 268,983.27 ms
7.41 GB		 219,422.77 ms
7.48 GB		 293,751.67 ms
7.48 GB		 248,699.72 ms
7.81 GB
3 258,601.58 ms
7.57 GB		 221,123.44 ms
7.77 GB		 303,444.17 ms
7.64 GB		 254,998.79 ms
7.44 GB

It's clear that when GraalVM CE is run with -XX:-UseJVMCINativeLibrary -XX:-UseJVMCICompiler, i.e., uses C1/C2 as the JIT compiler for the native-image Java process and graal.jar only as the backend for generating the native binary, it behaves more similar to Mandrel. We still see it performing slightly better, but as the measurements were done on a laptop I don't really trust them to make conclusions with only 3 runs.

This behavior is reproducible with prior Mandrel versions, so maybe we should consider whether Mandrel should start using libgraal as well.

@zakkak zakkak changed the title Mandrel 21.2.0.0-Final slower than GraalVM 21.2.0 Mandrel slower than corresponding GraalVM CE Sep 23, 2021
@zakkak
Copy link
Collaborator Author

zakkak commented Sep 23, 2021

... so maybe we should consider whether Mandrel should start using libgraal as well.

Using libgraal in Mandrel for Java 11 seems a no-go as libgraal depends heavily on JVMCI changes that are not available in OpenJDK 11. Moving to Java 17 we could reconsider this.

@zakkak zakkak added enhancement New feature or request and removed bug Something isn't working labels Sep 23, 2021
@jerboaa
Copy link
Collaborator

jerboaa commented Sep 30, 2021

Yes, I've reproduced this. ~20% slower build times.

@jerboaa
Copy link
Collaborator

jerboaa commented Sep 30, 2021

On the flip side I've seen libgraal making a difference in memory consumption in constrained environments. Running with -XX:-UseJVMCINativeLibrary -XX:-UseJVMCICompiler does no longer get the build killed (in a container with limits).

Graal VM CE 21.2 (via quay.io/quarkus/ubi-quarkus-native-image:21.2-java11):

$ sudo podman run --cpu-quota=300000 --cpu-period=100000 --memory=4G --memory-swap=4G --userns=keep-id --user=$(id -u) --entrypoint /bin/bash -v $(pwd):/project:z 253554a3d3e0 -c 'bash run_build.sh'
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:23]    classlist:  18,946.87 ms,  1.68 GB 1.25 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:23]        (cap):     490.97 ms,  1.68 GB 1.27 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:23]        setup:   2,306.70 ms,  1.68 GB 1.28 GB (VmRSS)
The bundle named: messages, 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.
17:03:32,458 INFO  [org.hib.Version] HHH000412: Hibernate ORM core version 5.5.7.Final
17:03:32,536 INFO  [org.hib.ann.com.Version] HCANN000001: Hibernate Commons Annotations {5.1.2.Final}
17:03:32,815 INFO  [org.hib.dia.Dialect] HHH000400: Using dialect: io.quarkus.hibernate.orm.runtime.dialect.QuarkusPostgreSQL10Dialect
17:04:41,837 INFO  [org.jbo.threads] JBoss Threads version 3.4.2.Final
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:23]     (clinit):   1,303.60 ms,  2.87 GB 3.79 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:23]   (typeflow): 100,846.47 ms,  2.87 GB 3.80 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:23]    (objects):  70,522.13 ms,  2.87 GB 3.80 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:23]   (features):   1,378.58 ms,  2.87 GB 3.80 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:23]     analysis: 179,092.17 ms,  2.87 GB 3.80 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:23]     universe:   6,512.90 ms,  2.88 GB 3.79 GB (VmRSS)
Error: Image build request failed with exit status 137
$ sudo podman images | grep 253554a3d3e0
quay.io/quarkus/ubi-quarkus-native-image             21.2-java11  253554a3d3e0  2 weeks ago   1.25 GB

Graal VM CE 21.2 with -XX:-UseJVMCINativeLibrary -XX:-UseJVMCICompiler:

$ sudo podman run --cpu-quota=300000 --cpu-period=100000 --memory=4G --memory-swap=4G --userns=keep-id --user=$(id -u) --entrypoint /bin/bash -v $(pwd):/project:z 253554a3d3e0 -c 'bash run_build.sh'
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:23]    classlist:  15,552.22 ms,  1.69 GB 0.97 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:23]        (cap):     436.54 ms,  1.69 GB 1.00 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:23]        setup:   2,429.24 ms,  1.69 GB 1.01 GB (VmRSS)
The bundle named: messages, 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.
17:18:04,546 INFO  [org.hib.Version] HHH000412: Hibernate ORM core version 5.5.7.Final
17:18:04,641 INFO  [org.hib.ann.com.Version] HCANN000001: Hibernate Commons Annotations {5.1.2.Final}
17:18:04,739 INFO  [org.hib.dia.Dialect] HHH000400: Using dialect: io.quarkus.hibernate.orm.runtime.dialect.QuarkusPostgreSQL10Dialect
17:19:14,645 INFO  [org.jbo.threads] JBoss Threads version 3.4.2.Final
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:23]     (clinit):   1,355.11 ms,  2.90 GB 3.52 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:23]   (typeflow):  98,272.00 ms,  2.90 GB 3.52 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:23]    (objects):  84,651.15 ms,  2.90 GB 3.52 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:23]   (features):   1,488.91 ms,  2.90 GB 3.52 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:23]     analysis: 188,123.33 ms,  2.90 GB 3.52 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:23]     universe:   6,611.26 ms,  2.90 GB 3.52 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:23]      (parse):  14,570.44 ms,  2.85 GB 3.75 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:23]     (inline):  18,789.42 ms,  2.85 GB 3.76 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:23]    (compile): 148,249.41 ms,  3.04 GB 3.73 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:23]      compile: 184,890.07 ms,  3.04 GB 3.73 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:23]        image:  10,247.45 ms,  2.90 GB 3.77 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:23]        write:   1,514.47 ms,  2.90 GB 3.77 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:23]      [total]: 409,815.01 ms,  2.90 GB 3.77 GB (VmRSS)
# Printing build artifacts to: /project/spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner.build_artifacts.txt

Mandrel 21.2 (via quay.io/quarkus/ubi-quarkus-mandrel:21.2-java11):

$ sudo podman run --cpu-quota=300000 --cpu-period=100000 --memory=4G --memory-swap=4G --userns=keep-id --user=$(id -u) --entrypoint /bin/bash -v $(pwd):/project:z bcb7fd481b9d -c 'bash run_build.sh'
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:47]    classlist:  15,819.63 ms,  1.19 GB 0.71 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:47]        (cap):     691.90 ms,  1.19 GB 0.73 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:47]        setup:   2,464.19 ms,  1.19 GB 0.74 GB (VmRSS)
The bundle named: messages, 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.
17:07:37,727 INFO  [org.hib.Version] HHH000412: Hibernate ORM core version 5.5.7.Final
17:07:37,812 INFO  [org.hib.ann.com.Version] HCANN000001: Hibernate Commons Annotations {5.1.2.Final}
17:07:38,044 INFO  [org.hib.dia.Dialect] HHH000400: Using dialect: io.quarkus.hibernate.orm.runtime.dialect.QuarkusPostgreSQL10Dialect
17:09:02,211 INFO  [org.jbo.threads] JBoss Threads version 3.4.2.Final
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:47]     (clinit):   1,169.83 ms,  3.02 GB 3.49 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:47]   (typeflow): 118,958.38 ms,  3.02 GB 3.49 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:47]    (objects):  91,161.64 ms,  3.02 GB 3.49 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:47]   (features):   1,574.82 ms,  3.02 GB 3.49 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:47]     analysis: 215,031.84 ms,  3.02 GB 3.49 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:47]     universe:   7,198.35 ms,  3.02 GB 3.53 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:47]      (parse):  23,000.72 ms,  2.84 GB 3.76 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:47]     (inline):  21,371.34 ms,  2.83 GB 3.70 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:47]    (compile): 214,593.69 ms,  3.04 GB 3.74 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:47]      compile: 261,936.51 ms,  3.04 GB 3.74 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:47]        image:   9,250.12 ms,  2.98 GB 3.78 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:47]        write:   1,459.14 ms,  2.98 GB 3.77 GB (VmRSS)
[spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner:47]      [total]: 513,565.72 ms,  2.98 GB 3.77 GB (VmRSS)
# Printing build artifacts to: /project/spring-to-quarkus-todo-0.0.1-SNAPSHOT-runner.build_artifacts.txt

@jerboaa
Copy link
Collaborator

jerboaa commented Oct 1, 2021

For reference. run_build.sh is a tiny script to get the VmRSS from /proc/self/status when the image build runs driven via the native-sources feature (native-image.args file) of quarkus:

native-image $(cat native-image.args) | while read line; do echo -n "$line"; pid=$(echo "$line" | grep '^\[' | awk '{ print $1 }' | sed 's/\[//g' | sed 's/\]//g' | cut -d':' -f2); if [ "${pid}_" != "_" ]; then grep VmRSS /proc/$pid/status | awk '{ print $2 }' | awk '{ val=$1 / 1024; val=val/1024; printf "%5.2f GB (VmRSS)\n", val }'; else echo; fi; done

@jerboaa
Copy link
Collaborator

jerboaa commented Oct 1, 2021

Resident set size is sometimes lower than reported Heap capacity due to lazy commit of the kernel. -XX:+AlwaysPreTouch removes that issue in reporting.

@zakkak zakkak mentioned this issue Oct 20, 2021
Closed
@github-actions
Copy link

github-actions bot commented Nov 1, 2021

This issue appears to be stale because it has been open 30 days with no activity. This issue will be closed in 7 days unless Stale label is removed, a new comment is made, or not-Stale label is added.

@github-actions github-actions bot added the Stale label Nov 1, 2021
@zakkak zakkak added not-Stale and removed Stale labels Nov 1, 2021
@jerboaa
Copy link
Collaborator

jerboaa commented Nov 2, 2021

Resident set size is sometimes lower than reported Heap capacity due to lazy commit of the kernel. -XX:+AlwaysPreTouch removes that issue in reporting.

Correction. Current implementation of memory reporting uses Runtime.getRuntime().totalMemory() which amounts to the heap capacity (as opposed to heap usage). When it's being switched to heap usage, then this issue isn't present. -XX:+AlwaysPreTouch is a work-around for making the GC operating-system-commit full heap capacity. Hence, the change in reporting.

@zakkak
Copy link
Collaborator Author

zakkak commented Dec 2, 2022

Running similar experiments with 22.3 I see that the difference is now smaller (~6% when comparing the average execution time of 5 runs). On these 5 runs Mandrel appears to have slightly bigger Peak RSS as well (~200MB on average).

I think we can close this issue at this point.

@zakkak zakkak mentioned this issue May 22, 2023
Closed
@zakkak
Copy link
Collaborator Author

zakkak commented May 23, 2023

The ~6% difference still stands for 22.3.2

Raw numbers from 10 runs of 5 configurations:

  • graal-default is using the graalvmce builder image without additional options
  • graal-nolib-graal is passing -J-XX:+UseJVMCINativeLibrary
  • graal-nolib-nograal is passing -XX:-UseJVMCINativeLibrary and -J-XX:-UseJVMCICompiler
  • mandrel-default is using the mandrel builder image without additional options
  • mandrel-graaljit is passing -J-XX:+UseJVMCICompiler
configuration total_time total_memory
0 graal-default 55538 7521435648
1 graal-default 56685 7219445760
2 graal-default 56161 7413432320
3 graal-default 55923 7400325120
4 graal-default 55290 7597981696
5 graal-default 55738 7566000128
6 graal-default 57507 7573864448
7 graal-default 55233 7501512704
8 graal-default 54862 7529824256
9 graal-default 56027 7438598144
10 graal-nolib-graal 60765 7885291520
11 graal-nolib-graal 60352 6984040448
12 graal-nolib-graal 59214 7720140800
13 graal-nolib-graal 59976 7832338432
14 graal-nolib-graal 58724 7773093888
15 graal-nolib-graal 59305 7204765696
16 graal-nolib-graal 59855 7347896320
17 graal-nolib-graal 58220 7459045376
18 graal-nolib-graal 58151 7366246400
19 graal-nolib-graal 59452 6779043840
20 graal-nolib-nograal 57023 7424442368
21 graal-nolib-nograal 58114 7389839360
22 graal-nolib-nograal 56685 7326924800
23 graal-nolib-nograal 57912 7593263104
24 graal-nolib-nograal 58215 7597981696
25 graal-nolib-nograal 57905 7150239744
26 graal-nolib-nograal 57399 7499415552
27 graal-nolib-nograal 58418 7571243008
28 graal-nolib-nograal 58627 7696547840
29 graal-nolib-nograal 59014 7319584768
30 mandrel-default 60614 6977224704
31 mandrel-default 63803 7253000192
32 mandrel-default 58275 7184318464
33 mandrel-default 59046 7400325120
34 mandrel-default 59313 7155482624
35 mandrel-default 58466 7033847808
36 mandrel-default 58093 7178027008
37 mandrel-default 58489 7192707072
38 mandrel-default 57934 7217348608
39 mandrel-default 58059 7178551296
40 mandrel-graaljit 57836 7087849472
41 mandrel-graaljit 59676 7119306752
42 mandrel-graaljit 58819 7343702016
43 mandrel-graaljit 58393 7308050432
44 mandrel-graaljit 58283 7231504384
45 mandrel-graaljit 58914 7267680256
46 mandrel-graaljit 58166 7297040384
47 mandrel-graaljit 57023 7320633344
48 mandrel-graaljit 58759 7326924800
49 mandrel-graaljit 58859 6896484352

@jerboaa
Copy link
Collaborator

jerboaa commented May 23, 2023

In order to do "fair" comparisons, there might be other flags which could have some effect. Using -XX:+PrintFlagsFinal on the jlinked graal java and mandrel java (which is stock Temurin JDK) I see a few differences:

$ diff -u graal_ce_javaflags.txt mandrel_javaflags.txt 
--- graal_ce_javaflags.txt	2023-05-23 12:04:00.545041883 +0200
+++ mandrel_javaflags.txt	2023-05-23 12:16:28.181482629 +0200
@@ -71,7 +71,7 @@
      intx CompileThreshold                         = 10000                                  {pd product} {default}
    double CompileThresholdScaling                  = 1.000000                                  {product} {default}
      intx CompilerThreadPriority                   = -1                                        {product} {default}
-     intx CompilerThreadStackSize                  = 2048                                   {pd product} {default}
+     intx CompilerThreadStackSize                  = 1024                                   {pd product} {default}
    size_t CompressedClassSpaceSize                 = 1073741824                                {product} {default}
      uint ConcGCThreads                            = 3                                         {product} {ergonomic}
      intx ConditionalMoveLimit                     = 3                                   {C2 pd product} {default}
@@ -94,7 +94,6 @@
      bool DumpReplayDataOnError                    = true                                      {product} {default}
      bool DumpSharedSpaces                         = false                                     {product} {default}
      bool DynamicDumpSharedSpaces                  = false                                     {product} {default}
-     bool EagerJVMCI                               = false                               {JVMCI product} {default}
      bool EagerXrunInit                            = false                                     {product} {default}
      intx EliminateAllocationArraySizeLimit        = 64                                     {C2 product} {default}
      bool EliminateAllocations                     = true                                   {C2 product} {default}
@@ -103,8 +102,6 @@
      bool EliminateNestedLocks                     = true                                   {C2 product} {default}
      bool EnableContended                          = true                                      {product} {default}
      bool EnableDynamicAgentLoading                = true                                      {product} {default}
-     bool EnableJVMCI                              = true                                {JVMCI product} {default}
-     bool EnableJVMCIProduct                       = true                                {JVMCI product} {jimage}
    size_t ErgoHeapSizeLimit                        = 0                                         {product} {default}
     ccstr ErrorFile                                =                                           {product} {default}
      bool ErrorFileToStderr                        = false                                     {product} {default}
@@ -178,23 +175,10 @@
     uintx InitiatingHeapOccupancyPercent           = 45                                        {product} {default}
      bool Inline                                   = true                                      {product} {default}
     ccstr InlineDataFile                           =                                           {product} {default}
-     intx InlineSmallCode                          = 1000                                {C2 pd product} {default}
+     intx InlineSmallCode                          = 2500                                {C2 pd product} {default}
      bool InlineSynchronizedMethods                = true                                   {C1 product} {default}
      intx InteriorEntryAlignment                   = 16                                  {C2 pd product} {default}
      intx InterpreterProfilePercentage             = 33                                        {product} {default}
-     uint JVMCICompilerIdleDelay                   = 1000                                {JVMCI product} {default}
-     intx JVMCICounterSize                         = 0                                   {JVMCI product} {default}
-     bool JVMCICountersExcludeCompiler             = true                                {JVMCI product} {default}
-     intx JVMCIEventLogLevel                       = 1                                   {JVMCI product} {default}
-    ccstr JVMCILibDumpJNIConfig                    =                                     {JVMCI product} {default}
-    ccstr JVMCILibPath                             =                                     {JVMCI product} {default}
-     intx JVMCINMethodSizeLimit                    = 655360                              {JVMCI product} {default}
-    ccstr JVMCINativeLibraryErrorFile              =                                     {JVMCI product} {default}
-   double JVMCINativeLibraryThreadFraction         = 0.330000                            {JVMCI product} {default}
-     bool JVMCIPrintProperties                     = false                               {JVMCI product} {default}
-     intx JVMCIThreads                             = 1                                   {JVMCI product} {default}
-     uint JVMCIThreadsPerNativeLibraryRuntime      = 1                                   {JVMCI product} {jimage}
-     intx JVMCITraceLevel                          = 0                                   {JVMCI product} {default}
      bool JavaMonitorsInStackTrace                 = true                                      {product} {default}
      intx JavaPriority10_To_OSPriority             = -1                                        {product} {default}
      intx JavaPriority1_To_OSPriority              = -1                                        {product} {default}
@@ -279,8 +263,8 @@
    size_t NewSizeThreadIncrease                    = 5320                                   {pd product} {default}
      intx NmethodSweepActivity                     = 10                                        {product} {default}
      intx NodeLimitFudgeFactor                     = 2000                                   {C2 product} {default}
-    uintx NonNMethodCodeHeapSize                   = 6979620                                {pd product} {ergonomic}
-    uintx NonProfiledCodeHeapSize                  = 122339310                              {pd product} {ergonomic}
+    uintx NonNMethodCodeHeapSize                   = 5839372                                {pd product} {ergonomic}
+    uintx NonProfiledCodeHeapSize                  = 122909434                              {pd product} {ergonomic}
      intx NumberOfLoopInstrToAlign                 = 4                                      {C2 product} {default}
      intx ObjectAlignmentInBytes                   = 8                              {product lp64_product} {default}
    size_t OldPLABSize                              = 1024                                      {product} {default}
@@ -352,7 +336,7 @@
     uintx ProcessDistributionStride                = 4                                         {product} {default}
      bool ProfileInterpreter                       = true                                   {pd product} {default}
      intx ProfileMaturityPercentage                = 20                                        {product} {default}
-    uintx ProfiledCodeHeapSize                     = 122339310                              {pd product} {ergonomic}
+    uintx ProfiledCodeHeapSize                     = 122909434                              {pd product} {ergonomic}
     uintx PromotedPadding                          = 3                                         {product} {default}
     uintx QueuedAllocationWarningCount             = 0                                         {product} {default}
       int RTMRetryCount                            = 5                                    {ARCH product} {default}
@@ -386,6 +370,8 @@
    size_t SharedBaseAddress                        = 34359738368                               {product} {default}
     ccstr SharedClassListFile                      =                                           {product} {default}
     uintx SharedSymbolTableBucketSize              = 4                                         {product} {default}
+    ccstr ShenandoahGCHeuristics                   = adaptive                                  {product} {default}
+    ccstr ShenandoahGCMode                         = satb                                      {product} {default}
      bool ShowCodeDetailsInExceptionMessages       = true                                   {manageable} {default}
      bool ShowMessageBoxOnError                    = false                                     {product} {default}
      bool ShrinkHeapInSteps                        = true                                      {product} {default}
@@ -419,7 +405,7 @@
     uintx TenuredGenerationSizeIncrement           = 20                                        {product} {default}
     uintx TenuredGenerationSizeSupplement          = 80                                        {product} {default}
     uintx TenuredGenerationSizeSupplementDecay     = 2                                         {product} {default}
-     intx ThreadPriorityPolicy                     = 1                                         {product} {jimage}
+     intx ThreadPriorityPolicy                     = 0                                         {product} {default}
      bool ThreadPriorityVerbose                    = false                                     {product} {default}
      intx ThreadStackSize                          = 1024                                   {pd product} {default}
     uintx ThresholdTolerance                       = 10                                        {product} {default}
@@ -456,10 +442,10 @@
      bool TrapBasedNullChecks                      = false                                  {pd product} {default}
      bool TrapBasedRangeChecks                     = false                               {C2 pd product} {default}
      intx TypeProfileArgsLimit                     = 2                                         {product} {default}
-    uintx TypeProfileLevel                         = 0                                      {pd product} {default}
+    uintx TypeProfileLevel                         = 111                                    {pd product} {default}
      intx TypeProfileMajorReceiverPercent          = 90                                     {C2 product} {default}
      intx TypeProfileParmsLimit                    = 2                                         {product} {default}
-     intx TypeProfileWidth                         = 8                                         {product} {default}
+     intx TypeProfileWidth                         = 2                                         {product} {default}
      intx UnguardOnExecutionViolation              = 0                                         {product} {default}
      bool UseAES                                   = true                                      {product} {default}
      intx UseAVX                                   = 2                                    {ARCH product} {default}
@@ -504,8 +490,6 @@
      bool UseHugeTLBFS                             = false                                     {product} {default}
      bool UseInlineCaches                          = true                                      {product} {default}
      bool UseInterpreter                           = true                                      {product} {default}
-     bool UseJVMCICompiler                         = true                                {JVMCI product} {default}
-     bool UseJVMCINativeLibrary                    = true                                {JVMCI product} {default}
      bool UseJumpTables                            = true                                   {C2 product} {default}
      bool UseLargePages                            = false                                  {pd product} {default}
      bool UseLargePagesIndividualAllocation        = false                                  {pd product} {default}
@@ -574,5 +558,5 @@
     uintx ZUncommitDelay                           = 300                                       {product} {default}
      bool ZeroTLAB                                 = false                                     {product} {default}
 openjdk 17.0.7 2023-04-18
-OpenJDK Runtime Environment GraalVM CE 22.3.2 (build 17.0.7+7-jvmci-22.3-b18)
-OpenJDK 64-Bit Server VM GraalVM CE 22.3.2 (build 17.0.7+7-jvmci-22.3-b18, mixed mode, sharing)
+OpenJDK Runtime Environment Temurin-17.0.7+7 (build 17.0.7+7)
+OpenJDK 64-Bit Server VM Temurin-17.0.7+7 (build 17.0.7+7, mixed mode, sharing)

@zakkak zakkak mentioned this issue Mar 6, 2024
Merged
@zakkak
Copy link
Collaborator Author

zakkak commented Sep 9, 2024

I think we can close this issue at this point.

Closing this as the difference is in the ballpark of 5% and we haven't had any complaints from users.

@zakkak zakkak closed this as completed Sep 9, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
enhancement New feature or request not-Stale
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@jerboaa @zakkak