maxguzenski

App in production crashing with DBConnection.ConnectionError

Hello.
I don’t know what the best place is, hoping to find any help with the problem I’ve been facing in production for about 3 days.

I have a niche social network that, on average, has 4 thousand users online, and makes around 30 thousand requests per second to the server. The application runs smoothly with an average per request of just 0.02s and memory of around 10GB. But something happens when the site reaches 5.5k users online, everything drops very quickly (less than 10s), the application goes from 10gb to 60gb in a few seconds, the Elixir Logger starts dropping logs, the server loses all connections with the database and starts trying to reestablish new connections, but they all timeout… so the app becomes irresponsible until docker is restarted (returning to normal speed and staying like that for about 20 minutes).

Error that appears in the log thousands of times:


DBConnection.ConnectionError

tcp recv: closed (the connection was closed by the pool, possibly due to a timeout or because the pool has been terminated)

My infrastructure:

The application runs on Docker (generated by Phoenix 1.7), deploys with AWS ECS on a c6i.x24large (96vcpu/189gb) and Aurora r6.x4large database (16cpu/128gb)

The database uses around 35% of CPU, and remains that way even when the application crashes. The application uses only 10% CPU and 10GB of RAM.

ps.: All online users connect via websocket, in addition to the normal request.

Elixir 1.15.7
Phoenix 1.7.10 with all deps updated
React front-end

Things I’ve tried

db connection pool: from 100 to 2400
Direct connection to Aurora and throught RDS proxy as well
I have tested with an instance with 50 gigabits of network performance
soft/hard “ulimit” from default value to 130k
queue_interval/target from 50ms to 2s

Because of websocket, I haven’t been able to test scaling horizontally yet.

Some screenshots

App on “normal” mode:

When app is not responding (See how memory increased):

Avarage request time, you can see it stop to responding very fast:

Aurora database shows that app is not reading the query result:

So what I need is some direction, it’s strange that it happens right after passing the 5500 users mark online, before that the app doesn’t present any problems or slowdowns.

I also don’t know if scaling horizontally would solve it, but there is no metric (memory/cpu) that indicates that the problem is close to occurring so that it can be scaled.

I would bet on some network limit, port exhaustion or process limit reached. But I don’t find anything in the logs other than the database connection error.

17 comments

#ecto #postgres

32 2206 17

2024-04-25 23:21:04 UTC

Most Liked

josevalim

Creator of Elixir

I would start by adding more metrics around the application. Having such a large connection number is likely going to lead to worse performance, as they won’t ever be effectively used and the runtime now has to spend more time managing them.

If you suspect this is related to the database, you should log the metrics emitted by Ecto, such as query time, checkout time, idle time and so on.

I would also log the memory metrics from the VM and, most important, the Erlang VM run queues, which tells you how much CPU/IO work it has to do. You can get those by running Phoenix LiveDashboard on the repo, but ideally you want to push these to an external tool too.

Post #4

felix-starman

Are you by chance using Bandit? I was experiencing a similar symptom, although w/ no resource issues that I noticed, just sudden timeouts that felt like port exhaustion.

If so, there’s a PR @mtrudel put out for thousand_island (Refine acceptor behaviour on abnormal conditions by mtrudel · Pull Request #103 · mtrudel/thousand_island · GitHub) that resolves an issue where the kernel might kill a connection, but the process responsible for it was not restarting since it looked “normal” to it. I was similarly seeing it occur during peaks, but it was mostly just coincidence since that’s when the most activity and aborted connections were occurring. I also saw large numbers of DB timeouts right after, but it was a red herring.

Post #5

dch

lots of great points already here, but not much on OS level.

questions

any info on what is the bottleneck? storage? network? kernel?
is there a load balancer in between you and the users?
are there any errors reported in kernel logs at this time?
any other sysctl or other tunables set for ulimit, max open files, …
are you running into any tcp ephemeral port exhaustion? this is surprisingly common when running behind load balancers, you should monitor total ports, and what state they are in, at runtime, both in kernel and of elixir app.

I would initially check the networking side first, before looking at storage. A reasonable hypothesis is this:

you are running out of free tcp sockets for inbound connections and/or queued connections in the kernel, and they’re not being recycled fast enough by OS
this could cause both the DB pool to be unable to spawn new connections, and same for phoenix on accepting new user connections
user requests start piling up in process mailboxes, causing memory to balloon
everything rapidly turns to custard

TLDR

You need to check/fix all of ulimits as seen by beam.smp process, kernel backlog & accept queues, phoenix acceptors, backlogs, and max requests.

check cat /proc/<pid>/limits for elixir beam.smp pid to ensure ulimits are ok (fix in systemctl unit file or ulimit if not a systemd service)
check ss -s to see how many “active” connections there are at runtime
save full output of ss -tan somewhere for review later
check sysctl net.ipv4.ip_local_port_range and increase it sysctl -w net.ipv4.ip_local_port_range="4096 65535" to give more headroom
check ss -lnt to see how many active connections phoenix is handling atm
adjust phoenix to handle more active connections if required (use gen_tcp backlog 1024 as a reasonable number)

Longer

NB many caveats and handwavey innacuracies, to keep it simple.

Incoming network connections arrive in the kernel, and are queued in several places.

first kernel queue is backlog queue, until tcp handshake is completed (syn, then syn-ack reply, final ack from client)
next kernel queue is the accept queue, waiting for your listening app to accept the next connection. The kernel will buffer 1.5x the maximum configured connections on behalf of your app. This default is either 128 or 4096 depending on OS. Note that 1.5 * 4096 is 6144 which is awfully close to 5500. Could be coincidence of course!
final queue is gen_tcp acceptors in phoenix app, if there are no free ones (busy with existing requests), then we “push back” and requests start piling up in the buffer, then the accept queue itself overflows, and the backlog queue, until new requests for both receive and send get rejected.

If you are using the default port range, you’ll have around 28000 available sockets behind a NAT. If each user request creates 2 tcp requests in, and a further temporary 1 or 2 out to DB or elsewhere, then 5500 active users brings you pretty close to maxing that out. Also another coincidence possibly!

You may see this info in AWS LB metrics, or in whatever grafana or similar server metrics you collect too.

Probably something like this:

### whats the configured ephemeral port range
# sysctl net.ipv4.ip_local_port_range
### how many sockets are open atm? one of these commands should work for you
### they all give slightly different info
# netstat -nat
# ss -lnt
# ss -tan | awk '{print $4}' | cut -d':' -f2 | sort | uniq -c | sort -n

I wrote a bit about this in the past so start with that. Some details on tcp networking in general: