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

Re-enable single parsing of compiler graphs in native-image #19511

Merged
merged 3 commits into from
Sep 28, 2021

Conversation

zakkak
Copy link
Contributor

@zakkak zakkak commented Aug 19, 2021

GraalVM 21.2-dev introduced a new enhancement (enabled by default) to avoid parsing compiler graphs twice.
This enhancement however resulted in increased memory usage (oracle/graal#3435) which then resulted in Quarkus' Integration Test failures in CI.
In GraalVM 21.2 and 21.3-dev this appears to no longer be an issue.

I have tested this branch with GraalVM CE and Mandrel 21.2, as well as with GraalVM CE and Mandrel 21.3-dev.

Things look good except for io.quarkus.it.jpa.postgresql.JPAFunctionalityInGraalITCase which fails when compiled with 21.3-dev with:

[ERROR] io.quarkus.it.jpa.postgresql.JPAFunctionalityInGraalITCase.verifyJdkXmlParsersHavebeenEcludedFromNative  Time elapsed: 0.137 s  <<< FAILURE!
org.opentest4j.AssertionFailedError: Type 'javax.xml.transform.TransformerFactory' was found in the report in target/quarkus-integration-test-jpa-postgresql-999-SNAPSHOT-native-image-source-jar/reports/used_classes_quarkus-integration-test-jpa-postgresql-999-SNAPSHOT-runner_20210819_173859.txt
	at org.junit.jupiter.api.AssertionUtils.fail(AssertionUtils.java:39)
	at org.junit.jupiter.api.Assertions.fail(Assertions.java:117)
	at io.quarkus.test.junit.nativeimage.ClassInclusionReport.assertContainsNot(ClassInclusionReport.java:67)
	at io.quarkus.test.junit.nativeimage.ClassInclusionReport.assertContainsNot(ClassInclusionReport.java:53)
	at io.quarkus.it.jpa.postgresql.JPAFunctionalityInGraalITCase.verifyJdkXmlParsersHavebeenEcludedFromNative(JPAFunctionalityInGraalITCase.java:25)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:688)
	at org.junit.jupiter.engine.execution.MethodInvocation.proceed(MethodInvocation.java:60)
	at org.junit.jupiter.engine.execution.InvocationInterceptorChain$ValidatingInvocation.proceed(InvocationInterceptorChain.java:131)
	at io.quarkus.test.junit.QuarkusTestExtension.interceptTestMethod(QuarkusTestExtension.java:895)
	at org.junit.jupiter.engine.execution.ExecutableInvoker$ReflectiveInterceptorCall.lambda$ofVoidMethod$0(ExecutableInvoker.java:115)
	at org.junit.jupiter.engine.execution.ExecutableInvoker.lambda$invoke$0(ExecutableInvoker.java:105)
	at org.junit.jupiter.engine.execution.InvocationInterceptorChain$InterceptedInvocation.proceed(InvocationInterceptorChain.java:106)
	at org.junit.jupiter.engine.extension.TimeoutExtension.intercept(TimeoutExtension.java:149)
	at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestableMethod(TimeoutExtension.java:140)
	at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestMethod(TimeoutExtension.java:84)
	at org.junit.jupiter.engine.execution.ExecutableInvoker$ReflectiveInterceptorCall.lambda$ofVoidMethod$0(ExecutableInvoker.java:115)
	at org.junit.jupiter.engine.execution.ExecutableInvoker.lambda$invoke$0(ExecutableInvoker.java:105)
	at org.junit.jupiter.engine.execution.InvocationInterceptorChain$InterceptedInvocation.proceed(InvocationInterceptorChain.java:106)
	at org.junit.jupiter.engine.execution.InvocationInterceptorChain.proceed(InvocationInterceptorChain.java:64)
	at org.junit.jupiter.engine.execution.InvocationInterceptorChain.chainAndInvoke(InvocationInterceptorChain.java:45)
	at org.junit.jupiter.engine.execution.InvocationInterceptorChain.invoke(InvocationInterceptorChain.java:37)
	at org.junit.jupiter.engine.execution.ExecutableInvoker.invoke(ExecutableInvoker.java:104)
	at org.junit.jupiter.engine.execution.ExecutableInvoker.invoke(ExecutableInvoker.java:98)
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeTestMethod$6(TestMethodTestDescriptor.java:210)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.invokeTestMethod(TestMethodTestDescriptor.java:206)
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:131)
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:65)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:139)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:129)
	at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:127)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:126)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:84)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1541)
	at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:38)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:143)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:129)
	at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:127)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:126)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:84)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1541)
	at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:38)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:143)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:129)
	at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:127)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:126)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:84)
	at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.submit(SameThreadHierarchicalTestExecutorService.java:32)
	at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:57)
	at org.junit.platform.engine.support.hierarchical.HierarchicalTestEngine.execute(HierarchicalTestEngine.java:51)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:108)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:88)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.lambda$execute$0(EngineExecutionOrchestrator.java:54)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.withInterceptedStreams(EngineExecutionOrchestrator.java:67)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:52)
	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:96)
	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:75)
	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.execute(JUnitPlatformProvider.java:188)
	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.invokeAllTests(JUnitPlatformProvider.java:154)
	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.invoke(JUnitPlatformProvider.java:128)
	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:428)
	at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:162)
	at org.apache.maven.surefire.booter.ForkedBooter.run(ForkedBooter.java:562)
	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:548)

Keeping this as draft for now.

Closes: #19446

GraalVM 21.2-dev at some point introduced a new enhancement (enabled by
default) to avoid parsing compiler graphs twice. This enhancement
however results in increased memory usage at the
moment (oracle/graal#3435) which then results
in Quarkus' Integration Test failures in CI.  In GraalVM 21.2 this
appears to no longer be an issue.
@zakkak
Copy link
Contributor Author

zakkak commented Sep 24, 2021

Testing this with a more recent Quarkus seems OK except for the following error in io.quarkus.it.jpa.postgresql.JPAFunctionalityInGraalITCase:

org.opentest4j.AssertionFailedError: Type 'javax.xml.transform.TransformerFactory' was found in the report in target/quarkus-integration-test-jpa-postgresql-999-SNAPSHOT-native-image-source-jar/reports/used_classes_quarkus-integration-test-jpa-postgresql-999-SNAPSHOT-runner_20210924_074424.txt

Passing -Dquarkus.native.additional-build-args="-H:-InlineBeforeAnalysis" makes the test pass.

@Sanne it looks like when ParseOnce and InlineBeforeAnalysis are both enabled (default behavior in the upcoming GraalVM 21.3)

public void beforeAnalysis(BeforeAnalysisAccess access) {
Class<?> pgSQLXMLClass = access.findClassByName("io.quarkus.jdbc.postgresql.runtime.graal.PgSQLXML");
try {
//Only if this method is ever invoked, then it's possible that field {@link PgSQLXML#domResult }
//is ever non-null, and only in that case the XML parsing facilities pulled in by the driver
//end up being necessary.
final Method triggerMethod = pgSQLXMLClass.getMethod("setResult", Class.class);
access.registerReachabilityHandler(this::identifiedXMLProcessingInDriver, triggerMethod);
} catch (Exception e) {
throw new RuntimeException(e);
}
}

doesn't work as expected.

My first thought was that setResult might be getting inlined before analysis and thus analysis sees it as reachable, following that thought I tried the following:

diff --git a/extensions/jdbc/jdbc-postgresql/runtime/src/main/java/io/quarkus/jdbc/postgresql/runtime/graal/PgSQLXML.java b/extensions/jdbc/jdbc-postgresql/runtime/src/main/java/io/quarkus/jdbc/postgresql/runtime/graal/PgSQLXML.java
index b0333866f2..2dea4eaeda 100644
--- a/extensions/jdbc/jdbc-postgresql/runtime/src/main/java/io/quarkus/jdbc/postgresql/runtime/graal/PgSQLXML.java
+++ b/extensions/jdbc/jdbc-postgresql/runtime/src/main/java/io/quarkus/jdbc/postgresql/runtime/graal/PgSQLXML.java
@@ -41,6 +41,7 @@ import org.postgresql.xml.PGXmlFactoryFactory;
 import org.xml.sax.InputSource;
 import org.xml.sax.XMLReader;
 
+import com.oracle.svm.core.annotate.NeverInline;
 import com.oracle.svm.core.annotate.Substitute;
 import com.oracle.svm.core.annotate.TargetClass;
 
@@ -222,6 +223,7 @@ public final class PgSQLXML implements SQLXML {
         return stringWriter;
     }
 
+    @NeverInline("Prevent inlining so that io.quarkus.jdbc.postgresql.runtime.graal.SQLXLMFeature keeps working with -H:+InlineBeforeAnalysis")
     @Substitute
     @Override
     public synchronized <T extends Result> T setResult(Class<T> resultClass) throws SQLException {

But the test still fails.

@Sanne any thoughts? (+ FYI)

@zakkak
Copy link
Contributor Author

zakkak commented Sep 24, 2021

After some profiling it looks like the use of ParseOnce is no longer causing issues with the CI (like the ones mentioned in #17711) both in 21.2 and 21.3-dev (averages of 3 runs)

21.3-dev

-H:+ParseOnce -H:-ParseOnce
compilation time ~263s ~274s
Allocated heap size 6.5 GB 7.3 GB

21.2

-H:+ParseOnce -H:-ParseOnce
compilation time ~282s ~290s
Allocated heap size 7.2 GB 7.4 GB

Especially motivated by the reduction of the allocated heap size in 21.3-dev I believe we should allow GraalVM/Mandrel to keep ParseOnce enabled moving forward.

Note: Since ParseOnce in conjuntion with InlineBeforeAnalysis is causing issues with one test (see #19511 (comment)) I opted for keeping InlineBeforeAnalysis disabled even when using 21.3 till we figure it out. According to my measurements InlineBeforeAnalysis has no significant impact on compilation times or memory utilization. However, it's supposed to enable GraalVM to take advantage of inline methods to improve the precision of the static analysis (see oracle/graal#3818) and thus it's expected to produce more efficient native executables. That said, we should try to enable it at some point.

@zakkak zakkak marked this pull request as ready for review September 24, 2021 13:22
@zakkak zakkak requested review from Sanne and geoand September 24, 2021 13:29
@geoand
Copy link
Contributor

geoand commented Sep 24, 2021

I can't say I know much about the subject. so I'll leave this to others.

@Sanne
Copy link
Member

Sanne commented Sep 24, 2021

Hi @zakkak , if javax.xml.transform.TransformerFactory is still being detected, it might be being included for other reasons.

I was able to identify the PgSQLXML case as being a reason for GraalVM to decide to include the TransformerFactory as non-dead code: it was the only detected path that made it reachable.

But having changed the analysis algorythms, I suppose other tricky paths might have materialized? It's very likely that it's being included via a different path now, as my patches on PgSQLXML make it unlikely.
We would need to do another reachability analysis to know where it's coming from; do you have any clue from the reports?

I think it's really important to keep such types out of it as they come with a significant amount of dependencies; however it might be more interesting for the long term to figure out why GraalVM isn't able to see such paths as dead code automatically.

@quarkus-bot
Copy link

quarkus-bot bot commented Sep 24, 2021

This workflow status is outdated as a new workflow run has been triggered.

Failing Jobs - Building 5a52322

Status Name Step Failures Logs Raw logs
Gradle Tests - JDK 11 Build Failures Logs Raw logs
Gradle Tests - JDK 11 Windows Build Failures Logs Raw logs

Full information is available in the Build summary check run.

Failures

⚙️ Gradle Tests - JDK 11 #

- Failing: integration-tests/gradle 

📦 integration-tests/gradle

io.quarkus.gradle.devmode.MultiModuleIncludedBuildTest.main line 24 - More details - Source on GitHub

java.lang.AssertionError: 

Expecting actual:

⚙️ Gradle Tests - JDK 11 Windows #

- Failing: integration-tests/gradle 

📦 integration-tests/gradle

io.quarkus.gradle.devmode.MultiModuleIncludedBuildTest.main line 24 - More details - Source on GitHub

java.lang.AssertionError: 

Expecting actual:

@zakkak zakkak requested a review from galderz September 27, 2021 14:58
@zakkak
Copy link
Contributor Author

zakkak commented Sep 28, 2021

@Sanne it turns out what is happening with ParseOnce + InlineBeforeAnalysis is that GraalVM is now able to figure out the trick in

//When GraalVM can figure out a constant name for the target method to be invoked reflectively,
//it automatically registers it for reflection. We don't want that to happen in this particular case.
private static String obfuscatedMethodName() {
return "reallyProcessDom" + "Result";
}

so it automatically registers it for reflection.

Fixed in c8187f5

Please re-review :)

new CI runs for Mandrel 21.2: https://github.com/graalvm/mandrel/actions/runs/1282221217
and GraalVM 21.3-dev: https://github.com/graalvm/mandrel/actions/runs/1282221313

@Sanne
Copy link
Member

Sanne commented Sep 28, 2021

ah awesome :) Sorry I should have remembered of that one.

Starting with GraalVM 21.3 InlineBeforeAnalysis is going to be enabled
by default. This patch enables it for 21.2 as well.
@zakkak
Copy link
Contributor Author

zakkak commented Sep 28, 2021

@quarkus-bot
Copy link

quarkus-bot bot commented Sep 28, 2021

Failing Jobs - Building b9e22a5

Status Name Step Failures Logs Raw logs
MicroProfile TCKs Tests Verify Failures Logs Raw logs

Full information is available in the Build summary check run.

Failures

⚙️ MicroProfile TCKs Tests #

- Failing: tcks/microprofile-fault-tolerance 

📦 tcks/microprofile-fault-tolerance

org.eclipse.microprofile.fault.tolerance.tck.TimeoutUninterruptableTest.testTimeoutAsyncBulkhead line 190 - More details - Source on GitHub

java.lang.AssertionError: Unexpected exception thrown from Future
	at org.testng.Assert.fail(Assert.java:85)
	at org.eclipse.microprofile.fault.tolerance.tck.util.Exceptions.expect(Exceptions.java:98)

@geoand geoand merged commit c40a024 into quarkusio:main Sep 28, 2021
@quarkus-bot quarkus-bot bot added this to the 2.4 - main milestone Sep 28, 2021
@zakkak zakkak deleted the enable-parseonce branch September 29, 2021 06:59
zakkak added a commit to zakkak/quarkus that referenced this pull request Oct 26, 2021
Disable single parsing of compiler graphs till the impact of it on heap
usage decreases see oracle/graal#3435 and
graalvm/mandrel#304 (comment)

quarkusio#19511 didn't take into account
runs with constraint memory.  Bringing back `-H:-ParseOnce` reduces the
heap usage significantly, from 3.9G down to 2.7G in
integration-tests/main.
zakkak added a commit to zakkak/quarkus that referenced this pull request Oct 26, 2021
Disable single parsing of compiler graphs till the impact of it on heap
usage decreases see oracle/graal#3435 and
graalvm/mandrel#304 (comment)

quarkusio#19511 didn't take into account
runs with constraint memory.  Bringing back `-H:-ParseOnce` reduces the
heap usage significantly, from 3.9G down to 2.7G in
integration-tests/main.
@zakkak
Copy link
Contributor Author

zakkak commented Oct 26, 2021

Removing triage/backport-2.2 due to #21018

quarkusio#19511 didn't take into account
runs with constraint memory.  Bringing back `-H:-ParseOnce` reduces the
heap usage significantly, from 3.9G down to 2.7G in
integration-tests/main.

Note: This is true for both 21.2 and 21.3

@zakkak zakkak mentioned this pull request Oct 27, 2021
zakkak added a commit to zakkak/quarkus that referenced this pull request Oct 27, 2021
Disable single parsing of compiler graphs till the impact of it on heap
usage decreases see oracle/graal#3435 and
graalvm/mandrel#304 (comment)

quarkusio#19511 didn't take into account
runs with constraint memory.  Bringing back `-H:-ParseOnce` reduces the
heap usage significantly, from 3.9G down to 2.7G in
integration-tests/main.
zakkak added a commit to zakkak/quarkus that referenced this pull request Oct 28, 2021
Disable single parsing of compiler graphs till the impact of it on heap
usage decreases see oracle/graal#3435 and
graalvm/mandrel#304 (comment)

quarkusio#19511 didn't take into account
runs with constraint memory.  Bringing back `-H:-ParseOnce` reduces the
heap usage significantly, from 3.9G down to 2.7G in
integration-tests/main.
@gsmet gsmet modified the milestones: 2.4.0.CR1, 2.2.4.Final Dec 1, 2021
gsmet pushed a commit to gsmet/quarkus that referenced this pull request Dec 1, 2021
Disable single parsing of compiler graphs till the impact of it on heap
usage decreases see oracle/graal#3435 and
graalvm/mandrel#304 (comment)

quarkusio#19511 didn't take into account
runs with constraint memory.  Bringing back `-H:-ParseOnce` reduces the
heap usage significantly, from 3.9G down to 2.7G in
integration-tests/main.

(cherry picked from commit 201b9a6)
gsmet pushed a commit to gsmet/quarkus that referenced this pull request Dec 1, 2021
Disable single parsing of compiler graphs till the impact of it on heap
usage decreases see oracle/graal#3435 and
graalvm/mandrel#304 (comment)

quarkusio#19511 didn't take into account
runs with constraint memory.  Bringing back `-H:-ParseOnce` reduces the
heap usage significantly, from 3.9G down to 2.7G in
integration-tests/main.

(cherry picked from commit 201b9a6)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

InlineBeforeAnalysis enabled by default in coming GraalVM 21.3 release
4 participants