Check for code usage fluctuations in native images

[zakkak]

This aims to aid in detecting code usage fluctuations as early as
possible. I set the threshold to 3% which might be a bit tight.

Ideally most (if not all) ITs being tested in native mode should include
such checks. This way when a dependency gets updated and brings in more
bloat, or a GraalVM change results in more code becoming reachable we
will be able to notice.

If significant fluctuations between GraalVM/Mandrel versions are
detected the annotations @DisableIfBuiltWithGraalVMOlderThan and
@DisableIfBuiltWithGraalVMNewerThan may be used to run tests with
different properties files.

The properties files can be generated by running the following script,
passing the build output json file as the first parameter and the path
to the target properties file as the second parameter (it will be
overwritten), after a failed run. This way enabling the check for a new
integration test is a matter of:

1. copying ImageMetricsITCase.java in the corresponding folder
2. running the test once
3. running the following script passing the
   build output json file as the first parameter.

#!/bin/bash

KEYS=( \
image_details.total_bytes \
analysis_results.types.reachable \
analysis_results.methods.reachable \
analysis_results.fields.reachable \
analysis_results.types.reflection \
analysis_results.methods.reflection \
analysis_results.fields.reflection \
analysis_results.types.jni \
analysis_results.methods.jni \
analysis_results.fields.jni \
)

echo "# Properties file used by ImageMetricsITCase" > $2
for i in "${KEYS[@]}"
do
  echo "$i=$(jq .$i $1)" >> $2
  echo "$i.tolerance=3" >> $2
done

Implements part of #36066

Supersedes #36091

After a first round of feedback I can add the check to more integration tests.

[quarkus-bot]

/cc @Sanne (hibernate-orm), @gsmet (hibernate-orm), @yrodiere (hibernate-orm)

[zakkak]

cc @jerboaa

[Sanne]

Looks like you expect people to copy/paste this class in various modules, then edit the constants.
Perhaps it could be reworked to help reuse of code a little? I'd especially avoid having to copy paste the report name constants everywhere.

e.g. change
buildOutput.assertValueWithinRange(EXPECTED_IMAGE_SIZE, TOLERANCE_PERCENTAGE, "image_details", "total_bytes");

to
buildOutput.expectImageSize(long expectedzie, int tolerancePercentage) ?

[Sanne]

Also, I'm wondering if you really want to allow some margin of error for each of these. For example, does it make sense to have tolerante about EXPECTED_JNI_TYPES ?
With a dedicated method you'd be able to nudge the other developers in the right direction.

[zakkak]

Perhaps it could be reworked to help reuse of code a little?

Done, it's much cleaner now and uses properties files for the expected value and the tolerance instead of code. This way it's more flexible and doesn't require code changes to add a new check.

For example, does it make sense to have tolerante about EXPECTED_JNI_TYPES ?

Sure, for some cases we can be stricter. Happy to adjust the tolerance to whatever the Quarkus team would feel comfortable with (note that the stricter the checks the more the expected test failures in the CI).

[galderz]

LGTM so far @zakkak

[zakkak]

I suggest we get this integrated as is and see how it goes for a couple of weeks before adding thresholds for more tests.

[jerboaa]

OK. Just some minor comments.

[zakkak]

It works and it's already failing :|

I will update the thresholds, and try to add version specific thresholds as well so that it doesn't crash if one tests with jdk-17 instead of jdk-21 for instance

[zakkak]

I updated the thresholds and added support for different thresholds per Mandrel/GraalVM version. @jerboaa please review d22e4f3

[zakkak]

ImageMetricsITCase.verifyImageMetrics:15 Expected analysis_results.methods.reflection to be within range [7472 +- 3%] but was 7734 ==> expected: but was:

That's interesting... The test fails (only for the main integration test) even after updating the thresholds...

I am running the test locally and the number of methods registered for reflection are indeed close to 7470 (+-4 methods), while on the github runner they appear to be higher with no apparent reason.

It's true that the compilation process is not deterministic (meaning more code might end up being reachable) but that's a big difference :/

In fact all metrics seem to be higher on GHA for this test:

GH build

   30,632 reachable types   (90.6% of   33,810 total)
   44,546 reachable fields  (63.7% of   69,902 total)
  152,675 reachable methods (58.6% of  260,569 total)
    9,170 types,   480 fields, and 7,734 methods registered for reflection
       62 types,    61 fields, and    55 methods registered for JNI access
        4 native libraries: dl, pthread, rt, z
...
  62.63MB (44.34%) for code area:   100,875 compilation units
  78.20MB (55.36%) for image heap:  679,819 objects and 418 resources
 424.77kB ( 0.29%) for other data
 141.25MB in total

Local build

   29,995 reachable types   (90.5% of   33,151 total)
   43,573 reachable fields  (63.7% of   68,375 total)
  148,865 reachable methods (58.5% of  254,360 total)
    8,978 types,   480 fields, and 7,470 methods registered for reflection
       62 types,    61 fields, and    55 methods registered for JNI access
        4 native libraries: dl, pthread, rt, z
...
  60.49MB (44.04%) for code area:    98,354 compilation units
  76.44MB (55.66%) for image heap:  662,828 objects and 422 resources
 421.87kB ( 0.30%) for other data
 137.34MB in total

[zakkak]

with no apparent reason.

It turns out I was running without -Dtest-containers... I will update the thresholds once more

[zakkak]

Test failures are irrelevant (see #37347 (comment))

[zakkak]

@Sanne could you please have another look?

[jerboaa]

Seems fine to me.

[maxandersen]

do I get it right that idea is to just add a test of these 17 characters in every IT test case and since the general structure is IT tests will include all the various extensions it will automagically works - no extra setup?

[zakkak]

Yes, if you follow the three steps mentioned in the description of this PR you should be good to go:

1. copying ImageMetricsITCase.java in the corresponding folder
2. running the test once
3. running the following script passing the build output json file as the first parameter.

[zakkak]

@maxandersen are you OK with this?

[geoand]

It would be nice if there was a writeup of what the state of the PR is after all the changes that went into it, as it would help people reviewing for the first time and free them from the burden of having to build up the context by reading all the comments.

Thanks!

[zakkak]

@geoand the description of the PR is up to date, there is no need to go through all the comments.

[geoand]

👍🏼

[geoand]

Minor nitpick - can we improve the name of this? Perhaps NativeBuildOutputExtension?

[zakkak]

Done

[geoand]

LGTM

[zakkak]

I rebased the branch to have a more recent CI run. If things look good and there are no objections I plan to merge this tonight.

[quarkus-bot]

Failing Jobs - Building 2e44e78

Status	Name	Step	Failures	Logs	Raw logs	Build scan
✖	Maven Tests - JDK 17	Build	Failures	Logs	Raw logs	🚧
✔️	Maven Tests - JDK 17 Windows					🚧

Full information is available in the Build summary check run.

Failures

⚙️ Maven Tests - JDK 17 #

- Failing: integration-tests/maven 

📦 integration-tests/maven

✖ io.quarkus.maven.it.DevMojoIT.testThatNewResourcesAreServed line 967 - More details - Source on GitHub

org.awaitility.core.ConditionTimeoutException: io.quarkus.maven.it.DevMojoIT expected "bff51429-4b63-4bb1-ba19-ff33e178871b" but was "Lorem ipsum dolor sit amet, consectetur adipiscing elit, sed do eiusmod tempor incididunt ut labore et dolore magna aliqua." within 2 minutes.
	at org.awaitility.core.ConditionAwaiter.await(ConditionAwaiter.java:167)
	at org.awaitility.core.AbstractHamcrestCondition.await(AbstractHamcrestCondition.java:86)

✖ io.quarkus.maven.it.DevMojoIT.testThatNewResourcesAreServed line 967 - More details - Source on GitHub

org.awaitility.core.ConditionTimeoutException: io.quarkus.maven.it.DevMojoIT expected "bff51429-4b63-4bb1-ba19-ff33e178871b" but was "Lorem ipsum dolor sit amet, consectetur adipiscing elit, sed do eiusmod tempor incididunt ut labore et dolore magna aliqua." within 2 minutes.
	at org.awaitility.core.ConditionAwaiter.await(ConditionAwaiter.java:167)
	at org.awaitility.core.AbstractHamcrestCondition.await(AbstractHamcrestCondition.java:86)

[jerboaa]

@zakkak We see some failures related to that on GraalVM master built with JDK 21 here:

Error:  Tests run: 1, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 6.406 s <<< FAILURE! -- in io.quarkus.it.jpa.postgresql.ImageMetricsITCase
Error:  io.quarkus.it.jpa.postgresql.ImageMetricsITCase.verifyImageMetrics -- Time elapsed: 0.332 s <<< FAILURE!
org.opentest4j.AssertionFailedError: Expected analysis_results.methods.reachable to be within range [96465 +- 3%] but was 104006 ==> expected: <true> but was: <false>
	at org.junit.jupiter.api.AssertionFailureBuilder.build(AssertionFailureBuilder.java:151)
	at org.junit.jupiter.api.AssertionFailureBuilder.buildAndThrow(AssertionFailureBuilder.java:132)
	at org.junit.jupiter.api.AssertTrue.failNotTrue(AssertTrue.java:63)
	at org.junit.jupiter.api.AssertTrue.assertTrue(AssertTrue.java:36)
	at org.junit.jupiter.api.Assertions.assertTrue(Assertions.java:214)
	at io.quarkus.test.junit.nativeimage.NativeBuildOutputExtension.assertValueWithinRange(NativeBuildOutputExtension.java:83)
	at io.quarkus.test.junit.nativeimage.NativeBuildOutputExtension.lambda$verifyImageMetrics$0(NativeBuildOutputExtension.java:59)
	at java.base/java.util.concurrent.ConcurrentHashMap.forEach(ConcurrentHashMap.java:1603)
	at java.base/java.util.Properties.forEach(Properties.java:1422)
	at io.quarkus.test.junit.nativeimage.NativeBuildOutputExtension.verifyImageMetrics(NativeBuildOutputExtension.java:52)
	at io.quarkus.test.junit.nativeimage.NativeBuildOutputExtension.verifyImageMetrics(NativeBuildOutputExtension.java:46)
	at io.quarkus.it.jpa.postgresql.ImageMetricsITCase.verifyImageMetrics(ImageMetricsITCase.java:16)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)

https://github.com/graalvm/mandrel/actions/runs/7228893522/job/19699465544#step:12:518

Edit: And Mandrel 23.1:

Error:  io.quarkus.it.jpa.postgresql.ImageMetricsITCase.verifyImageMetrics -- Time elapsed: 0.304 s <<< FAILURE!
org.opentest4j.AssertionFailedError: Expected analysis_results.fields.jni to be within range [59 +- 1%] but was 60 ==> expected: <true> but was: <false>
	at org.junit.jupiter.api.AssertionFailureBuilder.build(AssertionFailureBuilder.java:151)
	at org.junit.jupiter.api.AssertionFailureBuilder.buildAndThrow(AssertionFailureBuilder.java:132)
	at org.junit.jupiter.api.AssertTrue.failNotTrue(AssertTrue.java:63)
	at org.junit.jupiter.api.AssertTrue.assertTrue(AssertTrue.java:36)
	at org.junit.jupiter.api.Assertions.assertTrue(Assertions.java:214)
	at io.quarkus.test.junit.nativeimage.NativeBuildOutputExtension.assertValueWithinRange(NativeBuildOutputExtension.java:83)
	at io.quarkus.test.junit.nativeimage.NativeBuildOutputExtension.lambda$verifyImageMetrics$0(NativeBuildOutputExtension.java:59)
	at java.base/java.util.concurrent.ConcurrentHashMap.forEach(ConcurrentHashMap.java:1603)
	at java.base/java.util.Properties.forEach(Properties.java:1422)
	at io.quarkus.test.junit.nativeimage.NativeBuildOutputExtension.verifyImageMetrics(NativeBuildOutputExtension.java:52)
	at io.quarkus.test.junit.nativeimage.NativeBuildOutputExtension.verifyImageMetrics(NativeBuildOutputExtension.java:46)
	at io.quarkus.it.jpa.postgresql.ImageMetricsITCase.verifyImageMetrics(ImageMetricsITCase.java:16)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)

https://github.com/graalvm/mandrel/actions/runs/7228893522/job/19699471598#step:12:514

[jerboaa]

Also for Mandrel 23.1 for the main integration test:

Error:  io.quarkus.it.main.ImageMetricsITCase.verifyImageMetrics -- Time elapsed: 0.016 s <<< FAILURE!
org.opentest4j.AssertionFailedError: Expected analysis_results.fields.jni to be within range [61 +- 1%] but was 62 ==> expected: <true> but was: <false>
	at org.junit.jupiter.api.AssertionFailureBuilder.build(AssertionFailureBuilder.java:151)
	at org.junit.jupiter.api.AssertionFailureBuilder.buildAndThrow(AssertionFailureBuilder.java:132)
	at org.junit.jupiter.api.AssertTrue.failNotTrue(AssertTrue.java:63)
	at org.junit.jupiter.api.AssertTrue.assertTrue(AssertTrue.java:36)
	at org.junit.jupiter.api.Assertions.assertTrue(Assertions.java:214)
	at io.quarkus.test.junit.nativeimage.NativeBuildOutputExtension.assertValueWithinRange(NativeBuildOutputExtension.java:83)
	at io.quarkus.test.junit.nativeimage.NativeBuildOutputExtension.lambda$verifyImageMetrics$0(NativeBuildOutputExtension.java:59)
	at java.base/java.util.concurrent.ConcurrentHashMap.forEach(ConcurrentHashMap.java:1603)
	at java.base/java.util.Properties.forEach(Properties.java:1422)
	at io.quarkus.test.junit.nativeimage.NativeBuildOutputExtension.verifyImageMetrics(NativeBuildOutputExtension.java:52)
	at io.quarkus.test.junit.nativeimage.NativeBuildOutputExtension.verifyImageMetrics(NativeBuildOutputExtension.java:46)
	at io.quarkus.it.main.ImageMetricsITCase.verifyImageMetrics(ImageMetricsITCase.java:15)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)

https://github.com/graalvm/mandrel/actions/runs/7228893522/job/19699470818#step:12:619

[zakkak]

In Mandrel 23.1 it looks like the new field being accessed through JNI is sun.nio.fs.UnixFileAttributes.st_birthtime_sec introduced with https://bugs.openjdk.org/browse/JDK-8316304

I will just increase the value (in anticipation of the January release) along with the percentage threshold (for backwards compatibility).

PR: #37813

Looking into the GraalVM + main increase in reachable methods next.

[zakkak]

The GraalVM + main issue is a bit more complicated... What happens in this case is that Quarkus uses the "jvmci" version from the base-JDK used to build GraalVM.

When building GraalVM master with JDK 21 we are using LabsJDK 21.0.1+12-jvmci-23.1-b26, so Quarkus things the GraalVM version is 23.1 despite it acutally being 24.0.

Since upstream GraalVM doesn't plan on releasing GraalVM 24.0 based on JDK 21 it's not expected to get a jvmci version bump in LabsJDK 21. Unfortunately I don't see any way to work around this. Perhaps we could make these tests to be opt-out, so that we can disable them in certain environments. WDYT?

[jerboaa]

Since upstream GraalVM doesn't plan on releasing GraalVM 24.0 based on JDK 21 it's not expected to get a jvmci version bump in LabsJDK 21. Unfortunately I don't see any way to work around this. Perhaps we could make these tests to be opt-out, so that we can disable them in certain environments. WDYT?

+1 to an opt-out. In certain runs we should just be able to configure CI to not run the metrics tests. Environment variable or property comes to mind.

[zakkak]

Opt-out option implemented in #37820