Intermittent GC spikes with adaptive policy

[NemanjaBozovic-TomTom]

Describe the issue
During the load testing we discovered that (serial) garbage collector with adaptive policy have spikes in number of collection even tho for the whole test load stays more or less the same.

In attached picture we can see whole test run

and in this one zoomed in part of problematic area.

What I want to highlight is one example of spikes at 12:38, that lasts for about 25 seconds. In GC types graph on pics, we can see that number of GC events sharply rises, but their individual duration is not rising. Allocation rate stays roughly constant.

We can see that during that period "pre" memory (allocated memory when GC is triggered) is much smaller than usual. For example at time 2273861, which is right before problematic area, in logs we have Incremental GC with: 90133K->10261K
and then memory before collection starts to fall to 16811K->12203K at time 2280089 which is in bad area.

What could cause this behavior? It seems like young generation has shrunk and that causes GC to kick in earlier.
Attached are full GC logs

Steps to reproduce the issue
Cannot make reproducible example that doesn't uses our proprietary code.

Describe GraalVM and your environment:

• GraalVM version: 22.3.0
• JDK major version: 11
• OS: Linux custom
• Architecture: ARM64

arguments.txt
full_gc_data_compressed.zip
GCData.csv
notes.txt
zoom_in_gc_logs.txt

[galderz]

@NemanjaBozovic-TomTom By amazing coincidence, just this week I've been playing around with some visualizations for analysing native image GC logs and here's what I see having run it through the data in full_gc_data_compressed.zip:

Total pause times match what you see:

Heap used before counts also show the odd low numbers:

As well as the low reclaimed numbers around the times of low heap used before counts:

What I see different is the allocation rate. The mean allocation rate does look similar shape to yours, but the max allocation rate spikes up at times of problems. This is calculated using the heap before and heap after numbers, so the odd numbers in heap before could be causing this. How is the allocation rate calculated in your charts?

It's a pity that this is happening in proprietary code and you cannot share the reproducer with us. However, could you give us some information about what the application does so that we can try to replicate it? E.g. is it pure java or is it using frameworks such as Quarkus, Micronaut...etc? Does it connect to any external resources (e.g. db, messaging) or is it self contained? Is it a batch process or is it consuming some kind of incoming load like http requests?

If you can reproduce it again, it'd be useful for us if you could run with strace and attach the output during a poblematic phase. The output might be big so if you need to filter mmap,munmap,malloc are the system calls that we're most interested in.

From the data you've provided it's unclear if this is an issue specific to adaptive GC policy itself. For example, if you use space/time GC policy, does the issue go away? You can try this by passing in -H:InitialCollectionPolicy=com.oracle.svm.core.genscavenge.CollectionPolicy\$BySpaceAndTime at native image build time. Escaping $ is necessary if passing in via command line. I've explored this area before since we switched Quarkus to use adaptive instead of space/time GC policy late last year. You can see the result of these investigation here.

One final thing we've noticed is the use of -XX:MaximumYoungGenerationSizePercent=75 as argument. The default is 10%. Did you encounter issues with just 10%?

More things you can try:

• Try with JDK 17 instead of 11 and see if it makes any difference.
• GraalVM 23.0 will be released next week, so can wait to try that or try the latest pre-release here.

[chflood]

If you do run an strace, could you also add -tt so we can align the mmap calls to the graphs?

[MichalWlodarczyk-TomTom]

We are already using GraalVM 23.0 and JDK 17, since we have also been running some tests with Parallel GC.

Giving some more context on the application. It's pure Kotlin, and it's not using any 3rd party frameworks like Quarkus or Micronaut. It's a real-time application. It processes location updates of a fixed cadence (1 Hz). Per each update, multiple operations are performed to generate output events. Once per a few ticks, the application connects to online APIs, and then the response is deserialized and handled further.

We've been testing with the BySpaceAndTime policy also. In that case, we do not observe any peaks; see attached screenshot. However, on average, the total time spent in GC is higher than when using the Adaptive policy, and the total pause time in windows is also higher.

As for MaximumYoungGenerationSizePercent=75, we are playing with different options. For our application, that configuration outputs the best results so far.

@chflood : We will add -tt for further runs to get more data.

@galderz : Any new thoughts?

[oubidar-Abderrahim]

@NemanjaBozovic-TomTom Thank you for sharing this, could you please verify if similar behavior is observed in GraalVM 22.3.2?

[NemanjaBozovic-TomTom]

Hey.

We don't see any difference.
And we actually found a bug in our code that allocated millions of (small) objects per second. Once we fix that, we have seen no spikes whatsoever.

Unless I find time to create a simple reproducer that I can share I'll close a ticket, because running on our custom hardware requires a huge effort.