7

I have a Spring boot app that use HikariCP for Postgres connection pooling.

Recently I've set up tracing to collect some data how time is spent when handling a request to a specific endpoint.

My assumptions are that when using HikariCP:

  1. The first connection to the database while handling the request might be a bit slower
  2. Subsequent connections to the database should be fast (< 10 ms)

However, as the trace shows, the first connection is fast (< 10 ms). And while some subsequent connections during the same request handling are also fast (< 10 ms), I frequently see some subsequent connections taking 50-100ms, which seems quite slow to me, although I'm not sure if this is to be expected or not.

Is there anything I can configure to improve this behavior?

Maybe good to know:

  • The backend in question doesn't really see any other traffic right now, so it's only handling traffic when I manually send requests to it
  • I've changed maximumPoolSize to 1 to rule out that the issue is that it uses different connections in the context of 1 request and that's what causes the issue. The same behavior is still seen.

I use the default Hikari settings, I don't change them.

Trace screenshot

edwardmp
  • 6,339
  • 5
  • 50
  • 77
  • The relevant difference is in the case if an active connection from the pool can be reused or if a new connection must be opened on the pool request. This is dependent on the pool configuration that you did not show. – Marmite Bomber Nov 10 '22 at 13:59
  • @MarmiteBomber everything is according to default settings form Hikari. This means that both maximum pool size and idle = 10. I did try to test it with size =1, and I still see the same behavior weird enough. – edwardmp Nov 10 '22 at 14:49
  • I have no idea where your image came from. Any chance that "connection" lumps together making the connection, and using the connection? What do you get if you drill down into one of the longer "connection" lines? (I'm assuming the `>` means that this drill down is possible, but again without knowing what generated it I can't be sure of that) – jjanes Nov 10 '22 at 17:00
  • @jjanes It's a screenshot of Google Cloud Trace. You are right that it lumps for instance insert operations under it, which I have collapsed for brevity. But these operations itself are definitely not taking as much time as the connection itself seems to take. – edwardmp Nov 10 '22 at 18:59
  • @edwardmp **1.** Did you rule out network reliability? Are these 3 points (app[+|,] pool, db) all within the same zone and network on Google Cloud? Do the same operations in the app result in approximately the same connection times, or does operation A sometimes stay below 10ms and sometimes jumps to 90ms? **2.** *"operations itself are definitely not taking as much time"* - How do you rule out that these connection times are not driven by how long these queries take for the db to process? – Zegarek Nov 13 '22 at 16:03
  • @Zegarek not using Google Cloud, but yes they are within same zone & network anyhow. I rule out the queries itself don't take as much time because I trace that too (not shown in screenshot). The same operation in one request will take <10ms and in other requests take 100ms suddenly. Indeed I can not fully rule out network reliability I guess. What would be a good way to confirm or deny this? – edwardmp Nov 14 '22 at 12:41
  • It would be easier to help if you show your actual config (secrets filtered out of course) and perhaps even how you obtain connections... Also enabling and attaching log output with `logging.level.com.zaxxer.hikari.HikariConfig=DEBUG` and `logging.level.com.zaxxer.hikari=TRACE` would be helpful... – Per Huss Nov 18 '22 at 21:00
  • @PerHuss as mentioned before my config is default. And I have already enabled the trace logs, they show nothing out of the ordinary (i.e. there is a idle pool of 10 connections most of the time). – edwardmp Nov 20 '22 at 11:14

1 Answers1

0

I do think something is wrong with your pool configuration or your usage of the pool if it takes roughly 10 ms to get an already initialized connection from your pool. I would expect it to be sub-millisecond... Are you sure you are using the pool correctly?

Make sure you are using as new versions of pool and driver as possible, and make sure that connectionTestQuery is not set, as that would execute a query every time the connection is obtained from the pool. The defaults should be good enough for the rest of the settings.

Debug logs could be one thing help figure out what is happening, metrics on the pool another. Have a look at Spring Boot Actuator, it will help you with that...

To answer your actual question on how you can improve the situation given it actually takes roughly 10 ms to obtain a connection: Do not obtain and return the connection to the pool for every query... If you do not want to pass the connection around in your code, and if it suits your use case, you can make this happen easily by making sure your whole request is wrapped in a transaction. See the Spring guide on managing transactions.

Per Huss
  • 4,755
  • 12
  • 29
  • Yes, I am sure the pool is used. I enabled Hikari trace level logs that indicate this. – edwardmp Nov 20 '22 at 11:10
  • Make sure you don't have `connectionTestQuery` set, as that would trigger a query to test that the connection works every time obtained from the pool... – Per Huss Nov 20 '22 at 13:45
  • Updated answer with what you are actually asking for, but I really want to stress the fact that you should continue looking into why obtaining a connection from the pool is this expensive... It should not be. – Per Huss Nov 20 '22 at 14:00