[datasource-proxy] SLF4JSlowQueryListener issues

[rolandkozma-sg]

Hi,

I noticed some issues trying to configure the logging of slow-queries in our project. Please have a look.

Spring Boot: v3.3.2
datasource-proxy-spring-boot-starter: 1.11.0

With the above config, I got the following logs:

2025-06-16 12:41:02.826 [pool-1-thread-1] WARN n.t.d.l.l.SLF4JSlowQueryListener
Name:dataSource, Connection:73, Time:50, Success:False
Type:Prepared, Batch:False, QuerySize:1, BatchSize:0
Query:["select ID, MAP_KEY, VALUE, ENCRYPTED, KEY_IDX, Country, Currency from adm.REG_HASH where map_key = ?"]
Params:[(value)]

2025-06-16 12:41:02.848 [http-nio-8081-exec-22] 01bf4fd0-0d5c-47bc-8ccc-c871bd4cd256 DEBUG n.t.d.l.l.SLF4JQueryLoggingListener
Name:dataSource, Connection:73, Time:72, Success:True
Type:Prepared, Batch:False, QuerySize:1, BatchSize:0
Query:["select ID, MAP_KEY, VALUE, ENCRYPTED, KEY_IDX, Country, Currency from adm.REG_HASH where map_key = ?"]
Params:[(value)]

I noticed the following issues with SLF4JSlowQueryListener that would be very useful to be fixed:

1. the log doesn't display the correlationId ("01bf4fd0-0d5c-47bc-8ccc-c871bd4cd256").
   In contrast the SLF4JQueryLoggingListener is logging it.

2. the Time is always capped at 50, which is the configured threshold (strangely sometimes is 49, but never greater than 50).
   In contrast, the SLF4JQueryLoggingListener probably logs the correct value (Time:72)

3. It says Success:False.
   In contrast, the SLF4JQueryLoggingListener says Success:True

4. I expected the logs to show how many times the prepared statement is executed (because of the "count-query: true" config), but I can't see this info.

Thank you!
Roland

[gavlyukovskiy]

Hi @rolandkozma-sg, this all related to the fact that slow-query listener is running in a separate thread and preemptively logs query as soon as it reaches the threshold (see details in this and this comments). Concretely,

1. the log doesn't display the correlationId ("01bf4fd0-0d5c-47bc-8ccc-c871bd4cd256")

There's no correlation between the thread executing a query and the thread logging this warning message.

2. the Time is always capped at 50

That is the threshold value, meaning that the message is logged as soon as query execution time reaches 50ms without waiting for the query to finish.

3. It says Success:False

Since the query is not yet finished at the time of logging, the query has not succeeded (nor failed) yet, so False is likely just a default value of a boolean that tracks the state of the query.

With that in mind, you could switch to a non-preemptive approach as mentioned by @anton-tkachenko in this comment.

4. I expected the logs to show how many times the prepared statement is executed (because of the "count-query: true" config), but I can't see this info.

I didn't fully understand this one, where do you expect to see this info? If I'm not mistaken that can be retrieved programmatically through QueryCountHolder#get(String dataSourceName) or QueryCountHolder#getGrandTotal (see docs).

[rolandkozma-sg]

Hi,

Thank you for your prompt answer!
I'll explore the non-preemptive approach you suggested. For now I don't see advantages of the preemptive one.
Will the non-preemptive approach fix the correlationId as well? - It's quite inconvenient.
Probably it would be good if we could configure a threshold for query as well, not only for slow-query. This way I could configure to log only the long queries but on the same thread to not miss the correlationId.

Could you explain the purpose of count-query? I didn't find anything in the doc about it.

Thanks!

[gavlyukovskiy]

Could you explain the purpose of count-query? I didn't find anything in the doc about it.

It's up to you whether you need / can do something with those counters. For example, it could be exposed as metrics (e.g. setting up a Micrometer Gauge), logged periodically or used for asserts in tests.