{"id":"IL-0308","org":"RevenueCat","date":"2022-11-23","docs":[],"title":{"en":"Most RevenueCat backend systems failed after cutover to a new Aurora PostgreSQL 14 cluster as queries became very slow","ko":"RevenueCat 이 Aurora PostgreSQL 10 에서 14 새 클러스터로 넘어간 직후 쿼리가 극도로 느려져 대시보드와 SDK 엔드포인트가 세 시간 넘게 실패했다"},"domain":["database","aws"],"impact":{"scope":"The RevenueCat dashboard and the SDK endpoints failed or partly failed from 9:39 to about 13:07 UTC; entitlements for new purchases did not unlock or needed several attempts for about 2 hours; some integration events were dispatched without being recorded","users":"RevenueCat customers, and users of their apps who made new purchases or had expired entitlements","region":"unknown"},"review":{"written_by":"session","reviewed_at":null,"reviewed_by":null},"lessons":{"en":"The new cluster had not been analyzed, and the tests missed it because the test cluster had been up long enough to gather statistics. Dry runs replayed no write traffic, on the belief that writes are simpler than reads, and the team assumed sequence state was replicated with the data. Rolling back at the start would have been better than fixing forward. The migration, timed to finish before Thanksgiving and Black Friday, should have been delayed until the week after, because the US had entered a sensitive period and part of the US support team was already on holiday.","ko":"RevenueCat 은 처음부터 롤백했으면 더 나았다고 돌아봤다. 사전 연습에서는 데이터 일관성과 쿼리 성능만 보고 쓰기 트래픽을 재생하지 않았다. 쓰기는 인덱스가 얽히지 않아 읽기보다 단순하다고 여겼기 때문이다. 복제를 멈추고 평소처럼 쓰기를 해 봤다면 문제를 찾을 수 있었다. 시퀀스 상태가 복제되지 않는다는 한계를 놓치고 상태도 함께 복제된다고 가정했다. 사전 연습 때는 새 클러스터가 오래 떠 있어 vacuum 과 통계가 이미 끝나 있었기 때문에 ANALYZE 가 없는 문제를 보지 못했다. 시기로는 추수감사절과 블랙 프라이데이 전에 끝내려 했지만, 미국 지원팀 일부가 이미 휴가 중인 민감한 때였으므로 그다음 주로 미뤘어야 했다고 밝혔다."},"related":[],"sources":[{"url":"https://www.revenuecat.com/blog/engineering/postmortem-aurora-postgres-migration","kind":"blog","archived":"https://web.archive.org/web/20260809225700/https://www.revenuecat.com/blog/engineering/postmortem-aurora-postgres-migration"}],"summary":{"en":"AWS planned to end support for Aurora PostgreSQL 10.x on January 31st, 2023, so RevenueCat had to upgrade its main database cluster. This time the team restored a snapshot on a new cluster, upgraded it to Aurora PostgreSQL 14.x, replicated changes from the production cluster into it, and planned to switch the old cluster to read-only and fail over once the last changes had replicated. The 44-step procedure was prepared over more than two months of tests and dry runs, which predicted less than 10 seconds of full and 1 to 2 minutes of partial downtime. On November 23, 2022 the new cluster was created from the snapshot at 2:51 UTC, replication had caught up by 8:51 UTC, the old cluster was switched to read-only at 9:34 UTC, and traffic moved to the new cluster between 9:34 and 9:39 UTC.\n\nOn the new cluster, high-throughput queries became extremely inefficient because ANALYZE had not run on the largest tables. In testing, the 14.x cluster had been up long enough for vacuum to finish and gather the statistics the query planner needs, but on migration day the vacuum of one of the largest tables had not finished before the cutover. Slow queries used all database connections and caused contention on the pg bouncers, and the failures spread through all systems. The team added a statement timeout to the database user at 9:54 UTC, shed 90% of traffic with 503s from the load balancer at 9:58 UTC, dropped indexes that were being used wrongly and were not needed, stopped accepting Apple webhooks, and rolled out a release without New Relic, whose agent was running EXPLAIN on the many slow queries. Between about 12:00 and 13:07 UTC the team found that ANALYZE had not run on the new cluster and ran it by hand on the biggest tables, and database performance improved drastically. Traffic was back to 100% at 13:07 UTC, and the remaining jobs were restored at 13:33 UTC.\n\nTwo other problems came with the switch. Replication had copied the table data but not the state of sequences, so primary key sequences on a handful of large tables produced values that already existed; a script prepared in advance raised the affected sequences. Integration event dispatching had not been stopped at the switch, so for a few minutes while the old cluster was read-only, events were dispatched but their status could not be written, until the dispatcher was stopped by hand; RevenueCat replayed the webhooks among them. Rollback was considered, but it meant reversing replication and moving traffic back while accepting no writes, and RevenueCat later judged that rolling back at the start would have been the better choice. For new purchases, entitlements did not unlock or needed several attempts during a 2-hour period.","ko":"AWS 가 Aurora PostgreSQL 10.x 지원을 2023년 1월 31일에 끝낸다고 알려 와, RevenueCat 은 주 데이터베이스 클러스터를 업그레이드해야 했다. 이번에는 데이터베이스 복제를 쓰기로 했다. 스냅샷을 새 클러스터에 복원해 Aurora PostgreSQL 14.x 로 올리고, 운영 클러스터의 변경을 복제해 따라잡은 뒤, 옛 클러스터를 잠깐 읽기 전용으로 바꾸고 새 클러스터로 페일오버하는 계획이었다. 44단계짜리 작업이라 두 달 넘게 준비하고 여러 번 사전 연습을 했다. 예상한 중단은 전체 중단 10초 미만, 부분 중단 1~2분이었다.\n\n2022년 11월 23일 2:51 UTC 에 스냅샷으로 새 클러스터를 만들고 복제를 시작했고, 8:51 UTC 에 복제가 따라잡았다. 9:34 UTC 에 옛 클러스터를 읽기 전용으로 바꾸고 트래픽을 새 클러스터로 옮기기 시작했고, 9:39 UTC 에 트래픽 전부가 새 클러스터로 갔다. 곧바로 심각한 성능 저하가 왔다. 사전 연습 때는 14.x 클러스터가 충분히 오래 떠 있어 vacuum 이 끝나고 쿼리 플래너가 쓸 통계가 모여 있었지만, 이날은 가장 큰 테이블 하나의 vacuum 이 전환 전에 끝나지 않았다. ANALYZE 가 돌지 않은 가장 큰 테이블들에서 처리량이 많은 쿼리가 극도로 비효율적으로 바뀌었고, 이것이 모든 시스템에 연쇄 장애를 일으켰다.\n\n팀은 9:54 UTC 에 데이터베이스 사용자에 statement timeout 을 걸고, 9:58 UTC 에 로드 밸런서에서 트래픽의 90% 에 503 을 보내 부하를 덜었다. 10:00 UTC 무렵부터 잘못 쓰이던 불필요한 인덱스를 지웠고, 10:30 UTC 무렵 트래픽의 50% 를 받을 수 있게 되었다. Apple 웹훅을 잠시 받지 않으면서 13:07 UTC 까지 트래픽을 100% 로 되돌렸다. New Relic 이 느린 쿼리마다 돌리던 EXPLAIN 쿼리를 없애려고 New Relic 을 끈 릴리스도 냈다. 12:00 UTC 무렵 많은 쿼리 플랜을 살핀 끝에 새 클러스터에서 ANALYZE 가 돌지 않았다는 것이 드러났고, 가장 큰 테이블들에 손으로 ANALYZE 를 돌리자 성능이 크게 나아졌다. 13:33 UTC 에 통합 이벤트 발송, ETL, 웹 서버 밖의 작업이 모두 돌아왔다. 그 밖에 시퀀스 상태가 복제되지 않아 큰 테이블 몇 개에서 기본 키가 겹쳤다. 또 전환 직후 통합 이벤트 발송을 멈추지 않아, 일부 이벤트는 발송되고도 기록되지 않았다. 팀은 롤백도 검토했다. 그러나 롤백은 복제 방향을 뒤집고 트래픽을 옛 웹 계층으로 되돌리는 복잡한 절차였고, 원인을 알았을 때는 대책을 모두 적용한 서비스가 꽤 잘 돌고 있어 그대로 수정을 이어 갔다."},"trigger":{"en":"At 9:34 UTC production traffic was switched from the Aurora PostgreSQL 10.x cluster to the new Aurora PostgreSQL 14.x cluster, before ANALYZE had run on its largest tables.","ko":"복제를 이용해 Aurora PostgreSQL 10.x 클러스터에서 새 14.x 클러스터로 트래픽을 넘겼다. 그런데 가장 큰 테이블 하나의 vacuum 이 전환 전에 끝나지 않아, 새 클러스터의 가장 큰 테이블들에 ANALYZE 가 돌지 않은 상태였다."},"severity":"unknown","symptoms":["database-overloaded","high-latency","service-unavailable","connection-pool-exhausted"],"timeline":{"detected_after":"5m","resolved_after":"3h 33m"},"date_kind":"incident","detection":{"en":"At 9:39 UTC, with all traffic on the new cluster, latency looked bad and the infrastructure team began to investigate.","ko":"9:39 UTC 에 트래픽 전부가 새 클러스터로 넘어갔을 때 지연이 나빠 보였고, 인프라 팀이 바로 조사를 시작했다."},"components":["database","autovacuum","database-replication","database-proxy","query-planner"],"root_cause":"upgrade-breaking-change","remediation":[{"text":{"en":"Added a statement timeout to the database user so queries could not hold a connection too long","ko":"9:54 UTC 에 쿼리가 데이터베이스 연결을 너무 오래 잡지 않도록 데이터베이스 사용자에 statement timeout 을 걸었다."}},{"text":{"en":"Shed 90% of traffic by returning 503s from the load balancer","ko":"9:58 UTC 에 로드 밸런서에서 트래픽의 90% 에 503 을 보내 부하를 덜고 시스템이 회복할 여유를 만들었다."}},{"text":{"en":"Dropped indexes that the planner was using wrongly and that were not needed","ko":"10:00 UTC 무렵부터 오래 걸리는 쿼리에 EXPLAIN 을 돌려 보고, 해만 끼치고 필요 없는 인덱스를 지우기 시작했다."}},{"text":{"en":"Stopped accepting Apple webhooks for a time","ko":"트래픽을 100% 로 되돌리는 동안 Apple 웹훅을 잠시 받지 않았다."}},{"text":{"en":"Rolled out a release without New Relic to stop its EXPLAIN queries","ko":"New Relic 이 느린 쿼리마다 돌리는 EXPLAIN 쿼리를 없애려고 New Relic 을 끈 새 릴리스를 냈다."}},{"text":{"en":"Ran ANALYZE by hand on the biggest tables","ko":"12:00 UTC 무렵부터 가장 큰 테이블들에 손으로 ANALYZE 를 돌렸다."}},{"text":{"en":"Raised the values of the affected primary key sequences with a prepared script","ko":"미리 준비해 둔 스크립트로 영향받은 시퀀스 값을 자동으로 올려 기본 키 중복을 풀었다."}},{"text":{"en":"Stopped the integration event dispatcher by hand","ko":"전환 몇 분 뒤 통합 이벤트 발송 작업이 이벤트 테이블을 갱신하지 못하는 것을 잡고 발송 작업을 손으로 멈췄다."}},{"text":{"en":"Replayed the webhooks that were dispatched but not recorded","ko":"발송되었지만 데이터베이스에 기록되지 않은 웹훅을 만일에 대비해 다시 보냈다."}},{"text":{"en":"Restored integration event dispatching, ETLs and other non-web server jobs","ko":"13:33 UTC 에 통합 이벤트 발송, ETL, 웹 서버 밖의 작업을 모두 되살렸다."}}],"action_items":[{"text":{"en":"Consider change freezes during business-critical periods","ko":"사업에 중요한 시기에는 변경 동결을 두는 것을 검토한다."}},{"text":{"en":"Explain better how the SDK behaves during backend outages","ko":"백엔드 장애 때 SDK 가 얼마나 믿을 만하게 동작하는지 더 잘 알린다."}},{"text":{"en":"Tell customers about maintenance and outages in the developer dashboard and by direct email to technical contacts","ko":"개발자 대시보드와 기술 담당자에게 보내는 직접 이메일을 써서 유지보수와 장애를 고객에게 더 잘 알린다."}},{"text":{"en":"Replay a subset of write traffic in migration dry runs to mimic the cutover","ko":"사전 연습에서 트래픽 일부를 재생해 전환 당일과 더 비슷한 조건을 만든다. 이번 연습은 쓰기 트래픽을 재생하지 않았다."}},{"text":{"en":"Move costly processes to asynchronous work to keep the API fast and stable","ko":"API 를 빠르고 안정적으로 유지하려고 비용이 큰 작업을 최대한 비동기로 옮기는 데 더 투자한다."}},{"text":{"en":"Re-evaluate table indexes, including unused ones the database may choose for queries","ko":"테이블 인덱스를 다시 검토한다. 쓰이지 않는 인덱스가 있고, 데이터베이스가 쿼리에 그 인덱스를 고르면 성능이 떨어질 수 있다."}},{"text":{"en":"Show the load of each endpoint and system in the database dashboards","ko":"데이터베이스 대시보드에서 엔드포인트와 시스템별 부하를 더 잘 보여 줘 부하가 어디서 오는지 빨리 찾게 한다. 이번에는 Apple 웹훅 부하가 복구를 막는다는 것을 아는 데 너무 오래 걸렸다."}},{"text":{"en":"Involve support and customer communications staff during outages","ko":"장애 중에 고객 지원과 고객 커뮤니케이션 담당을 불러 소통을 맡긴다."}}],"contributing":["staging-not-representative","assumption-unverified","automation-amplified","monitoring-blind-spot"],"recurrence_of":null,"symptoms_text":{"en":"At 9:34 UTC on November 23, 2022, RevenueCat started moving traffic from its Aurora PostgreSQL 10.x cluster to a new Aurora PostgreSQL 14.x cluster. By 9:39 UTC all traffic was on the new cluster, latency was bad, and the RevenueCat dashboard and the endpoints used by the RevenueCat SDK stopped working.\n\nStatements took much longer than normal and used up all database connections, and the pg pool cluster looked totally saturated, with the slow queries causing contention on the pg bouncers waiting for a free connection. Running EXPLAIN on long-running queries showed very inefficient query plans: one query used the wrong index, and Postgres did not choose the obvious index even in very simple cases. A third-party APM agent runs EXPLAIN on slow queries, so nearly every query had a long-running EXPLAIN beside it. On a handful of large tables, primary key sequences produced values that violated unique constraints for rows already in the tables.\n\nThe service came back in steps. With 90% of traffic shed, the systems recovered enough to show that database slowness was the source. After index changes, about 50% of traffic could be served by 10:15 to 10:30 UTC, with high response times. Incoming Apple webhook requests ran a particularly slow query and set recovery back until RevenueCat stopped accepting them for a time. Traffic was back to 100% at 13:07 UTC, still with higher latency.\n\nThe team first blamed a cold cache on the new cluster, although it had warmed the critical tables by reading all records added in the last 24 hours. As the database warmed and spent less time on IO, attention moved to the saturated pg pool cluster, and it was not clear whether pg bouncer or the database was slow; telling cause from effect took about an hour. The wrong index could also have been a different choice by the PostgreSQL 14 query planner. Only between about 12:00 and 13:07 UTC did it become clear that ANALYZE had not run on the new cluster.","ko":"2022년 11월 23일 9:39 UTC 에 트래픽 전부가 새 Aurora PostgreSQL 14.x 클러스터로 넘어갔고, 지연이 나빠져 인프라 팀이 조사를 시작했다. 9:54 UTC 에는 쿼리가 평소보다 훨씬 오래 걸리면서 데이터베이스 연결을 모두 차지하고 있었다.\n\nRevenueCat 대시보드는 9:39 UTC 부터 13:07 UTC 무렵까지 열리지 않았고, SDK 가 쓰는 엔드포인트도 같은 시간 동안 문제를 겪었다. 11:30 UTC 무렵에는 요청의 절반쯤이 처리되었고, 13:07 UTC 에는 100% 가 처리되었다. 새 구매는 스토어에서는 성공했지만 2시간쯤 entitlement 가 풀리지 않거나 여러 번 시도해야 풀렸다. 이미 만료된 entitlement 를 가진 사용자는 장애 동안 접근을 잃었다.\n\n데이터베이스 성능 문제가 모든 시스템에 연쇄 장애를 일으켜, 원인과 결과를 가려내는 데 1시간쯤 걸렸다. 처음에는 새 클러스터의 캐시가 아직 데워지지 않았기 때문이라고 보았다. 지난 24시간 동안 핵심 테이블에 들어온 레코드를 모두 읽어 캐시를 미리 데워 두었는데도 그렇게 판단했다. 데이터베이스가 데워져 IO 에 쓰는 시간이 줄자, 이번에는 완전히 포화된 것처럼 보이는 pg pool 클러스터를 의심했다. 느린 쿼리 때문에 빈 연결을 기다리는 pg bouncer 에 경합이 심했지만, 문제가 pg bouncer 인지 데이터베이스가 느린 것인지 분명하지 않았다.\n\n느린 쿼리에 EXPLAIN 을 돌려 보니 쿼리 플랜이 극도로 비효율적이었다. 한 쿼리는 잘못된 인덱스를 쓰고 있었는데, ANALYZE 가 없어서인지 Postgres 14 쿼리 플래너가 다른 인덱스를 고른 것인지 분명하지 않았다. 다른 쿼리는 아주 단순한 경우에도 Postgres 가 뻔한 인덱스를 고르지 못했고, 이는 테이블 통계가 없다는 신호였다.\n\n새 클러스터에서는 거의 모든 쿼리 뒤에 오래 걸리는 EXPLAIN 쿼리가 함께 실행되었다. 서드파티 APM 도구인 New Relic 이 느린 쿼리마다 EXPLAIN 을 돌렸고, 느린 쿼리가 많아지자 EXPLAIN 쿼리도 데이터베이스 자원을 많이 썼다.\n\n트래픽을 다시 받기 시작하자 Apple 웹훅 요청이 들어왔다. 이 요청의 쿼리가 쿼리 플랜 문제로 특히 느려 복구가 다시 더뎌졌다. 큰 테이블 몇 개에서는 기본 키 시퀀스 값이 이미 테이블에 있는 행과 겹쳐 고유 제약 위반이 났다."},"updated_at":"2026-11-14T12:33:56.222692Z","url":"https://benchlet.com/incidentlib/app/cases/IL-0308","org_slug":"revenuecat"}