A misleading New Relic trace, nine goroutines, and a scheduled 9 AM push notification all contributed to a recurring stall on our job detail page. The slow query that everyone suspected turned out to be innocent. The real bottleneck was the database connection pool.

The symptom

Every morning at 9 AM, our marketing team sends a push notification blast. Every morning at 9:03, database CPU and I/O spike. And every morning, a handful of requests to the job detail page (GET /job/:slug, the most important page in our product) would stall. Not just slow: stalled. One trace showed a response time of 2 minutes 14 seconds.

The New Relic trace for that request looked like this:

Segment Duration %
GET /job/:slug 2 min 14 s 100%
service.jobPage 2 min 14 s 99.74%
Postgres select 219 ms 0.16%
repository.FindJob 45 ms 0.03%
Postgres other 27 ms 0.02%

The transaction spent 99.74% of its life inside jobPage, and New Relic could account for about 300 milliseconds of it. The remaining 2 minutes and 13 seconds were not attributed to anything. They sat inside a single parent segment with no children to explain them.

Why the trace showed nothing

jobPage loads a job, then fetches everything the page needs (the jobseeker's profile, CV, skills, preferences, the employer, the application state) as 9 parallel queries using an errgroup: 

g, gctx := errgroup.WithContext(ctx)

g.Go(func() error {
	profile, err = repo.FindProfile(gctx, db, userID)
	...
})
g.Go(func() error {
	employer, err = employerRepo.FindEmployer(gctx, db, employerID)
	...
})
// ... seven more

Each repository method starts a New Relic segment from the context, and our Postgres driver (nrpq) creates a datastore segment for every query. In theory, the trace should show all nine.

The catch is that the New Relic Go agent does not allow concurrent segment creation on a single transaction reference. All nine goroutines shared one *newrelic.Transaction through gctx. The agent keeps one segment stack per transaction, and nine goroutines pushing and popping on it concurrently corrupts that stack. The agent then silently drops the out-of-order segments.

That is why the trace was empty. The segments that would have shown the slow queries were being created and immediately discarded, and all the unaccounted time collapsed into the parent jobPage segment.

The fix is one transaction reference per goroutine: 

// inside each g.Go closure:
gctx := newrelic.NewContext(gctx, txn.NewGoroutine())

We wrapped that in a small helper and added it to every closure. This changed nothing about production behavior, but it changed what we could see.

The pool queue

The next morning, the trace told a different story:

repository call #1        7.14 s   99.76%
  ├─ Application code in (...)    7.14 s   99.65%   ← ???
  └─ Postgres select                 8 ms    0.11%
repository call #2        7.14 s   99.71%
  ├─ Application code in (...)    7.14 s   99.65%   ← ???
  └─ Postgres select                 4 ms    0.06%
repository call #3         26 ms
repository call #4         24 ms

The repository call took 7.14 seconds. The actual SQL query inside it took 8 milliseconds. New Relic labelled the gap honestly: "Application code", meaning time inside the function that is not any instrumented database call.

Two of the nine parallel queries blocked for an almost identical 7.14 seconds, then finished together. The other seven completed in 16–26 ms.

That gap lives inside Go's database/sql package, in the connection pool. nrpq instruments the driver; the pool sits one layer above it, and no APM instrumentation can see into it. The timeline of those 7.14 seconds was: 

[ waiting for a free connection from the pool ]  ~7.1 s   ← invisible
[ query executes ]                                8 ms

The two stalled goroutines were the last two in line when the pool ran dry. Seven of nine got connections instantly; the remaining two queued until connections were available, which is why they woke up at the same moment.

The connection math

Once you see it, the math is straightforward. For example, let each of these be a variable: 

C = concurrency per instance (requests)
Q = connections per jobPage request (one per parallel query)
P = pool size (maxOpenConns per instance)

peak demand       = C × Q connections
requests that fit = P ÷ Q

Once C × Q exceeds P, requests queue at the pool. On a normal day, queries are fast and connections turn over quickly enough that nobody notices. During the 9 AM burst, the database slows down under load, so every connection is held longer, which means the queue grows faster, which means more requests pile up holding connections while waiting. A congestion collapse, triggered on schedule every morning by marketing.

Raising maxOpenConns only moves the ceiling; it does not remove the 9× multiplier. The real ceiling is maxOpenConns × max instances versus Postgres' max_connections. We would have been back here within a quarter.

Merging the queries

The fundamental problem was not pool size. It was that one page view needed nine simultaneous connections. So we merged the eight fan-out queries into a single statement: one round trip, one connection.

The merged query returns exactly the same data as the eight separate queries it replaced, just in a single round trip. The approach is simple: fetch every section the page needs in one statement, returning single-row sections as columns and list-like sections as small JSON aggregates that the Go layer decodes into slices. The result preserves the old behavior, including how an empty section maps to a zero value. While merging, we also noticed one query was redundant and removed it.

The risky part of a wide merged query is the positional Scan() list: one wrong column order and you are shipping bug. So we handled it with careful testing. We ran the old queries and the new one against the same schema and data, then compared the results for every field, including the empty and missing section cases.

The test immediately caught a real bug: one legacy query scanned a date column into an embedded struct field whose name did not match, a mismatch invisible in the code until the comparison checked the two structs field by field.

Production EXPLAIN ANALYZE on the merged query reported 6.4 ms execution, with every table served by an index. We are satisfied with that result.

Results

Before After
Connections per request 8–9, concurrent 1
DB round trips per request 9 1
Peak demand at 80 req/instance ~720 conns ~80 conns
jobPage p99 during 9 AM burst up to 2 min 14 s milliseconds
Trace visibility 99.74% in jobPage, unattributed every step attributed

What we learned

  1. When your APM shows a large parent segment with no children, suspect the instrumentation before the code. Concurrent segment creation on one New Relic transaction reference silently drops segments. txn.NewGoroutine() per goroutine is not optional.
  2. "Application code" around a database call usually means the connection pool. Driver instrumentation cannot see pool wait time; it starts measuring after a connection is acquired. If the query is fast but the span is slow, you were queueing.
  3. Do the connection math. concurrency per instance × connections per request is your real demand. A pool sized for the average query count collapses the moment queries run in parallel.
  4. Pool size is a ceiling, not a fix. Reducing connections per request, whether through fewer queries or one merged query, removes the multiplier instead of raising the roof.
  5. Traffic bursts on a schedule are convenient. A predictable 9 AM spike is the easiest kind of incident to reproduce, instrument, and verify a fix against.
  6. Test the merge carefully. Merging queries is simple, but it is easy to get wrong. Comparing the old results with the new ones on the same data makes the change safe, and it will catch at least one bug you did not expect. It caught ours.