datasource-proxy slow-query logging doesn't work as expected

[rolandkozma-sg]

Hi,
I'm using datasource-proxy-spring-boot-starter 1.8.1 with spring boot 2.5.15.
Beside adding the above dependency, I also configured:
decorator.datasource.datasource-proxy.query.log-level=INFO
Then I started to see the queries logged at the info level, as expected.

However, I wasn't able to configure slow-queries to be logged using the properties:
decorator.datasource.datasource-proxy.slow-query.enable-logging=true
decorator.datasource.datasource-proxy.slow-query.log-level=WARN
decorator.datasource.datasource-proxy.slow-query.threshold=50

I'd like to log at WARN level all the queries that took longer than 50 milliseconds (although the doc says that the threshold property value is in seconds, I think that's a mistake).
After adding the above slow-query configs I still see all the logs at INFO level including the queries with longer execution time than 50 ms.
The only way I'm able to see logs at WARN level is to set the threshold to 0. Then all the logs will be with WARN.
My goal is to log only slow-queries at WARN level. Please help.

Regards,
Roland

[pcomp96]

Same problem for us :

SpringBoot 3.4.3
datasource-proxy-spring-boot-starter.version = 1.10.0

This our config:

decorator:
  datasource:
    enabled: true #Enable the decorator
    datasource-proxy:
      # Use only one of this
      multiline: false
      json-format: false
      format-sql: true
      slow-query:
        enable-logging: true
        threshold: 300 #Default threshold value Log for slow query
        log-level: WARN #default
      query:
        enable-logging: true #default
        log-level: DEBUG #default

I have the slow query (305 over my threshold) logged on SLF4JQueryLoggingListener

2025-03-27 15:02:38.291 DEBUG 73 --- [x-pool-1] [67e5688dcf1ec74a0fb65d84006455ba-57ebbe8fcae5f5c9] n.t.d.l.l.SLF4JQueryLoggingListener : Name:main, Connection:163845, Time:305, Success:True, Type:Prepar....

[gavlyukovskiy]

The values are in seconds, so for threshold=50, it means that query needs to take 50 seconds to be written in the logs.

@pcomp96 SLF4JQueryLoggingListener logs all queries regardless of their time, so that's why you see a log line.

With configuration:

decorator:
  datasource:
    datasource-proxy:
      format-sql: true
      query:
        log-level: INFO
      slow-query:
        threshold: 1

and simulating the sleep inside a query I correctly get two log

2025-03-30T11:03:01.117+02:00  WARN 11122 --- [datasource-proxy-sample] [pool-2-thread-1] n.t.d.l.logging.SLF4JSlowQueryListener   : 
Name:h2, Connection:2, Time:1000, Success:False
Type:Prepared, Batch:False, QuerySize:1, BatchSize:0
Query:["SELECT
  SLEEP(?)"]
Params:[(3000)]
2025-03-30T11:03:03.126+02:00  INFO 11122 --- [datasource-proxy-sample] [nio-8081-exec-1] n.t.d.l.l.SLF4JQueryLoggingListener      : 
Name:h2, Connection:2, Time:3010, Success:True
Type:Prepared, Batch:False, QuerySize:1, BatchSize:0
Query:["SELECT
  SLEEP(?)"]
Params:[(3000)]

[gavlyukovskiy]

I have opened #130 to allow milliseconds in duration (reported in #88), this should remove the confusion 👍

[gavlyukovskiy]

Closing this as expected behavior, feel free to reopen if you have any more questions.

[pcomp96]

Thank u @gavlyukovskiy , i have 2 point :

1. Question
   More important, when u release the new version with this feature of Duration? We want include in our prj asap

2. (Opinion)
   Let me say that
   300 seconds as default it's a bit too much, anyway is the same behaviour before this feat, so i get your point. The common use cases for this value is 300s ?

[gavlyukovskiy]

@pcomp96 I have released a new version 1.11.0, usually it takes a couple hours to be available in Maven Central.

Regarding the default value, I honestly cannot remember why I chose 5 minutes as the default. I was likely influenced by working on a project that had large reporting queries that we wanted to track 😅 Today I would chose a different value to be the default, however, I'd rather keep this conservative behavior to avoid unnecessary spam in the logs.

[pcomp96]

@gavlyukovskiy Nice for the release!

4 the second point, correct if u want a precautive value to avoid the spam. 👌

Thank u very much for the work, I apprecciate. Waiting the release , I wish u a good day!