quatermain

Is it possible to debug which processes and code places are using the DB pool when using Ecto?

Hi,

We have a regular Phoenix project using Ecto and Postgresql. But recently we are seeing a lot of connection timeouts or idle/closed connections. All looks like problem that DB pool is exhausted. Traffic has been pretty low, queries look ok, no big queries running all the time, no big Oban jobs. But I’m pretty sure we’re missing something.

So is it possible to debug which processes and code places are using the DB pool? Thanks to telemetry, we’re able to run code when these errors occur, but the question is whether it’s possible to get details about pool usage.

Telemetry handler:

 def handle_event(
        [:enaia, :repo, :query],
        measurements,
        %{result: {:error, %DBConnection.ConnectionError{} = error}} = metadata,
        _config
      ) do
   # check and log details about Pool usage
 end

I can get repo’s child, but I’m not sure how to proceed.

repo_pid = Process.whereis(MyApp.Repo)
children = Supervisor.which_children(repo_pid)

12 comments

#ecto #postgrex #db_connection

1 434 12

2025-02-14 14:47:12 UTC

Most Liked

josevalim

Creator of Elixir

First step is to see your data for queue times, query times, and idle times, as those will show how busy the pool is. Also, what do you mean by connection timeouts?

The idle/closed connections may happen if the database or a proxy are closing them and are not necessarily an indicator of a problem (although we do ping the connection every second).

Post #2

josevalim

Creator of Elixir

Other things that could be helpful:

Investigate if this relates to deployments somehow
Chart p90% and p99% not averages, especially for queue and query times, but you should be able to track queries that take too long. Even if by using custom telemetry handlers. If anything takes more than a second, make sure to log that

Post #6

quatermain

We already have had this issue with crashed primary machine multiple times this week, we changed machine with more resources maybe a week ago. so it’s new machine. In case this is the issue, something has to broke that machine even with new ones

Post #9

Last Post!

quatermain

I found nice explanation in other post

tl;dr the idle time is how long a connection was ready and enqueued in the connection pool waiting to be checked out by a process. Therefore we can be happy to see it above 0.

idle time is recorded to show how busy or not busy the connection pool is. During connection pool IO overload the idle time will be as close to 0 as it can be, not counting message passing overhead, because then the connections are always in use by processes running transactions/queries. If a connection is not immediately available there is queue time that is the time between when the request for a connection was sent and when a connection becomes available. This time has latency impact for processes running transaction/queries as they need to wait for a connection before they can perform a query because the connection pool does not have enough capacity. db time is the time spent holding onto to the connection, i.e. time spent actually using the database. Therefore the latency for the calling process is queue time plus db time.

When the connection pool has extra capacity the queue time should always be as close 0 as it can be because a connection is available when requested. Only once the transaction rate is beyond what the connection pool can handle does the queue time increase. However that is a little late because latency is already impacted once it goes above ~0. idle allows us to see how close to having queue time, the higher the idle time the more capacity we have in the connection pool.

Perhaps a clearer way to think about it is if you see an idle timeout of 100ms, that means we could have run 100ms worth of db time on that connection since the last time that connection was used. So to be as efficient as possible on resource we would want queue and idle to both be near 0. However because of the latency impact of queue, we should be happy to sacrifice some idle time to keep queue at 0 when possible.

Of course we can make queue time move to 0 by increasing the pool size. However if the pool is too large db time will suffer as the database becomes the bottleneck instead of the connection pool.

If the application is not sending any queries for a prologued interval and then sends a query why is the idle time capped? This occurs because idle connections periodically send a ping message to the database to try to ensure connectivity so that the connections are ready and live when needed, and we don’t need to attempt to connect when a query comes in. If we needed to reconnect then the database handshake time would add latency to the transaction/query being processed. The ping message resets the idle timer because an individual connection is unavailable from the pool during a ping. If it was left in the pool the connection would be blocked waiting for a pong response and incur a wait on the connection like just like a handshake. Pings are randomized to prevent all connection becoming busy at the same time.

So basically it can means that we have too big pool size and we fire too much pressure on DB and our connection pool basically do not handle pressure correctly.
That can explain peaks where we have more queries. Like here

When we had 444k ecto queries and 651 DBConnection.ConnectionError timeouts. And idle time was 1sec for 95P or 305ms mean. Queue time was 6ms.

So if i’m not wrong, reducing pool size we should move pressure from DB to our DBConnection Pool (“Ecto”) which should handle pressure more effective. Right?

Post #13