{"id":"IL-0582","org":"Kanmu","date":"2024-12-08","docs":["https://github.com/kanmu/qg","https://brandur.org/postgres-queues","https://github.com/riverqueue/river"],"title":{"en":"Jobs piled up in Kanmu's PostgreSQL-based qg job queue on Aurora as dequeue slowed and dead tuples kept growing","ko":"Aurora PostgreSQL 위의 qg 잡 큐에서 que_jobs 의 dead tuples 가 계속 늘어 잡이 대량으로 밀렸다"},"domain":["database","aws"],"impact":{"scope":"Asynchronous jobs in the qg job queue on the product database piled up and were processed slowly","users":"unknown","region":"unknown"},"review":{"written_by":"session","reviewed_at":null,"reviewed_by":null},"lessons":{"en":"A long-running query on the same database instance, even one unrelated to que_jobs, can keep VACUUM from removing que_jobs dead tuples, so the table keeps growing and the job queue slows down. qg's design with advisory locks and a recursive CTE is sensitive to dead tuples.","ko":"que_jobs 와 전혀 관계없는 쿼리라도 같은 DB 인스턴스에서 오래 실행되면 que_jobs 의 dead tuples 를 치우지 못하게 막아 테이블이 계속 커지고, qg 의 디큐 성능 저하와 DB 부하 상승으로 이어진다. 글쓴이는 이것을 오래 걸리는 쿼리 때문에 VACUUM 이 효과를 내지 못하는 PostgreSQL 운영의 전형적인 경우로 보았다. 이런 상황에서 어디를 확인해야 하는지를 정해 두고 습관으로 만들어야 한다고 느꼈다. 현재 qg 가 쓰는 advisory lock 과 Recursive CTE 는 dead tuples 의 영향을 받기 쉬운 설계다."},"related":[],"sources":[{"url":"https://tech.kanmu.co.jp/entry/2024/12/08/214106","kind":"blog","archived":"https://web.archive.org/web/20260725151017/https://tech.kanmu.co.jp/entry/2024/12/08/214106"}],"summary":{"en":"Kanmu runs its product database on Amazon Aurora PostgreSQL, a cluster with a writer instance and a reader instance. The same database is a transactional job queue through qg, a Go implementation of Que: jobs are rows in the que_jobs table, enqueued by the api and worker workloads and deleted by workers when finished. Workers dequeue with a recursive CTE that tries pg_try_advisory_lock on candidate jobs.\n\npg_stat_activity showed an unintended query from the PostgreSQL user created for Redash. Redash was meant to query the reader instance, but when the author had registered the Aurora database as a Redash data source in the past, the author had set the cluster endpoint, which points at the writer, instead of the reader endpoint. The query combined large table scans with CTEs, showed wait_event io:BufFileWrite, and kept running after the Redash client had disconnected, because the user had no query timeout such as statement_timeout. Under READ COMMITTED the query took its snapshot when it started, so que_jobs rows deleted after that were still visible to it and VACUUM would not remove them; the query's backend_xmin, 1226078887, matched the oldest xmin in the VACUUM output. The dequeue query filters only on queue and run_at, so the index scan also reached rows that were already dead and had to fetch each one to check its visibility, which slowed dequeue and raised the database load.\n\nThe team changed the Redash data source to the reader endpoint, ended the query's process with pg_terminate_backend and ran VACUUM again by hand, which cleaned up the dead tuples in one go, and dequeue performance returned to normal. Performance Insights had shown the query prominently, but it was missed at the time.","ko":"Kanmu 는 프로덕트 데이터베이스로 Amazon Aurora PostgreSQL 을 쓰고, 같은 데이터베이스를 Que 의 Go 구현인 qg 로 잡 큐로도 쓴다. 잡은 que_jobs 테이블의 행이고, worker 는 pg_try_advisory_lock 과 Recursive CTE 를 묶은 SQL 로 잡을 디큐하고 처리가 끝나면 행을 지운다. 어느 날 DataDog 에서 잡이 밀린다는 알림이 울렸다. 들어온 잡의 양은 평소와 같았지만 디큐 때의 lock_time 이 길어져 있었고, que_jobs 의 dead tuples 가 계속 늘고 있었다.\n\n원인은 Redash 였다. 글쓴이가 예전에 Aurora 데이터베이스를 Redash 데이터 소스로 등록하면서 reader 엔드포인트가 아니라 writer 인스턴스를 가리키는 클러스터 엔드포인트를 설정했다. Redash 에서 보낸 무거운 분석 쿼리는 클라이언트 연결이 끊긴 뒤에도 writer 에서 계속 돌았고, 그 사용자에게는 statement_timeout 같은 쿼리 타임아웃이 없었다. 트랜잭션 격리 수준이 READ COMMITTED 여서 이 쿼리는 시작할 때 스냅샷을 만들었고, 그 뒤 que_jobs 에서 지워진 튜플도 이 쿼리에는 보이는 상태였다. 그래서 VACUUM 은 이 튜플들을 치우지 않았다. qg 의 디큐 SQL 은 queue 와 run_at 으로만 걸러서 이미 dead 인 행도 인덱스로 훑었고, 가시성을 확인하려고 매번 튜플을 가져왔다. 그 결과 디큐가 느려지고 데이터베이스 부하가 올랐다.\n\n팀은 Redash 데이터 소스를 reader 엔드포인트로 고치고, pg_terminate_backend 로 문제의 쿼리를 끝낸 뒤 VACUUM 을 다시 실행했다. 이번에는 dead tuples 가 한꺼번에 치워졌고 worker 의 디큐 성능이 정상으로 돌아왔다."},"trigger":{"en":"A heavy ad hoc analysis query from the BI tool Redash ran for a long time on the writer instance, because the Redash data source pointed at the cluster endpoint.","ko":"Redash 에서 reader 인스턴스로 보내야 할 데이터 분석용 쿼리가, 데이터 소스 등록 때 잘못 설정한 클러스터 엔드포인트를 거쳐 writer 인스턴스에서 오래 실행됐다."},"severity":"unknown","symptoms":["throughput-degraded","high-latency"],"timeline":{"detected_after":null,"resolved_after":null},"date_kind":"published","detection":{"en":"A Datadog alert on unprocessed jobs piling up in the job queue.","ko":"처리되지 않은 잡이 밀리는지 감시하던 DataDog 알림이 대량의 잡이 쌓였을 때 울렸다."},"components":["database","autovacuum"],"root_cause":"human-operation","remediation":[{"text":{"en":"Changed the Redash data source to the reader endpoint","ko":"Redash 의 데이터 소스 설정 실수를 고쳐 reader 엔드포인트를 가리키게 했다."}},{"text":{"en":"Ended the long-running Redash query with pg_terminate_backend","ko":"VACUUM 을 막는 쿼리라고 확신한 뒤 pg_terminate_backend 로 그 쿼리의 프로세스를 강제로 끝냈다."}},{"text":{"en":"Ran VACUUM on que_jobs by hand again, which cleaned up the dead tuples","ko":"프로세스가 끝난 것을 확인하고 VACUUM 을 다시 수동으로 실행해 dead tuples 를 대량으로 치웠다."}}],"action_items":[{"text":{"en":"Make Redash unable to connect to the writer instance even if the writer endpoint is set, by mapping its host name to a TEST-NET-1 address in the Redash container's /etc/hosts","ko":"Redash 컨테이너의 /etc/hosts 에서 writer 엔드포인트 호스트 이름을 테스트용 무효 주소인 TEST-NET-1 의 IP 주소로 지정해, Redash 에 writer 엔드포인트를 잘못 설정해도 실제로는 접속하지 못하게 한다."}},{"text":{"en":"Set statement_timeout on PostgreSQL users so that long queries stop automatically","ko":"PostgreSQL 사용자의 statement_timeout 을 알맞게 설정해 오래 걸리는 쿼리를 자동으로 멈춰 재발을 막는다."}},{"text":{"en":"Consider improving qg's dequeue algorithm or adopting a job queue such as river that uses SELECT FOR UPDATE SKIP LOCKED","ko":"늘어날 잡을 견디도록 qg 를 개선하거나, SELECT FOR UPDATE SKIP LOCKED 로 락을 잡는 river 같은 기술을 쓰는 것을 검토한다."}}],"contributing":["delayed-effect-change","default-config-unchanged"],"recurrence_of":null,"symptoms_text":{"en":"A Datadog alert fired because a large number of unprocessed jobs had piled up in Kanmu's job queue and were not being worked off. The jobs were the batch enqueued at about the same time every day, in the usual volume, but the workers took far longer than normal to dequeue and process them.\n\nWorker logs showed the job fetch time, lock_time, longer than normal. The Datadog dead tuple metric postgresql.dead_rows showed the dead tuples of the que_jobs table growing steadily from a certain time. The team already knew that growing dead tuples degrade qg performance. autovacuum, which should remove them, did not seem to be working.\n\nA manual VACUUM VERBOSE que_jobs reported \"found 0 removable, 768195 nonremovable row versions in 15623 out of 15623 pages\" and \"679473 dead row versions cannot be removed yet, oldest xmin: 1226078887\", so running VACUUM did not reclaim anything.","ko":"처리되지 않은 잡이 밀리는지 감시하던 DataDog 에서 알림이 울렸다. 대량의 잡이 처리되지 못하고 쌓여 있었다.\n\n이 잡들은 매일 거의 같은 시각에 들어오는 것이었고 양도 평소와 크게 다르지 않았다. 그런데 worker 가 잡을 디큐해 처리하는 시간이 평소보다 눈에 띄게 길었다. worker 로그에서는 잡을 가져오는 시간인 lock_time 이 평소보다 길어져 있었다.\n\nDataDog 의 dead tuples 메트릭 postgresql.dead_rows 를 보자 que_jobs 테이블의 dead tuples 가 어느 시간대부터 계속 늘고 있었다. autovacuum 이 이를 처리해야 했지만 제대로 동작하지 않는 것으로 보였다.\n\n수동으로 VACUUM VERBOSE que_jobs 를 실행하자 INFO: \"que_jobs\": found 0 removable, 768195 nonremovable row versions in 15623 out of 15623 pages 와 DETAIL: 679473 dead row versions cannot be removed yet, oldest xmin: 1226078887 이 나왔다. 지울 수 있는 행은 0개였고, dead tuples 679,473개가 지워지지 않았다.\n\npg_stat_activity 에서 활성 쿼리를 보자 사내 BI 도구 Redash 용 사용자가 보낸 의도하지 않은 쿼리가 있었다. 이 쿼리는 Redash 클라이언트와 연결이 끊긴 뒤에도 계속 보였고, wait_event 는 io:BufFileWrite 였으며, backend_xmin 이 VACUUM 로그의 oldest xmin 과 같은 1226078887 이었다. 나중에 보니 이 쿼리는 Performance Insights 에도 눈에 띄게 나타나 있었지만 당시에는 놓쳤다."},"updated_at":"2026-11-14T12:34:22.796737Z","url":"https://benchlet.com/incidentlib/app/cases/IL-0582","org_slug":"kanmu"}