@TestProfile do not 'release' Metaspace on each profile run

[gkozyryatskyy]

Describe the bug

When you run few tests with @TestProfile and different profiles in a row, jvm Metaspace consumption incrementally increased.

Expected behavior

Next (after first) @TestProfile executions not lead to MEM consumption increase.

Actual behavior

Currently when you run few tests with @TestProfile and different profiles in a row, jvm Metaspace consumption incrementally increased. Log example from my test:

total:[377]mb free:[203]mb max:[800]mb, meta:[93]mb
total:[587]mb free:[321]mb max:[800]mb, meta:[174]mb
total:[662]mb free:[305]mb max:[800]mb, meta:[252]mb
total:[776]mb free:[180]mb max:[800]mb, meta:[329]mb
total:[776]mb free:[302]mb max:[800]mb, meta:[337]mb
total:[800]mb free:[253]mb max:[800]mb, meta:[407]mb
total:[800]mb free:[254]mb max:[800]mb, meta:[429]mb
total:[800]mb free:[180]mb max:[800]mb, meta:[499]mb
total:[800]mb free:[79]mb max:[800]mb, meta:[575]mb
total:[800]mb free:[54]mb max:[800]mb, meta:[648]mb

Where each line is from separate @TestProfile execution

• total is Runtime.getRuntime().totalMemory()
• free is Runtime.getRuntime().freeMemory()
• max is Runtime.getRuntime().maxMemory()
• total is

  public static long metaspace() {
      for (MemoryPoolMXBean memoryMXBean : ManagementFactory.getMemoryPoolMXBeans()) {
          if ("Metaspace".equals(memoryMXBean.getName())) {
              return memoryMXBean.getUsage().getUsed();
          }
      }
      return 0;
  }

How to Reproduce?

Reproducer can be 'unclear', but i created some https://github.com/gkozyryatskyy/quarkus-test-mem-leak-reproducer so you can understand the problem. I add some random dependency and classes to the reproducer, for app to @Inject at leas something. I assume, as more Injection we have, as more Metaspace is consumed for each run. But you are interested in tests execution https://github.com/gkozyryatskyy/quarkus-test-mem-leak-reproducer/tree/main/src/test/java

In my 'real' project tests, Metaspace consumption is worse.

Output of uname -a or ver

macOs 13.3.1 (a)

Output of java -version

openjdk version "19.0.1" 2022-10-18

GraalVM version (if different from Java)

No response

Quarkus version or git rev

3.1.0.Final

Build tool (ie. output of mvnw --version or gradlew --version)

Apache Maven 3.9.0 (9b58d2bad23a66be161c4664ef21ce219c2c8584)

Additional information

No response

[gsmet]

/cc @geoand

[geoand]

I don't see any problems.

If you actually size the Metaspace properly to provide headroom to load all the classes (I used -XX:MaxMetaspaceSize=390m), the JVM will properly GC the unused classes (i.e. application classes that are loaded by no longer used Quarkus ClassLoaders).

Here is a Graph a got from YourKit that shows GC of Metaspace in action:

[gkozyryatskyy]

@geoand Thank you for your reply!

The screen, you provided is from my reproducer? What you see in the logs? I see next picture:

===================Start: total:[267]mb free:[131]mb max:[1024]mb meta:[79]mb===================
===================End: total:[941]mb free:[5]mb max:[1024]mb meta:[79]mb===================
===================Start: total:[514]mb free:[249]mb max:[1024]mb meta:[137]mb===================
===================End: total:[1024]mb free:[47]mb max:[1024]mb meta:[137]mb===================
===================Start: total:[890]mb free:[613]mb max:[1024]mb meta:[194]mb===================
===================End: total:[1024]mb free:[58]mb max:[1024]mb meta:[194]mb===================
===================Start: total:[437]mb free:[241]mb max:[1024]mb meta:[196]mb===================
===================End: total:[985]mb free:[8]mb max:[1024]mb meta:[196]mb===================
===================Start: total:[907]mb free:[502]mb max:[1024]mb meta:[253]mb===================
===================End: total:[1024]mb free:[13]mb max:[1024]mb meta:[253]mb===================
===================Start: total:[607]mb free:[427]mb max:[1024]mb meta:[196]mb===================
===================End: total:[978]mb free:[8]mb max:[1024]mb meta:[196]mb===================
===================Start: total:[874]mb free:[469]mb max:[1024]mb meta:[253]mb===================
===================End: total:[1024]mb free:[14]mb max:[1024]mb meta:[253]mb===================

and it shows that metaspace is growing.

I also will run it with -XX:MaxMetaspaceSize, as you suggested, but lets set enough Metaspace for few profile runs, but not to all of them, because all tests are equivalent and should not increate Metaspace consumption after first run

Running with mvn install -DargLine='-Xmx1024m -XX:MaxMetaspaceSize=200m'

• 1st test is passed, so we have enough metaspace for single application

• next test are failed with metaspace exception 1st test

  ===================Start: total:[260]mb free:[114]mb max:[1024]mb meta:[79]mb===================
  ===================End: total:[950]mb free:[4]mb max:[1024]mb meta:[79]mb===================

  Tests after 1st

  
  java.lang.RuntimeException: io.quarkus.builder.BuildException: Build failure: Build failed due to errors
      [error]: Build step io.quarkus.arc.deployment.ArcProcessor#generateResources threw an exception: java.lang.OutOfMemoryError: Metaspace
      at java.base/java.lang.ClassLoader.defineClass1(Native Method)
      at java.base/java.lang.ClassLoader.defineClass(ClassLoader.java:1013)
      at io.quarkus.bootstrap.classloading.QuarkusClassLoader.loadClass(QuarkusClassLoader.java:506)
      at io.quarkus.bootstrap.classloading.QuarkusClassLoader.loadClass(QuarkusClassLoader.java:466)
      at io.quarkus.arc.processor.BeanProcessor.generateResources(BeanProcessor.java:190)
      at io.quarkus.arc.deployment.ArcProcessor.generateResources(ArcProcessor.java:575)
      at java.base/java.lang.invoke.LambdaForm$DMH/0x000000080147c000.invokeVirtual(LambdaForm$DMH)
      at java.base/java.lang.invoke.LambdaForm$MH/0x00000008016c7800.invoke(LambdaForm$MH)
      at java.base/java.lang.invoke.LambdaForm$MH/0x00000008016c5400.invoke(LambdaForm$MH)
      at java.base/java.lang.invoke.Invokers$Holder.invokeExact_MT(Invokers$Holder)
      at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invokeImpl(DirectMethodHandleAccessor.java:158)
      at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
      at java.base/java.lang.reflect.Method.invoke(Method.java:578)
      at io.quarkus.deployment.ExtensionLoader$3.execute(ExtensionLoader.java:909)
      at io.quarkus.builder.BuildContext.run(BuildContext.java:282)
      at io.quarkus.builder.BuildContext$$Lambda$1831/0x0000000801c89510.run(Unknown Source)
      at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18)
      at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2513)
      at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1538)
      at java.base/java.lang.Thread.runWith(Thread.java:1636)
      at java.base/java.lang.Thread.run(Thread.java:1623)
      at org.jboss.threads.JBossThread.run(JBossThread.java:501)
  
      [error]: Build step io.quarkus.datasource.deployment.devservices.DevServicesDatasourceProcessor#launchDatabases threw an exception: java.lang.RuntimeException: java.lang.OutOfMemoryError: Metaspace
      at io.quarkus.datasource.deployment.devservices.DevServicesDatasourceProcessor.startDevDb(DevServicesDatasourceProcessor.java:347)
      at io.quarkus.datasource.deployment.devservices.DevServicesDatasourceProcessor.launchDatabases(DevServicesDatasourceProcessor.java:136)
      at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
      at java.base/java.lang.reflect.Method.invoke(Method.java:578)
      at io.quarkus.deployment.ExtensionLoader$3.execute(ExtensionLoader.java:909)
      at io.quarkus.builder.BuildContext.run(BuildContext.java:282)
      at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18)
      at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2513)
      at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1538)
      at java.base/java.lang.Thread.run(Thread.java:1623)
      at org.jboss.threads.JBossThread.run(JBossThread.java:501)
  Caused by: java.lang.OutOfMemoryError: Metaspace
      at io.quarkus.devservices.postgresql.deployment.PostgresqlDevServicesProcessor$1.startDatabase(PostgresqlDevServicesProcessor.java:49)
      at io.quarkus.datasource.deployment.devservices.DevServicesDatasourceProcessor.startDevDb(DevServicesDatasourceProcessor.java:284)
      at io.quarkus.datasource.deployment.devservices.DevServicesDatasourceProcessor.launchDatabases(DevServicesDatasourceProcessor.java:136)
      at java.base/java.lang.invoke.LambdaForm$DMH/0x00000008013c4000.invokeVirtual(LambdaForm$DMH)
      at java.base/java.lang.invoke.LambdaForm$MH/0x0000000801d48400.invoke(LambdaForm$MH)
      at java.base/java.lang.invoke.LambdaForm$MH/0x000000080118c000.invoke(LambdaForm$MH)
      at java.base/java.lang.invoke.Invokers$Holder.invokeExact_MT(Invokers$Holder)
      at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invokeImpl(DirectMethodHandleAccessor.java:158)
      at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
      at java.base/java.lang.reflect.Method.invoke(Method.java:578)
      at io.quarkus.deployment.ExtensionLoader$3.execute(ExtensionLoader.java:909)
      at io.quarkus.builder.BuildContext.run(BuildContext.java:282)
      at io.quarkus.builder.BuildContext$$Lambda$1831/0x0000000801c89510.run(Unknown Source)
      at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18)
      at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2513)
      at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1538)
      at java.base/java.lang.Thread.runWith(Thread.java:1636)
      ... 2 more

[geoand]

The screen, you provided is from my reproducer?

Yes, your sampple with double the number profiles / tests

[gkozyryatskyy]

@geoand Sorry, I not finished previous comment (published unfinished). Now I updated it with -XX:MaxMetaspaceSize run. Please check.

[geoand]

That's why I said the metaspace needs to be sized properly.

[gkozyryatskyy]

@geoand but this is exactly the problem, if we have enough metaspce for a single profile run, we should be able to run any number of profiles sequentially with the same metaspace limit.

As i mentioned, in my 'real' project metaspace consumption is worse. It is starting from meta:[93]mb and ends up with meta:[648]mb. So you are saying this is ok and i just need to give more and more MEM when Im adding more profiles?

[geoand]

but this is exactly the problem, if we have enough metaspce for a single profile run

That's not what I said, I said we need enough to get things running. Obviously you should not be required to have the entire Metaspace

[geoand]

So you are saying this is ok and i just need to give more and more MEM when Im adding more profiles?

What I am saying is that I took your sample, and whether or not I doubled the profiles, I still needed around 300MB of metaspace to run it. The doubling of the profile was only done to introduce more GCs, which actually happened as expected.

[gkozyryatskyy]

@geoand Got your point. But this is strange that we can run fist profile and cant run others.

In some time I will try to reproduce the problem with -XX:MaxMetaspaceSize=390m, will let you know, if I will found anything.

Thank you for your help!

[geoand]

🙏🏼