[WIP] Started implementing compareNativeAndJVMSerialGCTime test #355

patrikcerbak · 2025-07-18T14:24:46Z

Work in progress

Hi,

I started to implement compareNativeAndJVMSerialGCTime for comparing native vs JVM SerialGC times and performance.

You can run it like so: mvn clean verify -DincludeTags=perfcheck -Dtest=PerfCheckTest#compareNativeAndJVMSerialGCTime -Ptestsuite -Dquarkus.version=3.23.0 -Dquarkus.native.container-runtime=podman

jerboaa

A few initial comments.

testsuite/src/it/java/org/graalvm/tests/integration/utils/BuildAndRunCmds.java

testsuite/src/it/java/org/graalvm/tests/integration/PerfCheckTest.java

patrikcerbak · 2025-08-07T12:17:17Z

FYI: Took some break on this, since I was busy with other stuff and had a PTO, I will continue with the work here now.

Karm

Thx Patrik,

When you address Severin's and mine concerns, either by doing what we suggest or by explaining why you would do it differently, could you please:

Take a look at the API call Hyperfoil is making to the Quarkus app? Perhaps a wrong port? URL?

Error:    PerfCheckTest.compareNativeAndJVMSerialGCTime:628 build-and-run.log log should not contain error or warning lines that are not whitelisted. See /home/runner/work/mandrel-integration-tests/mandrel-integration-tests/ts/testsuite/target/archived-logs/org.graalvm.tests.integration.PerfCheckTest/compareNativeAndJVMSerialGCTime/build-and-run.log and check these offending 399 lines: 
15:21:14,137 WARN  (epollEventLoopGroup-2-1) [i.h.h.h.RangeStatusValidator] #11 Sequence test(0)(4/4), request (#11, RUNNING, INVALID) GET localhost:8080/data/client/test//bonjour on connection Http1xConnection{/127.0.0.1:59476 -> localhost/127.0.0.1:8080, status=OPEN, size=1+0:[(#11, RUNNING, INVALID) GET localhost:8080/data/client/test//bonjour]} received invalid status 404
15:21:16,096 WARN  (epollEventLoopGroup-2-1) [i.h.h.h.RangeStatusValidator] #95 Sequence test(0)(4/4), request (#95, RUNNING, INVALID) GET localhost:8080/data/client/test//helloThere on connection Http1xConnection{/127.0.0.1:60140 -> localhost/127.0.0.1:8080, status=OPEN, size=1+0:[(#95, RUNNING, INVALID) GET localhost:8080/data/client/test//helloThere]} received invalid status 404
15:21:17,041 WARN  (epollEventLoopGroup-2-1) [i.h.h.h.RangeStatusValidator] #84 Sequence test(0)(4/4), request (#84, RUNNING, INVALID) GET localhost:8080/data/client/test//bonjour on connection Http1xConnection{/127.0.0.1:60562 -> localhost/127.0.0.1:8080, status=OPEN, size=1+0:[(#84, RUNNING, INVALID) GET localhost:8080/data/client/test//bonjour]} received invalid status 404

Could you analyze the output and form some basic thresholds akin to what JFR tests do, e.g.
** native run should not perform worse than n % on the hyperfoil percentiles than the HotSpot run
** time spent in GC should not be worse in native than n % of the HotSpot
** or think of another strategy what would track and safeguard native perf smoke test compared to HotSpot

Karm · 2025-08-11T08:25:26Z

apps/quarkus-full-microprofile/benchmark.hf.yaml

+scenario:
+  - test:
+      # Step `randomItem` randomly picks one item from the list below...
+      - randomItem:


@patrikcerbak I don't think a random pick here is a good idea. Is there a deterministic, sequential alternative?
The thing is that these APIs touch vastly different libraries and if one fails we kinda want to know it in a predictable order.
Speak up if you think it's not important though...

Okay, that makes sense. I'll try to replace it by a deterministic alternative.

testsuite/src/it/java/org/graalvm/tests/integration/PerfCheckTest.java

Karm · 2025-08-11T08:29:08Z

testsuite/src/it/java/org/graalvm/tests/integration/PerfCheckTest.java

+                    "Main is still open.");
+            Logs.checkLog(cn, mn, app, processLog);
+
+            // TODO, need to implement some asserting here once the timeSpentInGCs value is not 0


I also think a sanity check like that would be nice here.

testsuite/src/it/java/org/graalvm/tests/integration/PerfCheckTest.java

testsuite/src/it/java/org/graalvm/tests/integration/utils/BuildAndRunCmds.java

patrikcerbak · 2025-08-13T14:35:38Z

Take a look at the API call Hyperfoil is making to the Quarkus app? Perhaps a wrong port? URL?

@Karm, I think I fixed the issue, there was a double slash character in the endpoints. Can you please approve the workflows here, so I can be check and be sure it's fixed?

Karm · 2025-08-14T11:14:49Z

@patrikcerbak I invited you as a Collaborator on this project so as you can run CI as you please.

patrikcerbak · 2025-08-14T11:32:14Z

@patrikcerbak I invited you as a Collaborator on this project so as you can run CI as you please.

Thanks!

patrikcerbak · 2025-08-14T13:21:25Z

Hi @Karm,
By looking at the GH actions results, I noticed that from Mandrel 23.1, there is a new format for native GC logs and the current GC log parses doesn't work with it (hence why there is 0.0 value for timeSpentInGCs here).

I did some changes in the Commands.java file here, that should fix that: here. Would you mind looking at the few lines I added, when you have time? I want to be sure I used the UsedVersion API correctly and that the new RegExes make sense. Thanks!

PS: Sorry for the force push, I created some git problems locally...

Karm · 2025-08-14T14:34:07Z

@patrikcerbak Force push is fine in these woods, as long as it's in your own branch :-)

Karm · 2025-08-28T13:58:46Z

@patrikcerbak

This is a new, non-whitelisted error:

Error:  Failures: 
Error:    PerfCheckTest.compareNativeAndJVMSerialGCTime:653 build-and-run.log log should not contain error or warning lines that are not whitelisted. See /home/runner/work/mandrel-integration-tests/mandrel-integration-tests/ts/testsuite/target/archived-logs/org.graalvm.tests.integration.PerfCheckTest/compareNativeAndJVMSerialGCTime/build-and-run.log and check these offending 1 lines: 
2025-08-14 14:18:43,883 WARN  [io.net.boo.ServerBootstrap] (vert.x-acceptor-thread-0) Failed to register an accepted channel: [id: 0x3d2ab090, L:/127.0.0.1:8080 ! R:/127.0.0.1:59564]: java.lang.IllegalStateException ==> expected: <true> but was: <false>

Could you poke around, check Quarkus github, Netty and vertx githubs etc. and form an idea whether it's a benign thing or some kind of race we should pursue, please?

patrikcerbak · 2025-08-28T14:04:57Z

@Karm

Could you poke around, check Quarkus github, Netty and vertx githubs etc. and form an idea whether it's a benign thing or some kind of race we should pursue, please?

Definitely, I'll investigate the error! What is weird is that it seems to appear very randomly (even when I'm running the test locally).

Karm · 2025-09-04T10:52:52Z

@patrikcerbak Any news on this? Is it a safe candidate for WhiteList?

patrikcerbak · 2025-09-04T11:21:38Z

@Karm I'm inclined to say yes. The only meaningful conversation I found about this is here: https://groups.google.com/g/vertx/c/ekzl1sagkVU. Other than that, I mostly found some unresolved issues.

I also tried experimenting with changing the Hyperfoil config file and it seemed like that in some variants, the problem is hit less frequently. At this moment, I have a benchmark running locally to see if it is really the case or just luck (but it may take few more hours to run)...

patrikcerbak · 2025-09-04T12:46:38Z

Well, it seems that it was just luck. In my opinion, I would say it is okay to add it to the whitelist.

Karm · 2025-09-04T12:54:22Z

@patrikcerbak Ack. Whitelist with a comment, rebase, CI... Thx. 🙏

…ng the GC performance in native and JVM

Karm · 2025-09-09T19:32:05Z

@patrikcerbak

 [INFO] 
Error:  Failures: 
Error:    PerfCheckTest.compareNativeAndJVMSerialGCTime:661 Time spent in GCs is zero (native). ==> expected: not equal but was: <0.0>
[INFO] 
Error:  Tests run: 27, Failures: 1, Errors: 0, Skipped: 3
[INFO]

patrikcerbak · 2025-09-10T08:06:05Z

@Karm

Yes, that is a new (sanity) assert that I added. Seems like the issue is that it wrongly analyzes the logs for GC pause times, again. I'll investigate -- hopefully it's an easy fix.

patrikcerbak · 2025-09-10T09:46:46Z

Mandrel 24.x seems to put an extra Pause word into GC logs. The test should, hopefully, be fixed now.

Karm · 2025-09-11T11:55:40Z

@patrikcerbak I think It's fine now. Didn't you find the random pattern in the Hyperfoil config problematic?

patrikcerbak · 2025-09-11T12:52:55Z

@Karm

Yes, it certainly is problematic, I agree with that. However, when I did some digging into the Hyperfoil configs, i didn't find an easy "linear" replacement for it, all of the options seemed overly complicated. But I'll try looking into it a bit more and I'll let you know.

…not choose a random one

patrikcerbak · 2025-09-15T20:53:01Z

@Karm

In the last commit, I changed it, so that Hyperfoil makes requests all of the URLs one by one, and does not pick a random one. (And also tweaked some parameters in the config for it to work.) Maybe I'm missing something, but I found that to be the sanest way to do it.

What do you think? Should I leave it like this? If so (and everything finishes okay), I'm changing this from a draft to a PR.

Karm · 2025-09-15T21:28:13Z

@patrikcerbak Ack. Thx. Let's wait for the CI. 🙏

patrikcerbak · 2025-09-16T08:50:49Z

It will probably need some more changes to the config parameters, I'm working on it now...

…elist

patrikcerbak · 2025-09-25T13:19:19Z

@Karm

Hi, sorry for the delay, I was busy with other stuff. However, I did a lot of testing locally and I must say that I didn't find any Hyperfoil configuration, which would have a 100% success rate. It still, unfortunately, sometimes prints the Pool depleted, throttling execution! Enable trace logging to see subsequent pool depletion messages. warning.

However, since it only is a warning (and I don't think that throttling the benchmark execution will really mess with the GC times), I added the warning to the whitelist in the last commit. If you think that it is not the right way, let me know, I will revert the commit and try to find some other solution (even thought I don't think there is an easy one for this).

Karm · 2025-09-28T17:35:20Z

@patrikcerbak

I added the warning to the whitelist in the last commit.

Ack.

Thank you very much.

Rebase and let's merge.

Covers the following 4 tests: - JFRTest#jfrPerfTest - DebugSymbolsTest#debugSymbolsQuarkus - RuntimesSmokeTest#helidonQuickStart - RuntimesSmokeTest#quarkusFullMicroProfile Closes: Karm#364

patrikcerbak · 2025-09-29T11:13:30Z

@Karm

Rebase and let's merge.

Rebased, sorry for the mess. Will you pull the lever?

Karm · 2025-09-29T11:14:37Z

@patrikcerbak Did you do a rebase or something else? It seems to me I can see Severin's commit in this set...

patrikcerbak · 2025-09-29T11:33:28Z

@Karm
Yes, it was a rebase locally in IDE which I then pushed here. But it still required some manual editing here, hence why the last Merge branch 'master' into serialgc-test is there.

patrikcerbak · 2025-09-30T16:46:56Z

@Karm

Do you think it is ready for the merge or should I try to clean up locally and then force push? :)

Karm · 2025-10-06T17:56:12Z

Thx , merging.

jerboaa reviewed Jul 18, 2025

View reviewed changes

testsuite/src/it/java/org/graalvm/tests/integration/utils/BuildAndRunCmds.java Outdated Show resolved Hide resolved

testsuite/src/it/java/org/graalvm/tests/integration/PerfCheckTest.java Outdated Show resolved Hide resolved

Karm self-requested a review August 11, 2025 08:48

Karm requested changes Aug 11, 2025

View reviewed changes

patrikcerbak force-pushed the serialgc-test branch from d542761 to 0701c42 Compare August 14, 2025 13:18

patrikcerbak added 8 commits September 5, 2025 11:56

started implementing compareNativeAndJVMSerialGCTime test for compari…

dbf5679

…ng the GC performance in native and JVM

bug fix, there was an extra slash causing errors

2513829

changed wildcard imports to normal import statements

c8abab9

deleted unnecessary options from mvn command

5ffaabe

create a helper class and a method for uploading Hyperfoil benchmarks

247ad9f

added new regex pattern for matching GC logs in Mandrel >=23.1

1890e1d

lowered the usersPerSec number and removed concats

374d296

added vertx's "failed to register channel" warning to whitelist

693ece6

patrikcerbak force-pushed the serialgc-test branch from 0701c42 to 693ece6 Compare September 5, 2025 10:00

added basic time threshold checking for the gc comparison test

6f14a47

edited the new GC pause time regexes to match logs on Mandrel 24.x

124ac9b

Karm self-requested a review September 11, 2025 11:10

edited the Hyperfoil config to make requests to all URLs one by one, …

dcc31b6

…not choose a random one

tweaking the config parameters

cb99889

added the "pool depleted, throttling execution" warning into the whit…

0eee14e

…elist

patrikcerbak force-pushed the serialgc-test branch from 057e034 to 0eee14e Compare September 25, 2025 13:16

patrikcerbak marked this pull request as ready for review September 25, 2025 14:45

Allow list warnings count messages for GraalVM 26+

9c3b09e

Covers the following 4 tests: - JFRTest#jfrPerfTest - DebugSymbolsTest#debugSymbolsQuarkus - RuntimesSmokeTest#helidonQuickStart - RuntimesSmokeTest#quarkusFullMicroProfile Closes: Karm#364

patrikcerbak force-pushed the serialgc-test branch from 2e5c399 to 9c3b09e Compare September 29, 2025 11:06

Merge branch 'master' into serialgc-test

5ba6901

patrikcerbak mentioned this pull request Sep 30, 2025

event syntax error: 'topdown-retiring/metric-id=topdown!1retiring/,TOPDOWN.SL..' #372

Closed

Karm merged commit 20b07dd into Karm:master Oct 6, 2025
43 checks passed

[WIP] Started implementing compareNativeAndJVMSerialGCTime test #355

[WIP] Started implementing compareNativeAndJVMSerialGCTime test #355

Uh oh!

Conversation

patrikcerbak commented Jul 18, 2025

Work in progress

Uh oh!

jerboaa left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

patrikcerbak commented Aug 7, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Karm left a comment • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Karm Aug 11, 2025

Choose a reason for hiding this comment

Uh oh!

patrikcerbak Aug 12, 2025

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Karm Aug 11, 2025

Choose a reason for hiding this comment

Uh oh!

patrikcerbak Aug 12, 2025

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

patrikcerbak commented Aug 13, 2025

Uh oh!

Karm commented Aug 14, 2025

Uh oh!

patrikcerbak commented Aug 14, 2025

Uh oh!

patrikcerbak commented Aug 14, 2025

Uh oh!

Karm commented Aug 14, 2025

Uh oh!

Karm commented Aug 28, 2025

Uh oh!

patrikcerbak commented Aug 28, 2025

Uh oh!

Karm commented Sep 4, 2025

Uh oh!

patrikcerbak commented Sep 4, 2025

Uh oh!

patrikcerbak commented Sep 4, 2025

Uh oh!

Karm commented Sep 4, 2025

Uh oh!

Karm commented Sep 9, 2025

Uh oh!

patrikcerbak commented Sep 10, 2025

Uh oh!

patrikcerbak commented Sep 10, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Karm commented Sep 11, 2025

Uh oh!

patrikcerbak commented Sep 11, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

patrikcerbak commented Sep 15, 2025

Uh oh!

Karm commented Sep 15, 2025

Uh oh!

patrikcerbak commented Sep 16, 2025

Uh oh!

patrikcerbak commented Sep 25, 2025

Uh oh!

Karm commented Sep 28, 2025

Uh oh!

patrikcerbak commented Aug 7, 2025 •

edited

Loading

Karm left a comment •

edited

Loading

patrikcerbak commented Sep 10, 2025 •

edited

Loading

patrikcerbak commented Sep 11, 2025 •

edited

Loading