Why NextWhy Next
Back to posts
💻 Dev20 min read

We Got an Alert That the Database Was Down. The Database Was Never Down.

Four CRITICAL alerts piled up in a single day. A 504, a Prisma P2028, an admin 500, and 'DATABASE service down.' I opened the RDS metrics first: 21 straight hours with CPU peaking at 19.7%, perfectly healthy. What was slow was not the database but a round trip that crossed the Atlantic twenty-five times, and the 'down' alert was something the health check had manufactured all by itself.

TL;DR

A 504, a Prisma P2028, an admin 500, and DATABASE down. Three of these four CRITICAL alerts, which looked unrelated, came from a single root. Writes from the eu-west app cross the Atlantic to the us-east primary, and a single request makes that round trip twenty-five times. RDS sat below 20% CPU the whole time. The 'DATABASE down' alert was a false positive the health check created itself: because DIRECT_DATABASE_URL was not set, its SELECT 1 went down the exact proxy path that the app's writes were already congesting. The fix was not raising the timeout but folding the round trips away, and we judged the canary not by latency but by queries per request (22 -> 15.3).

On this page

I opened Slack in the morning and found four CRITICAL alerts waiting.

504 AppHttpException: The request timed out.
  POST /customer/practice/attempts

PrismaClientKnownRequestError
  Transaction already closed

500 DriverAdapterError: canceling statement due to statement timeout
  GET /admin/dashboard/stats

DATABASE 서비스 다운
  "error": "Database health check (retry) timeout after 2000ms"

The last one is the scariest, because it means the database is dead. Put all four on one screen and a story writes itself. The database was struggling, so queries backed up, so requests timed out, and in the end even the health check failed. It is a believable story.

So I opened the database metrics first. The story fell apart on the first screen.

The database was idle for 21 straight hours

I pulled RDS metrics at 5-minute resolution across a 21-hour window covering the incident. 252 data points.

MetricMinMax
CPU4.6%19.7%
Connections5373
CPU credit balance576576
Read latency0s0.01s
Write latency0.01s0.08s

CPU never crossed 20%, and the credit balance has the same minimum and maximum, which means none of it was ever spent. Write latency peaked at 80 milliseconds. I checked RDS Proxy too. Connection borrow latency peaked at 26 milliseconds, backend connections at 36. Nowhere is there a number that would explain an 8-second or 10-second query.

The database was not dead. It was not even busy.

One request crosses the Atlantic twenty-five times

So where did the 8-second query come from? The architecture answers that.

Our service runs in two regions, us-east and eu-west. There is a single primary database, in us-east. Reads from the eu-west app are served by a local replica, but every write crosses the Atlantic and goes through RDS Proxy to the us-east primary.

The number of writes was the problem. I followed one practice-attempt save request (POST /customer/practice/attempts) through the code and counted. One asset upsert, three pre-aggregation reads, four queries in the learning attempt transaction, one re-fetch by the runner, two or three progress updates, about six in the streak transaction, two in the stats transaction, and two or three review-state updates. Roughly twenty-five, spread across three separate interactive transactions.

The logs had that exact number in them.

06:03:17  request_done  POST /customer/practice/attempts
          status=201  duration_ms=11695  query_count=25

25 queries, 11.7 seconds. And this request did not even fail. It held on for 11.7 seconds and came back a 201.

There is one thing I should be honest about here. I did not measure how many milliseconds a single one of those round trips costs. One code comment says the cross-region RTT is 220 milliseconds; another comment says 80 to 100 milliseconds per statement. Without checking which of the two is right, I wrote the calculation "25 x 220ms = 5.5 seconds" into the issue. Looking back, that is not a measurement, it is a quotation. The accurate statement is this: I counted the round trips (25), and I did not measure the cost per round trip. The conclusion still holds. Cross the Atlantic twenty-five times and the cost adds up in seconds.

During the EU morning peak (06:00 to 06:10 UTC), 57 primary writes took longer than 3 seconds. LearningAttempt.create at 8,989ms, UserActiveDate.upsert at 9,070ms, LearningAttempt.findUnique at 10,561ms. Requests pushed against each other and the round-trip latency stacked up.

Two of the alerts came out of that gap.

Alerts 1 and 2: a 5-second transaction could not survive 9.3 seconds

The streak update code looked like this.

// streak.service.ts:254
const changed = await this.prisma.primary.$transaction(async (tx) => {
  // ... six queries that cross the region boundary ...
});

There is no options object, so Prisma's default interactive transaction timeout of 5,000 milliseconds applies. Normally that is fine. As long as you are not crossing a region.

Transaction API error: A query cannot be executed on an expired transaction.
The timeout for this transaction was 5000 ms,
however 9326 ms passed since the start of the transaction.

9,326 milliseconds. That becomes P2028, and the request becomes a 504 at the gateway.

This code was the only unprotected one in our codebase. Every other transaction path goes through a withTxRetry helper, which raises the timeout to 8 seconds and treats P2028 as retryable. Only the streak update sat outside that umbrella, still using the 5-second default.

Alert 4: the health check walked through the very bottleneck it was watching

The scariest alert, "DATABASE service down," turned out to be the silliest one.

The health check code was well written. It sends a SELECT 1 with a 2-second timeout, and if that fails it waits 500 milliseconds and tries once more, and if that fails too it fires a CRITICAL alert. It even has its own dedicated connection pool (max 2) so it never mixes with the app's Prisma pool. The design intent was that the health check stays alive even when the app pool is exhausted.

But the path this probe takes to reach the database was not isolated.

// health.service.ts:139
// If DIRECT_DATABASE_URL is set, use it; otherwise fall back to DATABASE_URL

DIRECT_DATABASE_URL was not set. The fallback kicked in, and DATABASE_URL points at the exact RDS Proxy where the app's writes were piling up. In other words, the SELECT 1 fired by the eu-west health probe had to cross the Atlantic, go through the proxy that was congested right at that moment, reach the us-east primary, and come back. In under 2 seconds.

The code knew this. It leaves a warning behind whenever the fallback kicks in.

DIRECT_DATABASE_URL is not set; DB health checks will use DATABASE_URL
and may still share proxy bottlenecks.

That line was sitting right there in the logs. Nobody had read it.

The decisive evidence was that both regions failed at the same moment. At 12:02:17, the health check on a us-east task timed out. At 12:02:18, an eu-west task timed out too. If it had been a regional problem, only one side should have died. Both dying together means the cause is something they share, which is the proxy path.

What follows is a foregone conclusion. Both health check attempts failed, so /public/health returned 503, and the orchestrator decided the task was unhealthy and replaced it. Four minutes later a new task came up. The new task hit the exact same health check timeout as soon as it booted. Swapping a task does not make the Atlantic any narrower.

"DATABASE service down" was not a symptom of an outage. It was the monitor walking down the congested road it was monitoring and then reporting that it was having a hard time.

The admin 500 was a separate matter

This is where the urge to tie all four alerts into one story arrives. I tried to write it that way at first too. But the admin 500 had a different root.

When GET /admin/dashboard/stats computes the most popular words, it filters to the last 7 days. But the table that filter lands on (category_attempt) has no date column of its own. The date only exists on the joined learning_attempt side. So Postgres has no way to slice category_attempt down by date up front and has to scan the entire history. No amount of good indexing can make this filter selective.

slow_query path=/admin/dashboard/stats
           label=CategoryAttempt.groupBy dur=8009ms

statement_timeout is 8,000 milliseconds. The query took 8,009. It died by 9 milliseconds. This was a full scan that has nothing to do with regions and was always going to blow up eventually as the table grew.

Three of the four alerts shared one root, and one did not. Four alerts landing on the same screen does not mean they have the same cause.

One theory we rejected

There was one plausible suspect. The device-cleanup cron that runs just before the 06:00 burst could have caused lock contention. The timing lined up nicely, so it was fairly convincing.

I went through the logs from both regions across the 05:30 to 06:15 window. There was not a single cron-related log line. Checking the path of the slow Device.updateMany, it was not the cron's bulk update but /v2/public/auth/refresh, an ordinary user's token refresh. The theory was rejected by measurement. Overlapping timing is a correlation. Not being in the logs is a fact.

We folded the round trips

There are two kinds of prescription. One endures the symptom: raise the timeout to 8 seconds, grow the pool, add retries. The other removes the cost itself: cut the number of round trips.

We did both. Wrapping the streak transaction in withTxRetry is a bandage, but it was a bandage we needed. The real prescription, though, was folding the round trips away.

The tool for it already existed. A migration dated June 27 contained a server-side function called create_practice_attempt_v1. It folds session locking, lookup, insert, session metadata update, and the pre-aggregation read into a single SQL function so the whole thing finishes in one round trip. It is even idempotent: call it twice with the same client attempt id and the second call returns the existing row along with inserted=false.

But the feature flag that turns this function on, PRACTICE_ATTEMPT_SINGLE_RT_ENABLED, defaults to false, and it was off in production.

Instead of removing a region or moving to active-active, what we did was flip a switch that was already built.

The canary: what do you judge it by?

We turned the flag on in eu-west only, leaving us-east off as a control group. Task definition went from 786 to 787 and we did a rolling deploy.

Choosing what to judge by is the heart of this story. Latency is a trap. Deploy during a quiet traffic hour and p95 improves even if you fixed nothing. And latency did improve. p50 went from 2,784ms to under 2,000ms. But that is weak evidence.

What I looked at instead was queries per request.

before  n=85   avg query_count = 22.0
after   n=49   avg query_count = 15.3

Query count is a per-request metric that does not depend on load. Whether traffic is heavy or light, the number of queries one request fires is decided by the code path. It went from 22 to 15.3, a drop of about 7. And those 7 match exactly the number of queries we folded into the function (session lock + lookup + insert + session metadata + pre-aggregation read). That number is the evidence that the code path actually changed. Not the latency.

The post-deploy sample is 49 requests over 15 minutes. There were zero 5xx and zero P2028 in that window, but I did not measure a "before" error count over a window of the same length on the same day, side by side. This flag only folds the attempt save. The streak transaction still crosses regions. Zero P2028 in that window means we were lucky, not that anything was proven.

The deploy worked, and the flag almost vanished

The way we ran the canary had a cost. 787 was a task definition registered by hand in the console. The next regular deploy would have the CD pipeline overwrite it with a task definition that has no flag. Not fatal, since overwriting it just falls back to a safe OFF. But the improvement would quietly disappear.

So it had to be promoted into terraform, and that is where the second trap appeared. The terraform workflow applies staging only on a develop push, and applies production only on a main push. And staging has no eu-west region to begin with. In other words, merging a PR that carries a production eu-west change into develop does nothing at all. We had to switch the base to main.

There was a third trap. Merging straight into main leaves develop behind, and if you do not merge it back, the next release reverts the change. We had to open a separate back-merge PR.

"terraform apply succeeded" and "it is live in production" are two different sentences.

What stayed with me

When a "database down" alert arrives, open the database metrics first. The name on an alert was chosen by the code that fired it, not by the cause. Our health check went as far as building a dedicated pool isolated from the app pool, and it still got stuck alongside the app, because the road to the database was the same one. Isolation is not only about splitting resources. It has to split the path too.

Raise the timeout from 5 seconds to 8 and that day's alerts stop. But the request still crosses the Atlantic twenty-five times. Grow traffic a little more and 8 seconds will not be enough either. It is better to decide up front whether you are enduring the symptom or removing the cost. If the cost is "count x distance," the thing to cut is the count.

Latency moves with load; per-request metrics do not. Before you deploy a performance fix, see p95 improve, and relax, check whether the amount of work one request does actually went down. That number is the same whether you deploy at dawn or at lunchtime.

I counted the round trips, and I borrowed the per-round-trip latency from a code comment. Those two comments disagreed with each other. The conclusion did not change, which is lucky, but next time the conclusion might. If you did not measure a number, write that you did not measure it.

Frequently asked questions

I am getting 'DATABASE service down' health check alerts, but the RDS metrics look fine. What should I look at?

Check what the health check passes through to reach the database. In our case, the health probe's SELECT 1 was going down the exact same RDS Proxy path where the app's write traffic was piling up. We had even given the probe its own dedicated connection pool so it would be isolated from app pool exhaustion, but since the path was shared, that isolation bought us nothing. A health check should reach the database over a path that is as independent as possible from what it is monitoring. Otherwise the alert is not a symptom of an outage, it is an echo of the congestion.

Cross-region writes are slow. Can't I just raise the timeout?

Raising the timeout stops things from dying, but they stay just as slow. If the cost is really 'number of round trips x cross-region latency,' then the thing to reduce is the number of round trips. We took a request that made twenty-five round trips and folded it into a single server-side function, bringing it down to one. Raising the timeout is enduring the symptom. Folding the round trips away removes the cost.

I deployed a performance fix. How do I judge whether it actually worked?

Latency alone moves with load. Deploy during a quiet hour and p95 looks better even if you fixed nothing. Look at a per-request metric that does not depend on load, such as queries per request. Our decisive evidence was that average queries per request dropped from 22 to 15.3, because the roughly 7 that disappeared matched exactly the list of queries we had folded into one function.

Related posts

0 comments