{"id":"IL-0288","org":"CDN77","date":"2026-03-09","docs":["https://luminousmen.com/post/data-partitioning-slice-smart-sleep-better/"],"title":{"en":"ZooKeeperWait rose to thousands of seconds on three redundant ClickHouse instances, degrading a CDN77 data pipeline","ko":"CDN77 의 ClickHouse 데이터 파이프라인에서 이중화된 인스턴스 세 곳의 ZooKeeperWait 가 수천 초로 치솟아 복제가 한 시간 넘게 느려졌다"},"domain":["database","observability"],"impact":{"scope":"One large ClickHouse data pipeline was degraded for over an hour, with ZooKeeper traffic multiplied and replication slowed on three redundant instances; no observable impact on internal users, customers or partners","users":"none observed","region":"unknown"},"review":{"written_by":"session","reviewed_at":null,"reviewed_by":null},"lessons":{"en":"Data structure matters even in a pipeline built around volume: incoherent timestamps can destabilise it as effectively as changes in cardinality. A metric that looks odd and cannot be explained at once should not be set aside under incident pressure; the falling mean insert size was what led to the cause. Means and medians each have their place, and here the mean, not the median, exposed the problem. Partitioning has to be chosen carefully: too few partitions give oversized parts, slow mutations and costly or ineffective TTL, while too many slow column scans, add final merging to aggregating queries and overload the Keeper.","ko":"이 파이프라인은 주로 데이터 양을 다루지만, 어긋난 타임스탬프도 카디널리티 변화만큼 파이프라인을 흔들 수 있었다. 이상한 지표를 바로 설명하지 못했다고 치워 두면 안 된다. 이번에도 원인으로 이끈 것은 처음에 무시한 insert 크기 감소였다. 중앙값과 평균은 각자 쓸모가 있고, 이번에는 평균이 실마리였다. 파티션이 너무 적으면 파트가 커지고 mutation 이 느려지며 TTL 이 너무 비싸지거나 아예 동작하지 않는다. 반대로 너무 많으면 열 스캔과 집계 쿼리가 느려지고 Keeper 가 과부하된다. Keeper 작업은 파트 수에 따라 선형보다 훨씬 빠르게 늘었다."},"related":[],"sources":[{"url":"https://www.cdn77.com/blog/the-mysterious-zookeeper-wait","kind":"blog","archived":"https://web.archive.org/web/20260712212537/https://www.cdn77.com/blog/the-mysterious-zookeeper-wait"}],"summary":{"en":"Almost all tables in the affected ClickHouse database are time series partitioned by a time unit, and writes from thousands of client machines are batched through Buffer tables. Two engineers, working from different places, independently found the cause. One looked for client machines that could explain normal batch sizes next to a falling mean and found two machines sending batches so small and so fast that they nearly halved the average. The other saw in system.part_log a sharp rise in created parts while the total number of rows stayed roughly the same, with partitions carrying timestamps as old as four months. The two machines had been unplugged from the network for several months with no other maintenance, and their shipper processes kept running. Their only data was a local health check on a regular cadence, near zero in volume, so months of it fit in the shipper's queue; the shipper batches at log time rather than send time, so the queue held many tiny batches, and the cadence evenly covered hours and days, the two most common partitioning keys. The Buffer table did combine these batches with other traffic, but each flush then spanned a long timeline that MergeTree partitioning cut into far too many parts: a table partitioned by 5 minutes gets 288 replicated parts for each historical day. The parts were inserted, replicated and immediately scheduled for TTL deletion, and the default max_number_of_merges_with_ttl_in_pool of 2 kept them from being cleared quickly, so Keeper traffic multiplied and slowed replication, though not ingest.\n\nMost tables eventually cleared their backlog of parts on their own. The one short table partitioned by 5 minutes did not, and after the incident CDN77 dropped and recreated it and broadened its partitioning from minutes to hours. CDN77 added rejection of out-of-range timestamps in the root MaterializedView tables, with a second materialized view recording what was rejected, and built a test with an insert whose timestamps span days or months. It decided against lowering max_partitions_per_insert_block, because that setting can refuse inserts entirely and lose data. The incident also showed that Keeper operations grow much faster than linearly with the number of parts.","ko":"2026년 3월 9일 13:30 UTC 에 CDN77 의 큰 ClickHouse 데이터 파이프라인에서 ZooKeeperWait 지표가 이중화된 인스턴스 세 곳에서 동시에 수천 초로 치솟았다. 팀은 먼저 그때 시작된 매일 도는 data diff 작업의 무거운 읽기를 의심했지만, diff 쿼리가 다시 가벼워진 뒤에도 값이 높고 CPU, RAM, 쿼리 수가 정상이어서 가설을 버렸다. system.zookeeper_log 를 기본값대로 꺼 두어 Keeper 트래픽을 직접 볼 수 없었다. 그 뒤 insert 쿼리의 평균 크기가 줄고 TTL 병합이 크게 늘어난 것을 찾았다. Grafana 패널이 중앙값이 아닌 평균을 보여 준 덕에 무언가가 쓰기 크기를 끌어내리고 있음을 알 수 있었다.\n\n서로 다른 곳에서 대응하던 엔지니어 두 명이 각자 같은 결론에 닿았다. 13:15 UTC 부터 일부 insert 가 아주 긴 시간 범위에 걸쳐 있었고, 시간 단위로 나뉜 MergeTree 파티션 키 때문에 지나치게 많은 파트로 잘렸다. 원인은 평균을 거의 반으로 끌어내린 클라이언트 머신 두 대였다. 이 머신들은 몇 달 동안 네트워크에서 떨어져 있었지만 전송기 프로세스는 계속 돌았다. 머신 자체의 헬스 체크 데이터는 네트워크 없이도 일정한 간격으로 쌓였고, 전송기는 보낼 때가 아니라 기록할 때 배치를 만들었으므로 작은 배치들이 큐를 채웠다. 네트워크가 돌아오자 몇 달 치 데이터가 빠르게 들어왔다. Buffer 테이블은 이 배치를 다른 트래픽과 합쳤지만 합친 데이터가 긴 기간에 걸쳐 파티션마다 쪼개졌다. 5분 단위로 나뉜 테이블은 과거 하루마다 복제 파트 288개를 만들었다. 기본값 2 인 max_number_of_merges_with_ttl_in_pool 때문에 파트가 빨리 정리되지 않았다. 파트가 들어오고 복제되고 바로 삭제 예약되면서 Keeper 트래픽이 몇 배로 늘었고, 복제가 느려졌다. 지연 모니터링 테이블은 남아 있던 필터 때문에 CDN layer 0 머신의 데이터만 기록했고, 그보다 높은 layer 에 있던 이 두 머신의 지연은 잡지 못했다.\n\n대부분의 테이블은 결국 쌓인 파트를 정리했지만 5분 단위로 파티션을 나눈 테이블 하나는 그러지 못했다. 장애 뒤 이 테이블을 DROP-CREATE 로 다시 만들고 파티션 단위를 분에서 시간으로 넓혔다. 내부 사용자, 고객, 파트너에게 보이는 영향은 없었다."},"trigger":{"en":"From 13:15 UTC two client machines that had been cut off from the network for several months came back and their log shippers sent months of queued, very small batches of health check data with old timestamps, spanning a very large time range.","ko":"몇 달 동안 네트워크에서 떨어져 있던 클라이언트 머신 두 대가 다시 연결되면서, 그동안 쌓인 몇 달 치 헬스 체크 데이터를 아주 작은 배치로 빠르게 보냈다."},"severity":"unknown","symptoms":["replication-lag","throughput-degraded"],"timeline":{"detected_after":"15m","resolved_after":null},"date_kind":"incident","detection":{"en":"An alert on the ZooKeeperWait metric fired at 13:30 UTC, fifteen minutes after the problematic inserts began at 13:15. The cluster's alerting uses a low watermark of 10 sec and a high watermark of 20 sec.","ko":"13:30 UTC 에 팀은 ZooKeeperWait 지표가 갑자기 오른다는 알림을 받았다. 이 클러스터 크기에 맞춘 알림 기준은 낮은 쪽 10초, 높은 쪽 20초였다."},"components":["database","coordination-store","database-replication","telemetry-agent"],"root_cause":"capacity","remediation":[{"text":{"en":"Dropped and recreated the one table partitioned by 5 minutes that had not cleared its backlog of parts","ko":"쌓인 파트를 끝내 정리하지 못한 5분 단위 파티션 테이블을 장애 뒤 DROP-CREATE 로 다시 만들어 정상으로 되돌렸다."}},{"text":{"en":"Broadened that table's partitioning from minutes to hours","ko":"그 테이블의 파티션 단위를 분에서 시간으로 넓혔다."}}],"action_items":[{"text":{"en":"Reject out-of-range timestamps in the root MaterializedView tables","ko":"루트 MaterializedView 테이블에서 범위를 벗어난 타임스탬프를 거부하도록 구현했다."}},{"text":{"en":"Record statistics on rejected rows in a second materialized view","ko":"두 번째 MaterializedView 가 거부된 데이터의 통계를 기록한다."}},{"text":{"en":"Refine the deliberately wide rejection boundaries as data on rejections comes in","ko":"거부 범위는 과거 데이터 백필을 위해 일부러 넓게 잡았고, 거부되는 데이터를 모아 가며 범위를 다듬는다."}},{"text":{"en":"Keep a minimal test scenario with an insert query whose timestamps span days or months","ko":"타임스탬프가 며칠이나 몇 달에 걸친 insert 쿼리 하나로 이번 상황을 재현하는 최소 시험 시나리오를 만들었다."}},{"text":{"en":"Make a range of observability improvements","ko":"관측 기능을 여러 가지 개선한다."}}],"contributing":["monitoring-blind-spot","default-config-unchanged","early-signal-ignored"],"recurrence_of":null,"symptoms_text":{"en":"At 13:30 UTC on 9 March 2026, CDN77's data team was alerted to a sudden rise in the ZooKeeperWait metric on the ClickHouse cluster behind one of its large data pipelines. Alerting for this cluster size is set at 10 sec for the low watermark and 20 sec for the high one, and the metric reached thousands of seconds. The same rise appeared on three symmetrically redundant ClickHouse instances in different datacenters, each with its own ZooKeeper instance, and the pipeline stayed degraded for over an hour, with no observable impact on internal users, customers or partners.\n\nThe first suspect was a heavy read query stalling writes, the usual cause when ZooKeeperWaitMicroseconds climbs, especially as no configuration had changed that day. A daily data-diff job had started almost exactly when the metric went up, but within minutes its queries were light again while ZooKeeperWait stayed high, and CPU, RAM and the number of executing queries on the affected instances all looked normal, so heavy reads were ruled out.\n\nAbout twenty minutes in, an engineer saw that the mean insert query size in system.query_log was falling: the log shippers seemed to send a median of around 70,000 rows per second, while ClickHouse reported an average around 40,000. The team set this aside as a side effect of Keeper load, because an overloaded ClickHouse normally shows slower Buffer engine flushes and these were not slowing. Then TTL merges rose sharply, with merge reason TTLDeleteMerge everywhere in system.part_log, and the error log repeated \"Not executing log entry because 2 merges with TTL already executing.\" The team asked whether ttl_only_drop_parts, enabled on most of its tables, had somehow been disabled. The classic \"too many parts\" error never fired, because the configured limits were not reached.\n\nTwo gaps made the investigation harder. system.zookeeper_log, which would have shown Keeper traffic directly, was disabled, as it is by default in ClickHouse, because it can grow very large. The table that monitors delivery delay recorded only machines at CDN layer zero because of a leftover filter, while the machines behind the problem sat on a higher layer, so the lag was never measured precisely.","ko":"13:30 UTC 에 ZooKeeperWait 지표가 갑자기 오른다는 알림이 왔다. 이 클러스터의 알림 기준은 낮은 쪽 10초, 높은 쪽 20초인데 값은 수천 초였다. 값은 대칭으로 이중화된 인스턴스 세 곳에서 똑같이 올랐다.\n\n팀은 처음에 무거운 읽기 쿼리가 쓰기를 막는다고 의심했다. ZooKeeperWaitMicroseconds 가 오르기 시작한 때와 거의 같은 때 매일 도는 data diff 작업이 시작됐기 때문이다. 몇 분 뒤 diff 쿼리가 가벼워졌는데도 ZooKeeperWait 는 높게 남았고, CPU, RAM, 실행 중인 쿼리 수도 정상이어서 이 가설을 버렸다.\n\nKeeper 트래픽을 직접 볼 수 있는 system.zookeeper_log 는 ClickHouse 기본값대로 꺼 두었기 때문에 팀은 Keeper 부하를 간접 증거로 짐작해야 했다. 세 인스턴스는 서로 다른 데이터센터에 있어 한꺼번에 문제가 생길 것 같지 않았다.\n\n장애가 시작되고 약 20분 뒤, system.query_log 에서 본 insert 쿼리의 평균 크기가 줄고 있었다. 로그 전송기는 평소대로 중앙값 약 70,000 행/초를 보내는데 ClickHouse 는 40,000 행/초 대의 평균을 보고했다. 팀은 이를 바로 설명하지 못해 Keeper 부하의 부수 효과로 치워 두었다.\n\nsystem.part_log 에서는 병합 이유가 TTLDeleteMerge 인 TTL 병합이 크게 늘었고, ClickHouse 오류 로그에는 \"Not executing log entry because 2 merges with TTL already executing.\" 이 되풀이됐다. 팀은 대부분의 테이블에 켜 둔 ttl_only_drop_parts 가 어떤 이유로 꺼진 것은 아닌지 의심했다.\n\nsystem.part_log 에서 만들어진 파트 수는 크게 늘었는데 전체 행 수는 거의 그대로였고, 파티션 이름에는 넉 달 전 타임스탬프까지 보였다. 흔히 겪는 \"too many parts\" 오류는 나지 않았다. 설정한 한도에 닿지 않았기 때문이다."},"updated_at":"2026-11-14T12:33:54.316049Z","url":"https://benchlet.com/incidentlib/app/cases/IL-0288","org_slug":"cdn77"}