More tests leaking

[Sanne]

Describe the bug

If I take a heap dump of the hibernate-orm deployment integration tests, there is a number of new leaks.

An interesting clue was reported by the thread_overview report from MAT:

Object / Stack Frame         |Name                    | Shallow Heap | Retained Heap | Max. Locals' Retained Heap |Context Class Loader                                             |Is Daemon| Priority |State| State value
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
java.lang.Thread @ 0xa6fa8a20|Database shutdown thread|          112 |           496 |                            |io.quarkus.bootstrap.classloading.QuarkusClassLoader @ 0xa634b288|false    |        5 |[]   |         0x0
java.lang.Thread @ 0xae153e10|Database shutdown thread|          112 |           504 |                            |io.quarkus.bootstrap.classloading.QuarkusClassLoader @ 0xb1ccc540|false    |        5 |[]   |         0x0
java.lang.Thread @ 0xbbb4ac00|Database shutdown thread|          112 |           504 |                            |io.quarkus.bootstrap.classloading.QuarkusClassLoader @ 0xbacc2fb0|false    |        5 |[]   |         0x0
java.lang.Thread @ 0xb8f9d210|Database shutdown thread|          112 |           504 |                            |io.quarkus.bootstrap.classloading.QuarkusClassLoader @ 0xbad044e0|false    |        5 |[]   |         0x0
java.lang.Thread @ 0xbcc60870|Database shutdown thread|          112 |           504 |                            |io.quarkus.bootstrap.classloading.QuarkusClassLoader @ 0xbde368e8|false    |        5 |[]   |         0x0
java.lang.Thread @ 0xcce8c5d0|Database shutdown thread|          112 |           504 |                            |io.quarkus.bootstrap.classloading.QuarkusClassLoader @ 0xcce8bdf8|false    |        5 |[]   |         0x0
java.lang.Thread @ 0xd3c44ea8|Database shutdown thread|          112 |           496 |                            |io.quarkus.bootstrap.classloading.QuarkusClassLoader @ 0xd3c19d58|false    |        5 |[]   |         0x0
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------

Note how each thread with the same name "Database shutdown thread" is having a different context classloader.

cc/ @stuartwdouglas does this ring a bell?

Expected behavior

We should see a single Database shutdown thread alive at any given time.

How to Reproduce?

Run mvn clean verify -pl :quarkus-hibernate-orm -Dstart-containers -Dtest-containers

Capture heap at approximately the end, hopefully before it crashes in lack of metaspace.

Quarkus version or git rev

9aa9a5ad85

[Sanne]

A more interesting sample:

Object / Stack Frame                       |Name                                 | Shallow Heap | Retained Heap | Max. Locals' Retained Heap |Context Class Loader                                             |Is Daemon| Priority |State       | State value
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
io.vertx.core.impl.VertxThread @ 0xb2a1c680|[DevConsole]vert.x-eventloop-thread-0|          152 |           248 |                            |io.quarkus.bootstrap.classloading.QuarkusClassLoader @ 0xb1ccc540|false    |        5 |[terminated]|         0x2
io.vertx.core.impl.VertxThread @ 0xb5cdd238|[DevConsole]vert.x-eventloop-thread-0|          152 |           248 |                            |io.quarkus.bootstrap.classloading.QuarkusClassLoader @ 0xbacc2fb0|false    |        5 |[terminated]|         0x2
io.vertx.core.impl.VertxThread @ 0xba98b058|[DevConsole]vert.x-eventloop-thread-0|          152 |           248 |                            |io.quarkus.bootstrap.classloading.QuarkusClassLoader @ 0xbad044e0|false    |        5 |[terminated]|         0x2
io.vertx.core.impl.VertxThread @ 0xbc1e6bc8|[DevConsole]vert.x-eventloop-thread-0|          152 |           248 |                            |io.quarkus.bootstrap.classloading.QuarkusClassLoader @ 0xbde368e8|false    |        5 |[terminated]|         0x2
io.vertx.core.impl.VertxThread @ 0xce068df8|[DevConsole]vert.x-eventloop-thread-0|          152 |           248 |                            |io.quarkus.bootstrap.classloading.QuarkusClassLoader @ 0xcce8bdf8|false    |        5 |[terminated]|         0x2
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------

N.B. I had prefixed the names of Vert.x threads generated by the DevConsole with [DevConsole] so to be able to catch duplication with the main production vert.x instance.

It seems we're having multiple DevConsole instances running.

[stuartwdouglas]

The database ones are the H2 shutdown hook thread. Maybe the dev ui is not being shutdown properly.

[stuartwdouglas]

Those Dev UI threads are terminated, they are not the issue.

[Sanne]

Ah I just realized these threads are indeed terminated. But they are still referred so can't be garbage collected

Class Name                                                                                                          | Shallow Heap | Retained Heap
---------------------------------------------------------------------------------------------------------------------------------------------------
io.vertx.core.impl.VertxThread @ 0xbde5e4c0  [DevConsole]vert.x-acceptor-thread-0                                   |          152 |           248
'- thread io.netty.channel.nio.NioEventLoop @ 0xb9bedde0                                                            |          152 |        14,464
   '- [0] io.netty.util.concurrent.EventExecutor[1] @ 0xb9beddc8                                                    |           24 |            24
      '- children io.netty.channel.nio.NioEventLoopGroup @ 0xb9bedda8                                               |           32 |        14,776
         '- acceptorEventLoopGroup io.vertx.core.impl.VertxImpl @ 0xb9bed540                                        |          168 |        18,976
            '- vertx io.vertx.ext.web.impl.RouterImpl @ 0xbbba6850                                                  |           24 |           344
               '- mainRouter class io.quarkus.vertx.http.deployment.devmode.console.DevConsoleProcessor @ 0xb9bed358|           48 |       870,456
---------------------------------------------------------------------------------------------------------------------------------------------------

[Sanne]

Class Name                                                                                                       | Shallow Heap | Retained Heap
------------------------------------------------------------------------------------------------------------------------------------------------
java.lang.Thread @ 0xb8f9d210  Database shutdown thread                                                          |          112 |           504
'- val$closeHookThread io.quarkus.datasource.deployment.devservices.DevServicesDatasourceProcessor$2 @ 0xb8f9d1f8|           24 |           528
   '- [1] java.lang.Object[49] @ 0xba1aeda8                                                                      |          216 |       246,648
      '- elementData java.util.ArrayList @ 0xbad1bb10                                                            |           24 |       246,672
         '- closeTasks io.quarkus.bootstrap.classloading.QuarkusClassLoader @ 0xbad60058                         |          128 |    10,868,128
------------------------------------------------------------------------------------------------------------------------------------------------

[Sanne]

I'll try to reset closeTasks on QuarkusClassLoader#close

[stuartwdouglas]

That is not the issue, if QuarkusClassLoader is still referenced then that is the leak. Anything held by it does not matter, as it will be released when the CL is released.

[Sanne]

good point, I was getting confused.

I should reduce the number of default threads being started on my machine, it's overwhelming.

On Tue, 3 Aug 2021, 14:02 Stuart Douglas, @.***> wrote:

That is not the issue, if QuarkusClassLoader is still referenced then that is the leak. Anything held by it does not matter, as it will be released when the CL is released.

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/quarkusio/quarkus/issues/19202#issuecomment-891828157, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAAKMTNF2K2MJ5W3LN6GIHDT27SHBANCNFSM5BOXRQEQ .

[Sanne]

So it seems like many "leaks" I was seeing in MAT today were induced by the fact I was running GraalVM as JDK: apparently in this case when taking heap dumps some classes were being flagged as "JNI Global" GC Roots, and with the class they would also pin the classloader. My hunch is that these classes were being compiled at this time.

I'll close this. Lesson learned: don't use GraalVM for heap analysis - at least until I figure out what was going on.