Incident Library

IL-0330 incident.io · 2023-04-20 (published)database

Requests timed out for two weeks waiting on Go's database/sql connection pool, one for almost 20 seconds

incident.io's Go application talks to Postgres through the connection pool in the database/sql package, which caps how many parts of the application can use the database at once; when every connection is in use, an operation blocks until one is free. In early 2023 requests intermittently waited for a connection, one of them for almost 20 seconds, and timed out. Because the waits were spread across many requests and pools and the database load looked normal, the team first shipped quick fixes for whatever looked slow: policy violations were moved to a materialised view instead of loading policies and all their incidents on each request, new indices were added, and queries that filtered on unindexed columns after a join were rewritten to filter on an indexed column already in the join. When the timeouts returned, a one second lock timeout was added to all transactions, and Slack webhooks, which can arrive in large batches and had each triggered database queries inside the HTTP request, were forwarded to PubSub for asynchronous processing.

After yet another period of timeouts, the team added a measure of how long each operation held a database connection. Hooks in gorm, the ORM, also counted time spent waiting for the pool, so a middleware built on the ngrok/sqlmw package recorded the time around each query and transaction, counting a transaction as one hold so its statements were not counted twice, and added it to the log line and trace of each HTTP request and PubSub message. While checking that this counter worked, the team noticed an unnecessary transaction opened every time the application handled a Slack modal submission, the HTTP endpoint Slack calls when a user confirms the view opened by a slash command such as /inc. The transaction was removed from most modal submissions and kept explicitly on the code paths that needed transactional guarantees. Because the timeouts did not happen every day, it took a few days to confirm that this was the cause; four months later there had been no further database timeouts. No single slow operation was behind the problem: many short transactions, added together, caused it.

Severity
–
Scope
Intermittent timeouts on API requests and other operations that used the database, over a period of two weeks
Users affected
–
Region
–
Time to detect
–
Time to resolve
–

Symptoms

Over two weeks in early 2023, incident.io's Go application intermittently timed out on requests that used its Postgres database. A customer reported the problem, Sentry showed a burst of context canceled errors, and the first episode was over within a minute.

The Grafana API dashboard confirmed that some API requests had timed out. The trace of one failed HTTP request showed it had waited almost 20 seconds to get a connection from the client-side connection pool in Go's database/sql package; the wait appeared as a database.sql.ConnectionPoolWait span, which incident.io had added by patching database/sql. Grouping the stuck requests in Kibana showed that the waits were spread across many kinds of requests and many connection pools, not one pool, and neither Kibana nor Google Cloud Trace showed a pattern in the slow requests.

Nothing obvious had changed: no code change had altered database usage much, traffic had not jumped, and logs, traces and dashboards showed nothing alarming. Historical HTTP traffic and PubSub metrics looked ordinary, and Heroku's Postgres statistics showed normal load apart from some queries that had grown slower as the database grew. The team fixed those slow queries, but the timeouts came back within a couple of days. A one second lock timeout on every transaction broke nothing but brought the team no closer to the cause, and moving Slack event handling to asynchronous processing through PubSub was followed by another period of timeouts the next day. In those two weeks the team deployed 24 performance and observability changes.

Symptom Connection pool exhaustionIntermittent timeouts

Root cause

Root cause Software defect

Component Database
Contributing factor Monitoring blind spot
Trigger
–

Detection

A customer report and a flurry of context canceled errors in Sentry; the on-call engineer opened an incident and checked the Grafana API dashboard. In the second episode an incident was opened automatically and the on-call engineer was pulled into it.

Remediation

Action items

–

Lessons

The cause was not one slow operation but many short transactions that, added together, caused the problem. The investigation left incident.io with a way to filter logs and traces by how long each operation holds a database connection, and with real performance improvements. Separate databases for separate parts of the application would probably have made the cause easier to find, but would bring distributed transactions and less convenient development environments, a trade-off incident.io chose not to make for now.

Sources

Related cases

Check your cluster for this

kubegap audits a Kubernetes cluster for conditions like the ones in this case, Database among them, read-only, from Claude Code or Codex. Its checks cite public reports like this one.

Open kubegap

For AI tools and scripts

The API needs no key. The MCP server offers search_incidents, get_incident, list_incidents, get_topic and vocab; both are explained on API and MCP.