memory leak when using in combination with datasource-decorator from observations

[cmdjulian]

When using your library (which I really do like, thx btw) in combination with Spring Data Datasource Decorator, a library which wraps the original data source and enhances it with different kind of loggings for instance for slow query logs, a memory leak emerges after some time.
I tried to find out what might be the problem, I only found out, removing the mentioned dependency, the leak vanishes. I also tried using an older version of datasource-micrometer but all seem to have that problem. I'm unsure if the problem is within your lib or in Spring Data Datasource Decorator, but as the stacktraces from the heap dumps hint towards your library creating this excessive objects my guess would be the problem lying here somewhere.

I build a small reproducer at https://github.com/cmdjulian/datasource-micrometer-leak. When you run it, after some time you see the heap getting crowded with SimpleObservation objects.

Leaker thread stacktrace

```text main at io.micrometer.observation.SimpleObservation$SimpleScope.getLastScope(Lio/micrometer/observation/SimpleObservation$SimpleScope;)Lio/micrometer/observation/SimpleObservation$SimpleScope; (SimpleObservation.java:327) at io.micrometer.observation.SimpleObservation$SimpleScope.close()V (SimpleObservation.java:303) at net.ttddyy.observation.tracing.DataSourceObservationListener.handleConnectionClose(Lnet/ttddyy/dsproxy/listener/MethodExecutionContext;)V (DataSourceObservationListener.java:306) at net.ttddyy.observation.tracing.DataSourceObservationListener.afterMethod(Lnet/ttddyy/dsproxy/listener/MethodExecutionContext;)V (DataSourceObservationListener.java:211) at net.ttddyy.dsproxy.listener.CompositeMethodListener.afterMethod(Lnet/ttddyy/dsproxy/listener/MethodExecutionContext;)V (CompositeMethodListener.java:25) at net.ttddyy.dsproxy.listener.MethodExecutionListenerUtils.invoke(Lnet/ttddyy/dsproxy/listener/MethodExecutionListenerUtils$MethodExecutionCallback;Lnet/ttddyy/dsproxy/proxy/ProxyConfig;Ljava/lang/Object;Lnet/ttddyy/dsproxy/ConnectionInfo;Ljava/lang/reflect/Method;[Ljava/lang/Object;)Ljava/lang/Object; (MethodExecutionListenerUtils.java:53) at net.ttddyy.dsproxy.proxy.ConnectionProxyLogic.invoke(Ljava/lang/Object;Ljava/lang/reflect/Method;[Ljava/lang/Object;)Ljava/lang/Object; (ConnectionProxyLogic.java:47) at net.ttddyy.dsproxy.proxy.jdk.ConnectionInvocationHandler.invoke(Ljava/lang/Object;Ljava/lang/reflect/Method;[Ljava/lang/Object;)Ljava/lang/Object; (ConnectionInvocationHandler.java:25) at jdk.proxy2.$Proxy80.close()V () at java.lang.invoke.LambdaForm$DMH+0x00007fabac3b0800.invokeInterface(Ljava/lang/Object;Ljava/lang/Object;)V (LambdaForm$DMH) at java.lang.invoke.LambdaForm$MH+0x00007fabac9ef000.invoke(Ljava/lang/Object;Ljava/lang/Object;)Ljava/lang/Object; (LambdaForm$MH) at java.lang.invoke.Invokers$Holder.invokeExact_MT(Ljava/lang/Object;Ljava/lang/Object;Ljava/lang/Object;)Ljava/lang/Object; (Invokers$Holder) at jdk.internal.reflect.DirectMethodHandleAccessor.invokeImpl(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object; (DirectMethodHandleAccessor.java:153) at jdk.internal.reflect.DirectMethodHandleAccessor.invoke(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object; (DirectMethodHandleAccessor.java:103) at java.lang.reflect.Method.invoke(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object; (Method.java:580) at net.ttddyy.dsproxy.proxy.ConnectionProxyLogic.performQueryExecutionListener(Ljava/lang/Object;Ljava/lang/reflect/Method;[Ljava/lang/Object;)Ljava/lang/Object; (ConnectionProxyLogic.java:116) at net.ttddyy.dsproxy.proxy.ConnectionProxyLogic.access$000(Lnet/ttddyy/dsproxy/proxy/ConnectionProxyLogic;Ljava/lang/Object;Ljava/lang/reflect/Method;[Ljava/lang/Object;)Ljava/lang/Object; (ConnectionProxyLogic.java:25) at net.ttddyy.dsproxy.proxy.ConnectionProxyLogic$1.execute(Ljava/lang/Object;Ljava/lang/reflect/Method;[Ljava/lang/Object;)Ljava/lang/Object; (ConnectionProxyLogic.java:50) at net.ttddyy.dsproxy.listener.MethodExecutionListenerUtils.invoke(Lnet/ttddyy/dsproxy/listener/MethodExecutionListenerUtils$MethodExecutionCallback;Lnet/ttddyy/dsproxy/proxy/ProxyConfig;Ljava/lang/Object;Lnet/ttddyy/dsproxy/ConnectionInfo;Ljava/lang/reflect/Method;[Ljava/lang/Object;)Ljava/lang/Object; (MethodExecutionListenerUtils.java:42) at net.ttddyy.dsproxy.proxy.ConnectionProxyLogic.invoke(Ljava/lang/Object;Ljava/lang/reflect/Method;[Ljava/lang/Object;)Ljava/lang/Object; (ConnectionProxyLogic.java:47) at net.ttddyy.dsproxy.proxy.jdk.ConnectionInvocationHandler.invoke(Ljava/lang/Object;Ljava/lang/reflect/Method;[Ljava/lang/Object;)Ljava/lang/Object; (ConnectionInvocationHandler.java:25) at jdk.proxy2.$Proxy80.close()V () at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.closeConnection(Ljava/sql/Connection;)V (DatasourceConnectionProviderImpl.java:127) at org.hibernate.internal.NonContextualJdbcConnectionAccess.releaseConnection(Ljava/sql/Connection;)V (NonContextualJdbcConnectionAccess.java:64) at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.releaseConnection()V (LogicalConnectionManagedImpl.java:224) at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.close()Ljava/sql/Connection; (LogicalConnectionManagedImpl.java:258) at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.close()Ljava/sql/Connection; (JdbcCoordinatorImpl.java:161) at org.hibernate.internal.AbstractSharedSessionContract.close()V (AbstractSharedSessionContract.java:442) at org.hibernate.internal.SessionImpl.closeWithoutOpenChecks()V (SessionImpl.java:409) at org.hibernate.internal.SessionImpl.close()V (SessionImpl.java:391) at org.springframework.orm.jpa.EntityManagerFactoryUtils.closeEntityManager(Ljakarta/persistence/EntityManager;)V (EntityManagerFactoryUtils.java:424) at org.springframework.orm.jpa.JpaTransactionManager.doCleanupAfterCompletion(Ljava/lang/Object;)V (JpaTransactionManager.java:654) at org.springframework.transaction.support.AbstractPlatformTransactionManager.cleanupAfterCompletion(Lorg/springframework/transaction/support/DefaultTransactionStatus;)V (AbstractPlatformTransactionManager.java:1061) at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(Lorg/springframework/transaction/support/DefaultTransactionStatus;)V (AbstractPlatformTransactionManager.java:846) at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(Lorg/springframework/transaction/TransactionStatus;)V (AbstractPlatformTransactionManager.java:757) at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(Lorg/springframework/transaction/interceptor/TransactionAspectSupport$TransactionInfo;)V (TransactionAspectSupport.java:676) at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(Ljava/lang/reflect/Method;Ljava/lang/Class;Lorg/springframework/transaction/interceptor/TransactionAspectSupport$InvocationCallback;)Ljava/lang/Object; (TransactionAspectSupport.java:426) at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(Lorg/aopalliance/intercept/MethodInvocation;)Ljava/lang/Object; (TransactionInterceptor.java:119) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed()Ljava/lang/Object; (ReflectiveMethodInvocation.java:184) at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(Lorg/aopalliance/intercept/MethodInvocation;)Ljava/lang/Object; (PersistenceExceptionTranslationInterceptor.java:137) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed()Ljava/lang/Object; (ReflectiveMethodInvocation.java:184) at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(Lorg/aopalliance/intercept/MethodInvocation;)Ljava/lang/Object; (CrudMethodMetadataPostProcessor.java:164) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed()Ljava/lang/Object; (ReflectiveMethodInvocation.java:184) at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(Lorg/aopalliance/intercept/MethodInvocation;)Ljava/lang/Object; (ExposeInvocationInterceptor.java:97) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed()Ljava/lang/Object; (ReflectiveMethodInvocation.java:184) at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(Ljava/lang/Object;Ljava/lang/reflect/Method;[Ljava/lang/Object;)Ljava/lang/Object; (JdkDynamicAopProxy.java:223) at jdk.proxy2.$Proxy119.deleteById(Ljava/lang/Object;)V () at com.example.demo.DemoApplication.lambda$onStart$0(Lcom/example/demo/TestRepository;[Ljava/lang/String;)V (DemoApplication.java:32) at com.example.demo.DemoApplication$$Lambda+0x00007fabac8f2628.run([Ljava/lang/String;)V () at org.springframework.boot.SpringApplication.lambda$callRunner$5(Lorg/springframework/boot/ApplicationArguments;Lorg/springframework/boot/CommandLineRunner;)V (SpringApplication.java:790) at org.springframework.boot.SpringApplication$$Lambda+0x00007fabac9a8868.acceptWithException(Ljava/lang/Object;)V () at org.springframework.util.function.ThrowingConsumer$1.acceptWithException(Ljava/lang/Object;)V (ThrowingConsumer.java:83) at org.springframework.util.function.ThrowingConsumer.accept(Ljava/lang/Object;Ljava/util/function/BiFunction;)V (ThrowingConsumer.java:60) at org.springframework.util.function.ThrowingConsumer$1.accept(Ljava/lang/Object;)V (ThrowingConsumer.java:88) at org.springframework.boot.SpringApplication.callRunner(Ljava/lang/Class;Lorg/springframework/boot/Runner;Lorg/springframework/util/function/ThrowingConsumer;)V (SpringApplication.java:798) at org.springframework.boot.SpringApplication.callRunner(Lorg/springframework/boot/Runner;Lorg/springframework/boot/ApplicationArguments;)V (SpringApplication.java:789) at org.springframework.boot.SpringApplication.lambda$callRunners$3(Lorg/springframework/boot/ApplicationArguments;Lorg/springframework/boot/Runner;)V (SpringApplication.java:774) at org.springframework.boot.SpringApplication$$Lambda+0x00007fabac9a8440.accept(Ljava/lang/Object;)V () at java.util.stream.ForEachOps$ForEachOp$OfRef.accept(Ljava/lang/Object;)V (ForEachOps.java:184) at java.util.stream.SortedOps$SizedRefSortingSink.end()V (SortedOps.java:357) at java.util.stream.AbstractPipeline.copyInto(Ljava/util/stream/Sink;Ljava/util/Spliterator;)V (AbstractPipeline.java:510) at java.util.stream.AbstractPipeline.wrapAndCopyInto(Ljava/util/stream/Sink;Ljava/util/Spliterator;)Ljava/util/stream/Sink; (AbstractPipeline.java:499) at java.util.stream.ForEachOps$ForEachOp.evaluateSequential(Ljava/util/stream/PipelineHelper;Ljava/util/Spliterator;)Ljava/lang/Void; (ForEachOps.java:151) at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(Ljava/util/stream/PipelineHelper;Ljava/util/Spliterator;)Ljava/lang/Object; (ForEachOps.java:174) at java.util.stream.AbstractPipeline.evaluate(Ljava/util/stream/TerminalOp;)Ljava/lang/Object; (AbstractPipeline.java:234) at java.util.stream.ReferencePipeline.forEach(Ljava/util/function/Consumer;)V (ReferencePipeline.java:596) at org.springframework.boot.SpringApplication.callRunners(Lorg/springframework/context/ConfigurableApplicationContext;Lorg/springframework/boot/ApplicationArguments;)V (SpringApplication.java:774) at org.springframework.boot.SpringApplication.run([Ljava/lang/String;)Lorg/springframework/context/ConfigurableApplicationContext; (SpringApplication.java:341) at org.springframework.boot.SpringApplication.run([Ljava/lang/Class;[Ljava/lang/String;)Lorg/springframework/context/ConfigurableApplicationContext; (SpringApplication.java:1354) at org.springframework.boot.SpringApplication.run(Ljava/lang/Class;[Ljava/lang/String;)Lorg/springframework/context/ConfigurableApplicationContext; (SpringApplication.java:1343) at com.example.demo.DemoApplication.main([Ljava/lang/String;)V (DemoApplication.java:15) ```

The hot fix at the moment is to simply disabling observation auto config via spring.autoconfigure.exclude=net.ttddyy.observation.boot.autoconfigure.DataSourceObservationAutoConfiguration. This results in the loss of all observations though.

Here is a heap dump showing the error: heapdump.zip

Would appreciate your help here.
My assumption would be there is something different with the exposed datasource which prevents closing or disposal of observations, so that they're pilling up.

[cmdjulian]

This sounds exactly like my problem: https://github.com/jdbc-observations/datasource-micrometer/commit/99b2c52a46b3603ea325b161c741db1de6804ce6

[ttddyy]

@cmdjulian Thanks for the report.

I checked how JDBC API is called in the sample project and it seems correct - a Connection is retrieved and properly closed.

Meanwhile, can you try 1) update datasource-proxy version to 1.10, 2) I see async is specified in H2 url. Can you try with non-async such as mem?

Also, do you need to use spring-boot-data-source-decorator?

decorator:
  datasource:
    datasource-proxy:
      multiline: true
      logging: slf4j
      query:
        enable-logging: false
        log-level: debug
        logger-name: com.example.demo.query-logger
      slow-query:
        enable-logging: true
        log-level: warn
        threshold: 300
        logger-name: com.example.demo.slow-query-logger
    flexy-pool:
      metrics:
        reporter:
          jmx:
            enabled: false

The datasource-micrometer equivalent is:

jdbc:
  datasource-proxy:
    multiline: true
    logging: slf4j
    query:
      enable-logging: false
      log-level: debug
      logger-name: com.example.demo.query-logger
    slow-query:
      enable-logging: true
      log-level: warn
      threshold: 300
      logger-name: com.example.demo.slow-query-logger

well, unfortunately, the flexy-pool part is not configurable by datasource-micrometer though.

[cmdjulian]

1.: Not quite sure what you mean, both of:

implementation("net.ttddyy.observation:datasource-micrometer-spring-boot:1.0.3")
runtimeOnly("com.github.gavlyukovskiy:datasource-proxy-spring-boot-starter:1.9.1")

use the latest available version from maven central :S

2. I adjusted it to mem, I still see the problem
3. Yes, I could live with that, is there a way I can configure the flexy pool myself or extend datasource-micrometer to do it for me?

Edit: I think I understood now what you meant by 1., I added implementation("net.ttddyy:datasource-proxy:1.10") explicitly to set the transitive version from the starters, the leak still is present, but it changes slightly:

I updated the repository accordingly

[ttddyy]

Thanks for the update. Yes, I meant net.ttddyy:datasource-proxy:1.10. So, with the upgrade, from the new pictures, there is no more SimpleObservation, which is good.

The picture shows scheduler-related objects. I believe they are coming from slow query detection. If you look at the SlowQueryListener implementation, it submits a new task (Runnable) to check the query execution time. The advantage of this preemptive approach is that it can report a slow query as soon as the query passes the threshold time.

Since the demo app keeps generating queries, I assume the slow query check tasks are accumulating in the scheduler. One way to improve this is to pass a configured scheduler rather than using the default one.

On the other hand, if you are okay with reporting the slow query after the query has finished, you can write a custom listener (see the NOTE) without using separate threads (a non-preemptive way).

3. Yes, I could live with that, is there a way I can configure the flexy pool myself or extend datasource-micrometer to do it for me?

No, the auto-configuration for flexy-pool is done by the Spring Boot DataSource Decorator project. So, you may check its auto-configuration class to see how it works.

[cmdjulian]

I see, thx. I'm still unsure regarding the slow query log. When removing com.github.gavlyukovskiy:datasource-proxy-spring-boot-starter I don't see that heap consumption in the DelayedWorkQueue, as you can see from the MAT screenshot, there still seems to be a leak.

[ttddyy]

@cmdjulian I wonder what happens if you disable the slow-query (decorator.datasource.datasource-proxy.slow-query.enable-logging=false) while still using com.github.gavlyukovskiy:datasource-proxy-spring-boot-starter?

[cmdjulian]

I did some tests. Setting decorator.datasource.datasource-proxy.slow-query.enable-logging=false without hard coded net.ttddyy:datasource-proxy:1.10, has the same leak.
When hard coding net.ttddyy:datasource-proxy:1.10 and set decorator.datasource.datasource-proxy.slow-query.enable-logging=false, no leak is present

[ttddyy]

Thanks for testing it out.

It seems that net.ttddyy:datasource-proxy:1.10 has fixed the problem on my side. The combination of datasource-micrometer-spring-boot:1.0.3 and net.ttddyy:datasource-proxy:1.10 with slow-query:true works. However, adding com.github.gavlyukovskiy:datasource-proxy-spring-boot-starter causes DelayedWorkQueue leaks. This suggests that datasource-proxy-spring-boot-starter might be the cause, although it's strange since it should be a simple configurer for datasource-proxy rather than providing its own implementation.

Anyway, I'm closing the issue as there are no indications of leaks after using net.ttddyy:datasource-proxy:1.10.

Thanks a lot.