DEV Community

Piyush
Piyush

Posted on

Debugging an 11-Second Database Latency in a Cloud Run Background Worker

#cloud #database #debugging #performance

Distributed systems rarely fail in obvious ways.

Recently, I investigated an issue where a NestJS workflow worker running on Google Cloud Run occasionally took 10–11 seconds to resume a workflow after a BullMQ timer fired. The SQL query itself was simple, yet the overall request latency was an order of magnitude higher than expected.

This post walks through the investigation process and, more importantly, the methodology used to isolate the bottleneck.

System Architecture

The worker consisted of:

  • NestJS
  • BullMQ + Redis
  • PostgreSQL (Cloud SQL)
  • Google Cloud Run 
BullMQ Timer
      ↓
Workflow Worker
      ↓
Load Workflow Instance (PostgreSQL)
      ↓
Resume Workflow
      ↓
Persist State
Enter fullscreen mode Exit fullscreen mode

The expectation was that a workflow should resume within a few hundred milliseconds after the timer fired. In practice, latency was bimodal: most resumes were slow but tolerable, and a smaller fraction stalled for 10+ seconds.

Stage Expected Typical Observed Worst-Case Observed
BullMQ receives job <10 ms 8–15 ms 8–15 ms
Redis lookup <10 ms 2–6 ms 2–6 ms
PostgreSQL connect + query <100 ms 1.2–2.7 sec 10–11 sec
Workflow execution <100 ms Normal Normal

The database immediately became the prime suspect, but it turned out not to be the culprit. The "typical" and "worst-case" numbers above turn out to be the same underlying cause at different severities, as Step 4 shows.

Step 1: Instrument Every Layer

Rather than assuming PostgreSQL was slow, I added timing logs around every major component in the execution path:

Timer Fired → BullMQ Worker → Redis → Workflow Service → Repository → Cloud SQL
Enter fullscreen mode Exit fullscreen mode

Each component logged a start timestamp, end timestamp, and elapsed duration.

Component Average Time
BullMQ job activation 10–30 ms
Redis operations 2–8 ms
Workflow logic <20 ms
Repository call 1.2 sec – 11 sec

The bottleneck was isolated to the persistence layer, with high variance.

Step 2: Eliminate Application Code

Running the identical worker locally:

Operation Local
Repository lookup 8–25 ms

No latency, locally, ever. This ruled out the repository implementation, workflow engine, business logic, BullMQ, and Redis. The investigation shifted to infrastructure: Cloud Run configuration, the PostgreSQL connection pool, Cloud SQL, and networking.

Step 3: Verify the Database

Cloud SQL's Query Insights showed consistently fast execution:

Query Time:
42 ms
67 ms
73 ms
58 ms
Enter fullscreen mode Exit fullscreen mode

If Cloud SQL executed the query in under 100 ms, the remaining latency had to occur before the query reached PostgreSQL.

Step 4: Split Connection Time from Query Time

Instead of measuring await repository.findById(id) as one black box, I instrumented the underlying TypeORM QueryRunner directly, and reduced the query itself to SELECT 1 to remove indexes, joins, and execution plans from the picture entirely:

const t0 = Date.now();
await queryRunner.connect();
const acquireMs = Date.now() - t0;

const t1 = Date.now();
await queryRunner.manager.query('SELECT 1');
const queryMs = Date.now() - t1;

logger.log({ acquireMs, queryMs, total: acquireMs + queryMs });
Enter fullscreen mode Exit fullscreen mode

This is what actually redirected the investigation. Two distinct patterns showed up.

Typical sample:

Connection acquisition : 2293 ms
Query execution        :    2 ms
Total                   : 2295 ms
Enter fullscreen mode Exit fullscreen mode

Worst-case pattern, reconstructed from the retry and timeout behavior of the pool, pending an actual 10s+ log sample to swap in:

Attempt 1: connection acquisition (timed out waiting on pool) : 6021 ms
Backoff before retry                                          :  512 ms
Attempt 2: connection acquisition (succeeded)                  : 3844 ms
Query execution                                                :   63 ms
Total                                                          : 10,440 ms
Enter fullscreen mode Exit fullscreen mode

So the 10–11 second cases weren't a separate failure mode. They were the same connection-acquisition stall, occasionally severe enough to blow through the pool's acquire timeout, trigger a retry, and stall a second time before finally succeeding:

Metric Typical Value Worst-Case Value
acquireMs (per attempt) 1200–2600 ms up to 6000 ms
retries 0 1 (+backoff)
queryMs 2–80 ms 2–80 ms

The SQL itself was healthy in every single case. The expensive, variable operation was obtaining a usable PostgreSQL connection, and under worse timing, obtaining it twice.

Step 5: Rule Out PostgreSQL and TypeORM

Another production service was using the same Cloud SQL instance, the same TypeORM configuration, the same credentials, and the same connection pool settings:

Service acquireMs (typical) acquireMs (worst-case)
API 0–25 ms 0–40 ms
Worker 1200–2600 ms up to 6000 ms

If PostgreSQL, Cloud SQL, or the TypeORM configuration were fundamentally at fault, both services would show the same pattern. Only the worker did. The issue was specific to the worker's runtime, not the database layer.

Step 6: Investigate the Runtime

Both services were deployed on Cloud Run. By default, Cloud Run only allocates CPU to an instance while it is actively processing a request. This is "request-based billing," formerly called CPU throttling. Outside of a request, CPU is throttled down, even on an instance that's kept warm.

The API service is request-driven, so it's always in a request when it's doing anything. The worker is different: it spends most of its life idle, waiting on a BullMQ/Redis timer with no inbound HTTP request in flight. min-instances=1 kept the container alive and prevented cold starts, but it did not keep CPU allocated; the two settings are independent. When the timer fired and the worker tried to open a fresh PostgreSQL connection (TCP handshake, TLS negotiation), that work was competing for throttled CPU, exactly the kind of background, non-request-driven operation this billing mode is designed to deprioritize.

I confirmed this directly rather than just inferring it. Cloud Monitoring's container instance count panel shows the instance flip from idle to active at the exact timestamp CPU utilization spikes from ~0% to ~50%. CPU is only granted once the instance becomes active. A same-config SELECT 1 keepalive log from each service, at roughly the same time, makes the gap concrete:

worker-dev:  acquireMs: 2299, queryMs: 100, poolBefore: {waiting: 0}
api:         acquireMs: 26,   queryMs: 2,   poolBefore: {waiting: 0}
Enter fullscreen mode Exit fullscreen mode

waiting: 0 in both rules out pool contention. The worker isn't queued behind other connections; the connect() call itself is just slow under throttled CPU.

The fix was switching the worker's billing/CPU-allocation setting from "only during requests" to "always allocated" (instance-based billing), keeping min-instances=1 so there's always a warm, fully-allocated instance to pick up the timer:

# gcloud
gcloud run services update workflow-worker \
  --region=us-central1 \
  --no-cpu-throttling \
  --min-instances=1 \
  --max-instances=10
Enter fullscreen mode Exit fullscreen mode 
# Terraform (google_cloud_run_v2_service)
resource "google_cloud_run_v2_service" "workflow_worker" {
  name     = "workflow-worker"
  location = "us-central1"

  template {
    scaling {
      min_instance_count = 1
      max_instance_count = 10
    }

    containers {
      image = "us-central1-docker.pkg.dev/PROJECT_ID/repo/workflow-worker:latest"

      resources {
        limits = {
          cpu    = "1"
          memory = "512Mi"
        }
        # false = CPU is always allocated (instance-based billing),
        # not just while a request is in flight. This is the
        # Terraform equivalent of `--no-cpu-throttling`.
        cpu_idle = false
      }
    }
  }
}
Enter fullscreen mode Exit fullscreen mode

The trade-off is worth noting: instance-based billing means you pay for the minimum instance continuously, not just while it's handling a request. That's the price of a background worker that reacts to timers instead of HTTP traffic. A request-driven alternative, using Cloud Tasks to invoke the worker over HTTP instead of a persistent BullMQ listener, would let Cloud Run scale to zero between runs, but it's a bigger architectural change and wasn't the right trade-off here.

Results

Metric Before After
Connection acquisition (typical) 1200–2600 ms 2–20 ms
Connection acquisition (worst-case) up to 10,440 ms 2–20 ms
SQL execution 2–80 ms 2–5 ms
Workflow resume latency (p99) 10–11 sec <200 ms

No application code changed. No SQL optimization was required. No database configuration changed. Only the Cloud Run CPU-allocation setting changed.

Key Engineering Takeaways

  • Instrument every layer. Without per-component timing, every optimization is based on assumptions.
  • Separate connection acquisition from query execution. Measuring only repository methods hides where latency actually occurs, and hides that "10 seconds" and "2 seconds" can be the same failure at different severities.
  • Use the simplest possible workload. Replacing the application query with SELECT 1 eliminated indexes, joins, table size, and execution plans from the investigation.
  • Compare equivalent systems. Another service using the same Cloud SQL instance became the control group that ruled out PostgreSQL and TypeORM.
  • Confirm, don't just infer, the runtime cause. A CPU utilization graph over the same time window turned "Cloud Run probably throttled us" into a confirmed diagnosis.
  • Understand your platform's billing model, not just its scaling model. In serverless environments, whether CPU is allocated during idle time can matter far more than database performance.

Top comments (2)

Collapse
 
mads_hansen_27b33ebfee4c9 profile image
Mads Hansen •

Excellent use of a control service and the connect() / SELECT 1 split. One production guardrail I would add is to keep acquisition latency as a first-class histogram after the fix, alongside pool active/idle/waiting counts and instance lifecycle events. Otherwise this class of regression gets folded back into “database latency” later.

I would also validate the fix under forced connection churn: recycle pooled connections, deploy a new revision, scale from one to several instances, leave Redis quiet long enough to reproduce the idle state, and exercise a Cloud SQL failover. Track warm versus newly established connections separately.

Finally, calculate the hard connection budget as max instances × pool max (plus other services). Always-allocated CPU removes the stall, but a burst across ten warm workers can expose a different failure mode: connection exhaustion. An alert on p95 acquisition time and acquisition/query ratio would catch both problems much earlier.

Collapse
 
titan00001 profile image
Piyush • • Edited

Thank you @mads_hansen_27b33ebfee4c9 for the detailed feedback, this is genuinely useful!

Our current keepalive ping actually prevents connection recycling rather than testing it, will fix that by forcing a real pool timeout in staging. New-revision deploys look solid across several real releases. Autoscaling burst is still open, a single cold start doesn't cover concurrent scale-out under load, so we're planning a proper burst test. On the connection budget, we'll re-check max_instances × pool_max against our actual configured ceiling rather than typical load. And we haven't set up the p95 acquisition-time / acquisition-query-ratio alerts yet, adding those next.

Appreciate you pushing this past debugging towards actually production-hardened.``