{"id":"IL-0330","org":"incident.io","date":"2023-04-20","docs":[],"title":{"en":"Requests timed out for two weeks waiting on Go's database/sql connection pool, one for almost 20 seconds","ko":"Go database/sql 커넥션 풀을 기다리던 요청이 2주 동안 간헐적으로 타임아웃됐고, 한 요청은 거의 20초를 기다렸다"},"domain":["database"],"impact":{"scope":"Intermittent timeouts on API requests and other operations that used the database, over a period of two weeks","users":"unknown","region":"unknown"},"review":{"written_by":"session","reviewed_at":null,"reviewed_by":null},"lessons":{"en":"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.","ko":"한 번에 모든 것이 풀리는 결정적인 발견은 없었다. 대신 그 과정에서 이런 문제를 진단할 준비가 훨씬 잘 됐고, 실제 성능 개선도 함께 이뤄졌다. 원인은 눈에 띄게 느린 것 하나가 아니라 짧은 트랜잭션 여러 개가 합쳐진 것이었다. 애플리케이션의 부분마다 다른 데이터베이스를 썼다면 아마 더 빨리 찾았을 것이다. 하지만 그러면 분산 트랜잭션을 고민해야 하고 개발 환경도 덜 편해지므로, 팀은 지금의 선택을 유지한다."},"related":[],"sources":[{"url":"https://incident.io/blog/database-performance","kind":"blog","archived":"https://web.archive.org/web/20260617221712/https://incident.io/blog/database-performance"}],"summary":{"en":"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.\n\nAfter 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.","ko":"2023년 초 incident.io 애플리케이션은 2주 동안 데이터베이스를 쓸 때 간헐적으로 타임아웃을 겪었다. 첫 신호는 고객 신고와 Sentry 의 context canceled 오류였다. 트레이스를 보니 요청이 Go 의 database/sql 패키지가 관리하는 클라이언트 쪽 커넥션 풀에서 커넥션을 얻으려고 거의 20초를 기다렸다. 이 패키지는 커넥션 풀로 한 번에 데이터베이스와 통신하는 앱 프로세스 수를 제한한다. 쓸 수 있는 커넥션이 다 쓰이고 있으면 작업이 커넥션을 얻을 때까지 막힌다. 팀은 go.patch 파일로 database/sql 을 고쳐 ConnectionPoolWait 에 트레이스를 넣어 두었기 때문에 이 대기를 볼 수 있었다. 대기는 특정 풀 하나가 아니라 여러 곳에 퍼져 있었다. 트래픽, PubSub 지표, Heroku 의 Postgres 통계도 평소와 같았다.\n\n뚜렷한 출발점이 없어 팀은 느려 보이는 쿼리를 빠르게 고쳤다. 정책 위반 계산을 머티리얼라이즈드 뷰로 옮기고, 인덱스를 더하고, 인덱스 없는 열로 거르는 조인 쿼리를 다시 썼다. 며칠 안에 타임아웃이 다시 나자 모든 트랜잭션에 1초 락 타임아웃을 걸었다. 또 Slack 웹훅을 받으면 데이터베이스 쿼리 없이 바로 PubSub 로 넘기도록 바꿨다. 다음 날 또 타임아웃이 나자 팀은 관측성을 키우는 데 집중했다. ngrok/sqlmw 패키지로 미들웨어를 만들고, trackUsage 메서드로 작업마다 데이터베이스 커넥션을 쥐고 있던 시간을 세어 로그와 트레이스에 남겼다. gorm 의 훅은 커넥션 풀 대기 시간까지 포함해 재기 때문에 쓰지 않았다. 2주 동안 성능과 관측성을 겨냥한 변경 24개를 배포했다.\n\n로그를 살피던 중 팀은 Slack 모달 제출을 처리할 때마다 필요 없는 트랜잭션을 열고 있다는 것을 발견했다. 이 HTTP 엔드포인트는 사용자가 /inc 같은 슬래시 명령의 화면에서 확인 버튼을 누를 때마다 Slack 이 호출한다. 대부분의 모달 제출에서 트랜잭션을 없애고, 트랜잭션 보장이 필요한 코드 경로에만 명시적으로 넣었다. 타임아웃이 매일 나지는 않아서 이것이 근본 원인이었다는 것은 며칠 뒤에야 확인됐다. 느린 것 하나가 아니라 짧은 트랜잭션 여러 개가 쌓여 문제를 만들었다. 글을 쓴 시점까지 4개월 동안 데이터베이스 타임아웃은 없었다."},"trigger":null,"severity":"unknown","symptoms":["connection-pool-exhausted","intermittent-timeouts"],"timeline":{"detected_after":null,"resolved_after":null},"date_kind":"published","detection":{"en":"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.","ko":"고객 신고가 들어왔고 Sentry 에 context canceled 오류가 쏟아지면서 알아챘다. 온콜 엔지니어가 장애를 열고 Grafana 의 API 대시보드에서 타임아웃을 확인했다. 두 번째 타임아웃 때는 장애가 자동으로 열리고 온콜 엔지니어가 호출됐다."},"components":["database"],"root_cause":"software-bug","remediation":[{"text":{"en":"Moved the policy violations calculation to a materialised view","ko":"정책 위반은 요청마다 정책과 관련 장애를 모두 가져와 계산해 왔는데, 이 계산을 머티리얼라이즈드 뷰로 옮겼다."}},{"text":{"en":"Added database indices for slow queries","ko":"느린 쿼리를 빠르게 하려고 데이터베이스 인덱스를 새로 더했다."}},{"text":{"en":"Rewrote queries to filter on an indexed column already present in the join","ko":"인덱스 없는 열로 조인한 뒤 거르던 쿼리를, 조인에 이미 들어 있는 테이블의 인덱스 있는 같은 열로 거르도록 다시 썼다."}},{"text":{"en":"Added a one second lock timeout to all transactions","ko":"어떤 요청이 트랜잭션을 오래 쥐고 있는지 빨리 찾으려고 모든 트랜잭션에 1초 락 타임아웃을 걸었다."}},{"text":{"en":"Forwarded incoming Slack webhooks to PubSub and processed them asynchronously","ko":"Slack 웹훅이 들어오면 데이터베이스 쿼리 없이 바로 PubSub 로 넘겨 Slack 이벤트를 비동기로 처리하게 바꿨다."}},{"text":{"en":"Added a middleware that logs how long each operation holds a database connection","ko":"ngrok/sqlmw 패키지로 미들웨어를 만들고, trackUsage 메서드로 작업마다 데이터베이스 커넥션을 쥔 시간을 세어 로그와 트레이스에서 거를 수 있게 했다."}},{"text":{"en":"Removed the unnecessary transaction from most Slack modal submissions, keeping it only where needed","ko":"Slack 모달 제출 대부분에서 필요 없던 트랜잭션을 없애고, 트랜잭션 보장이 필요한 코드 경로에만 명시적으로 넣었다."}}],"action_items":[],"contributing":["monitoring-blind-spot"],"recurrence_of":null,"symptoms_text":{"en":"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.\n\nThe 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.\n\nNothing 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.","ko":"2023년 초 incident.io 애플리케이션이 데이터베이스를 쓰는 동안 간헐적으로 타임아웃이 났다. 고객 신고가 들어왔고, 오류 수집 도구 Sentry 에 context canceled 오류가 한꺼번에 쏟아졌다.\n\nGrafana 의 API 대시보드에서는 일부 API 요청이 타임아웃된 것이 보였지만 1분이 안 돼 정상으로 돌아왔다. 실패한 요청 하나의 트레이스를 열어 보니 HTTP 요청이 커넥션 풀에서 쓸 수 있는 커넥션을 얻으려고 거의 20초를 기다렸다. 이 대기는 database.sql.ConnectionPoolWait 스팬에 나타났다.\n\nKibana 에서 커넥션을 기다린 요청의 종류를 나눠 보니 특정 커넥션 풀 하나가 아니라 여러 곳에 퍼져 있었다. 이전 HTTP 트래픽과 PubSub 지표에는 평소와 다른 점이 없었다. Heroku 의 Postgres 통계에서도 데이터베이스 부하는 평범한 수준이었다. 데이터베이스 사용을 크게 바꾼 코드 변경도, 갑작스러운 트래픽 변화도 없었다. 로그, 트레이스, 대시보드에도 눈에 띄는 것이 없었다.\n\n팀은 느려 보이고 빨리 고칠 수 있는 쿼리부터 손봤고 장애를 닫았다. 하지만 며칠 안에 다시 커넥션 풀 대기로 타임아웃이 났다. Kibana 와 Google Cloud Trace 에서 느린 요청 사이에 뚜렷한 규칙은 보이지 않았다. 모든 트랜잭션에 1초 락 타임아웃을 걸어 봤지만 아무것도 깨지지 않았고 원인에 가까워지지도 않았다. Slack 이벤트를 비동기로 처리하게 바꾼 다음 날에도 타임아웃이 또 났다."},"updated_at":"2026-11-14T12:33:58.296702Z","url":"https://benchlet.com/incidentlib/app/cases/IL-0330","org_slug":"incident-io"}