Hive Hive
Sign in

kura: snapshot index reconcile costs ~5x its memory budget and runs at 100% duty cycle, driving nodes to Critical and stalling replication

GitHub issue · Open

Metadata
Source
tuist/tuist #12026
Updated
Jul 22, 2026
Domains
Kura
Details

On 2026-07-22, kura-tuist-eu-central-1-1 (production, eu-central) went from Constrained to sustained Critical memory pressure at 16:02Z and stayed there. Critical pauses the outbox worker outright, and the pod’s replication outbox went from 0 to 103,576 messages in 25 minutes.

The trigger was the action-cache snapshot index reconcile, which started at 15:55:11Z — the first snapshot fetch this process ever served. Two defects compound:

  1. a reconcile pass allocates roughly 5× the memory budget it reserves, and
  2. a pass takes longer than the freshness window it is kept fresh to, so it runs continuously rather than periodically.

Either alone would be tolerable. Together they turn a node sitting 230–330 MB under its hard limit into one pinned at Critical, and the only thing memory pressure sheds is peer replication.

Grafana links are included, but the raw series are inlined in the appendix because they age out of retention within days.

Impact

CriticalMemoryController::pause_outbox()outbox_task_loop skips process_outbox entirely:

// kura/src/replication/mod.rs:221
let pause_outbox = state.memory.pause_outbox();
state.metrics.update_background_work_paused("outbox", pause_outbox);
if !pause_outbox && let Err(error) = process_outbox(&state).await { ... }
// kura/src/memory/mod.rs:146
pub fn pause_outbox(&self) -> bool {
self.pressure() == MemoryPressure::Critical
}

kura_background_work_paused{worker="outbox"} goes to 1 at 16:02Z and never returns to 0. The outbox climbs monotonically from there. Peer replication requests decay from 11,861 to 5,798 per 5 min while 13k–23k artifact writes per 5 min keep arriving.

This is not a lone data point — the mesh is broadly backlogged. At 16:20Z: kura-tuist-eu-central-1-0 = 913,842 outbox messages draining ~630 per 5 min, kura-tuist-scw-fr-par-0 = 64k–120k.

Timeline (UTC, 2026-07-22)

Time Event
~13:10 pod becomes Ready after its cold bootstrap (kura_ready_state 0→1); pressure has been Constrained since before 12:00 and never returns to Normal
13:00–15:55 RSS flat 1.48–1.60 GB. jemalloc_allocated flat at 356–358 MB. Outbox flat at 0 all day. No snapshot index has ever been built (zero snapshot log lines from 06:00Z on)
15:55:11 first action-cache snapshot index build started, namespaces tuist and mastodon, 225 µs apart — both cold, Serve-triggered
15:56:30 first Critical transition; RSS +310 MB in 2.5 min (1.485 → 1.795 GB) with no client write traffic yet
15:57:23 pass 1 completes: changed=100000 (the cap), cascade-deletes 30,919 entries, elapsed_ms=132303
15:58 recovers to Constrained (RSS dips to 1.602 GB, under the 1.642 GB recovery threshold)
16:00:00 CI wave lands. Artifact writes 0–185 → 15,054 per 5 min. BatchReadBlobs 0 → 13,134 per 10 min. Outbox leaves 0 for the first time
16:03:30 outbox drains 19,502 → 6,318 — the sender is still keeping up at this point
16:02:00 Critical latches. background_work_paused{worker="outbox"} = 1. RSS 1.87–2.02 GB thereafter
16:02 → 16:25 outbox climbs monotonically to 103,576

Defect 1 — the build’s permit understates its real peak by ~5×

run_index_build takes a materialization permit sized:

// kura/src/reapi/mod.rs:871
let budget = SNAPSHOT_BUILD_BUDGET_BYTES
.min(state.memory.reapi_materialization_pool_bytes() / 2)
.max(1);

For this pod (soft 1,502,609,408, hard 1,824,522,240):

  • pool = clamp((hard − soft) / 2, 1, 128 MiB) = min(160,956,416, 134,217,728) = 128 MiB
  • budget = min(192 MiB, 64 MiB) = 64 MiB

Measured cost of a pass:

before 15:55 during reconcile
jemalloc_allocated flat 356–358 MB 476–675 MB sawtooth, peaks at pass boundaries
jemalloc_resident 468–492 MB 675 → 973 MB
process RSS 1.48–1.51 GB 1.69 → 2.02 GB

The RSS rise (+480 MB) is matched almost exactly by the jemalloc_resident rise (+480 MB), so this is heap, not page cache or mmap. rocksdb_block_cache_usage stays flat at 48–77 MB throughout and manifest_cache_bytes is 0 — neither is involved.

So a pass costs +120 to +320 MB of live heap against a 64 MiB reservation. The .min(pool / 2) adaptation shrinks the token without shrinking the work: admission control admits work it cannot cover. At 64 MiB out of a 128 MiB pool, two namespaces are admitted concurrently (which is exactly what happened — tuist and mastodon both built at 15:55:11).

The constant’s own comment says it is sized at “~1KB per entry of scan-buffer + current-map peak, with headroom” (reapi/mod.rs:2313) — that reasoning is undone by the adaptation, and by the fact that the peak also carries the node table, which the entry cap does not bound (nodes reached 477,218 for 78,842 entries).

Secondary effect: jemalloc_resident (950 MB) runs ~350 MB above allocated (~600 MB), so pages dirtied by a pass stay resident after it ends and RSS ratchets rather than returning to the pre-pass level.

Also note the build waits up to SNAPSHOT_BUILD_PERMIT_WAIT (600 s) for a permit rather than declining (reapi/mod.rs:855). That is deliberate and well-argued in the comment, but the consequence is that memory pressure cannot shed this work — the only background worker pressure can shed is the outbox.

Defect 2 — a pass outlives its freshness window, so it never stops

  • SNAPSHOT_RECONCILE_INTERVAL = 60 s (reapi/mod.rs:2328)
  • SNAPSHOT_REFRESH_TICK = 15 s (reapi/mod.rs:2335)
  • observed elapsed_ms for the tuist namespace: 62 s → 217 s

The pass is stale the moment it finishes, so the next 15 s tick re-triggers it. The reconcile log shows passes back to back with no gaps from 15:55 onward: for this namespace it is a 100 % duty cycle, not a periodic job. That is what makes the transient permanent — there is no idle interval for RSS to fall back through the 1.642 GB recovery threshold, so Critical latches by hysteresis (observe(), memory/mod.rs:88: from Critical, de-escalation needs ≤ 90 % of the limit; post-16:00 RSS never drops below 1.685 GB).

It also self-worsens. Across 35 minutes:

pass end entries nodes changed deleted scan_ms load_ms gate_ms elapsed_ms
15:57:23 50,497 138,831 100,000 30,919 18,679 32,804 80,820 132,303
15:59:35 57,499 151,443 49,503 22,740 17,358 15,791 29,295 62,444
16:02:48 59,068 298,180 42,501 21,220 37,311 11,772 70,800 119,883
16:05:43 61,386 354,355 40,932 19,393 31,567 13,251 69,736 114,554
16:08:54 67,208 197,054 38,614 14,532 34,314 9,771 81,783 125,868
16:11:56 68,986 311,956 32,792 14,934 35,008 9,246 68,984 113,238
16:14:49 72,783 474,008 31,014 12,174 22,006 14,130 70,067 106,203
16:17:57 73,438 210,295 27,217 14,365 39,485 7,181 66,785 113,451
16:21:04 74,756 344,996 26,562 14,252 30,349 8,400 82,626 121,375
16:24:51 76,715 391,258 25,244 17,363 33,674 9,460 110,161 153,295
16:29:40 78,842 477,218 23,285 17,255 42,621 9,420 165,019 217,060

gate_ms — the presence gate, which does a store point read per node per entry (reapi/mod.rs:1073) — grows 29 s → 165 s and is the dominant and fastest-growing term. Note this is not an effect of the Critical transition: allow_manifest_cache_admission() requires Normal, and the pod had been Constrained for hours, so the manifest cache was already cold at 0 bytes before any of this. It tracks the node table growing.

Why it only started at 15:55

Included because it explains why this is latent rather than continuous, and why it will recur on every node as fleet traffic shifts.

The reconcile is demand-created: refresh_snapshot_indexes only walks indexes already in the snapshot cache (reapi/mod.rs:172“a node serving nothing does no work”), and an index enters that cache only via a Serve. The snapshot has no route of its own — it rides GetActionResult under the reserved action key tuist-actioncache-snapshot/v2 (reapi/mod.rs:2221), so it is invisible in route metrics.

This pod was Ready from ~13:10 and served GetActionResult from ~14:20, but a client fetches the full snapshot once per session (reapi/mod.rs:165). 15:55:11 is the first new session to land here — the leading edge of the CI wave whose full weight arrives at 16:00. From that instant the refresher has something to walk, and never stops.

(One thing the data cannot distinguish: whether 15:55 was the first new session or the first client speaking snapshot v2. The snapshot shares the GetActionResult counter.)

Directions worth considering

  • Bound a pass’s actual peak to the permit it holds, or size the permit from the observed peak. Today the adaptation does neither.
  • Serialize index builds per node instead of admitting one per namespace concurrently.
  • Back off when a pass overruns its interval — schedule the next from the observed pass duration rather than a fixed window, so the duty cycle stays below 100 %.
  • Reconsider whether the presence gate must sweep the whole index every pass. It is the dominant cost and grows with the node table, which nothing bounds.
  • Emit metrics for reconcile duration, duty cycle, and overrun count. Today this is only visible by reading Loki, which is how it went unnoticed.

Related

  • #11221 — GetActionResult returning hits whose output blobs were evicted. The presence gate in this reconcile is the machinery that fixes that; this issue is about what that machinery costs.
  • #11955 — the same pod’s cold bootstrap, which is why it only became Ready at ~13:10.

Appendix — raw series (env=production, pod=kura-tuist-eu-central-1-1)

Grafana: kura-7c-pod, 15:50–16:15Z

Limits (constant): kura_memory_soft_limit_bytes = 1,502,609,408 · kura_memory_hard_limit_bytes = 1,824,522,240 · recovery thresholds (9/10) = 1,352,348,467 (soft) and 1,642,070,016 (hard).

kura_process_resident_memory_bytes, MB, 60 s — reconcile starts 15:55:11, writes start 16:00:

15:45 1506 | 15:46 1507 | 15:47 1507 | 15:48 1505 | 15:49 1505 | 15:50 1505 | 15:51 1505
15:52 1504 | 15:53 1504 | 15:54 1484 | 15:55 1485 | 15:56 1756 | 15:57 1795 | 15:58 1602
15:59 1688 | 16:00 1685 | 16:01 1716 | 16:02 1866 | 16:03 1874 | 16:04 1818 | 16:05 1893
16:06 1916 | 16:07 1847 | 16:08 1923 | 16:09 1937 | 16:10 1815 | 16:11 1920 | 16:12 1910
16:13 1826 | 16:14 1940 | 16:15 1946 | 16:16 1889 | 16:17 1979 | 16:18 1972 | 16:19 1832
16:20 1962 | 16:21 1954 | 16:22 1891 | 16:23 1968 | 16:24 1974 | 16:25 1982 | 16:26 1898
16:27 2009 | 16:28 2009 | 16:29 1989 | 16:30 1967 | 16:31 1990 | 16:32 2022 | 16:33 2005
16:34 2004 | 16:35 2001

(The 15:56:30 Critical transition does not appear as a >1825 sample here — the controller observes on a finer cadence than the 60 s scrape, so the peak falls between samples. The transition counter confirms it: see below.)

kura_jemalloc_allocated_bytes / kura_jemalloc_resident_bytes, MB, 150 s:

time allocated resident
15:30 356
15:35 357
15:40 356
15:45 357 492
15:50 357 490
15:55 358 468
15:57 675 784
16:00 476 675
16:02 605 865
16:05 621 879
16:07 616 886
16:10 482 778
16:12 546 814
16:15 596 905
16:17 675 924
16:20 625 931
16:22 575 875
16:25 578 950
16:27 666 973
16:30 600 921
16:32 674 962
16:35 671 953

kura_jemalloc_retained_bytes, MB, 300 s:

15:30 1344 | 15:35 1413 | 15:40 1426 | 15:45 1445 | 15:50 1447 | 15:55 1468 | 16:00 1756
16:05 1719 | 16:10 1920 | 16:15 1902 | 16:20 2047 | 16:25 2073 | 16:30 2149 | 16:35 2117

kura_memory_pressure_state, 30 s (0 normal / 1 constrained / 2 critical):

15:4515:56:00 1
15:56:3015:57:30 2
15:58:0016:01:30 1
16:02:0016:35 2 (sustained)

kura_memory_pressure_transitions_total (cumulative): constrained→critical 1 → 2 (~15:56) → 3 (~16:02); critical→constrained 1 → 2 (~15:58); normal→constrained 1 for the pod’s whole life — it never returned to Normal.

kura_background_work_paused, 30 s: worker="outbox" and worker="usage_outbox" = 0 until 15:56:30, 1 for 15:56:30–15:57:30, 0 again, then 1 from 16:02:00 onward, continuously. worker="segment_refresh" = 1 for the entire window (it requires Normal).

kura_outbox_messages, 30 s — 0 for the whole day before 16:00:

15:40 0 | 15:50 0 | 16:00:00 0 | 16:00:30 3172 | 16:01:00 7282 | 16:01:30 14262
16:02:00 16408 | 16:02:30 17924 | 16:03:00 19502 | 16:03:30 6318 | 16:04:00 7833
16:04:30 6520 | 16:05:00 5325 | 16:05:30 4597 | 16:06:00 5168 | 16:06:30 5761
16:07:00 6909 | 16:07:30 7856 | 16:08:00 9213 | 16:08:30 10202 | 16:09:00 12376
16:09:30 14749 | 16:10:00 16780 | 16:10:30 34529 | 16:11:00 40160 | 16:11:30 45585
16:12:00 51701 | 16:12:30 55442 | 16:13:00 59104 | 16:13:30 62594 | 16:14:00 64140
16:14:30 65141 | 16:15:00 66933 | 16:15:30 69200 | 16:16:00 70283 | 16:16:30 71328
16:17:00 72814 | 16:17:30 75530 | 16:18:00 74654 | 16:18:30 77355 | 16:19:00 79790
16:19:30 82182 | 16:20:00 83855 | 16:20:30 86727 | 16:21:00 89212 | 16:21:30 92482
16:22:00 95046 | 16:22:30 95667 | 16:23:00 97318 | 16:23:30 98791 | 16:24:00 100921
16:24:30 103490 | 16:25:00 103576

Mesh-wide kura_outbox_messages at 16:20Z: kura-tuist-eu-central-1-0 913,842 (draining ~630 per 5 min) · kura-tuist-scw-fr-par-0 76,690 · kura-tuist-eu-central-1-1 83,855. Every other tenant’s pods are at 0.

increase(kura_artifact_writes_total[5m]) — the enqueue side:

14:0016:00 0 to 185 per 5 min (trickle)
16:00 15,054 | 16:05 11,571 | 16:10 23,269 | 16:15 13,161 | 16:20 14,123 | 16:25 4,903 | 16:30 1,038

increase(kura_replication_requests_total[5m]) — the drain side (sum over both targets, kura-tuist-eu-central-1-0 and kura-tuist-scw-fr-par-0, which track each other within 0.1 %):

14:0016:00 0 to 371 per 5 min
16:00 11,861 | 16:05 8,829 | 16:10 9,702 | 16:15 7,292 | 16:20 6,400 | 16:25 6,077 | 16:30 5,798

increase(kura_public_request_latency_seconds_count[10m]) by route — the 16:00 CI wave:

route 14:20 15:00 16:00 16:10 16:20 16:30
ActionCache/GetActionResult 861 914 45 3,447 3,584 5,666
ActionCache/UpdateActionResult 99 95 29 2,046 2,428 2,525
CAS/BatchReadBlobs 0 0 424 13,135 10,413 6,593
CAS/BatchUpdateBlobs 0 0 0 1,674 2,395 1,720
CAS/FindMissingBlobs 99 95 34 2,045 2,428 2,534

Other gauges at 16:20Z: rocksdb_block_cache_usage_bytes 77,123,338 (capacity 67,108,864; flat 48–77 MB all window) · manifest_cache_bytes 0 (capacity 67,108,864) · manifest_cache_evictions_total 1,810,967 · manifest_index_entries 0 · segment_evicted_artifacts_total 2,127,998 · replication_apply_results_total 8,324,429 · bootstrap_runs_total{result="ok"} 3 · bootstrap_duration_seconds_sum 53,909 s · membership_generation 3 · discovered_peer_nodes 2 · writer_lock_owned 1 · tmp_dir_bytes 912.

Loki queries used:

{env="production", namespace="kura", container="kura"} | pod="kura-tuist-eu-central-1-1" | json
| message=~"action-cache snapshot index reconciled|deleted action-cache entries whose blobs were evicted"
sum by (message) (count_over_time(
{env="production", namespace="kura", container="kura"}
| pod="kura-tuist-eu-central-1-1" | json | line_format "{{.message}}" [5m]))
Flights

Investigate, reproduce, or fix this item in an isolated repository. Each Flight preserves its outcome and agent session.

New Flights are paused Configure model inference, GitHub, and a sandbox provider to start another Flight. Existing results remain available below.
No Flights yet

Start a Flight and preserve its objective, outcome, and session here.

Comments

No GitHub comments yet.