diff --git a/.agents/skills/mz-debug-replica-latency/SKILL.md b/.agents/skills/mz-debug-replica-latency/SKILL.md new file mode 100644 index 0000000000000..1a4546235babe --- /dev/null +++ b/.agents/skills/mz-debug-replica-latency/SKILL.md @@ -0,0 +1,175 @@ +--- +name: mz-debug-replica-latency +description: > + Triage a production Materialize replica that is stalling or running slow, + using Grafana (Prometheus) and PolarSignals. Trigger: a "persist ... heartbeat + call took Ns" or slow-consensus warning, "why is this replica slow", "persist + op taking seconds", "consensus/CRDB looks slow", "environmentd/clusterd + stalled", "reads timing out in prod", or a pasted prod log line plus Grafana + access. Reach for this whenever a single replica or environment shows + multi-second internal latency in production and you need to decide whether the + cause is the backing store, the process/runtime, shard contention, or memory + pressure, even if the user only pastes a log line and asks "what is this". +--- + +# Debugging production replica latency + +A single warning like `mz_persist_client::read reader (...) of shard (...) +heartbeat call took 60.6s` almost never means what it says on the surface. +The warning names a downstream symptom (a slow consensus/persist operation), +but the real cause is usually one layer down: the backing store, the process +runtime, shard contention, or local memory pressure. +This skill is the triage procedure to tell those apart with evidence, instead +of guessing from the log line. + +The core mental model: most of these "slow op" warnings time an `.await` on an +external call. That call can be slow because the store is genuinely slow, OR +because the local process is not polling the future (it is stalled off-CPU on +paging, blocked threads, or CPU starvation). The whole job here is to figure out +which, because the fixes are completely different. + +## What you need + +* Grafana MCP (Prometheus) access to the production metrics datasources. +* PolarSignals MCP access for CPU profiles (optional but useful). +* The identifying labels for the affected workload: namespace (the environment), + and pod (the specific replica or environmentd). A log line usually does not + carry these, so the user must supply them or you infer them from context. + +Do not hardcode datasource UIDs or environment identifiers. Discover them at +runtime, as below. Treat metric names as the stable contract, since UIDs and +label values drift. + +## Step 0: Locate the environment + +List Prometheus datasources (`list_datasources type=prometheus`). Production +regions follow a `cloud-production ` naming pattern, with separate +datasources per region. You do not know the region up front, so probe. + +Confirm the environment lives in a datasource before querying deeply. A cheap +existence check: + +```promql +count by (namespace) (mz_persist_external_started_count{namespace=""}) +``` + +Run it across the production datasources until one returns data. That datasource +is your environment's region. The infra metrics (`kube_*`, `container_*`, +cadvisor) live in the same datasource as the `mz_*` app metrics. + +NOTE: the pod label is `pod`. If a `pod=` filter returns empty but the namespace +has data, you probably have the wrong metric name, not the wrong label. Verify +the exact metric name with `list_prometheus_metric_names` before assuming the +label is wrong. Persist external-op metrics are `mz_persist_external_seconds`, +`mz_persist_external_started_count`, `mz_persist_external_succeeded_count` (note: +no `op` in the metric name; `op` is a label). + +## The decision tree + +Work top to bottom. Each step narrows the cause and tells you what to read next. + +1. **Is the slowness one replica, or the whole environment?** + Compare the suspect pod's external-op latency against its siblings on the + same backing store. Average op latency: + + ```promql + sum(rate(mz_persist_external_seconds{op="consensus_cas", namespace=""}[2m])) + by (pod) + / sum(rate(mz_persist_external_started_count{op="consensus_cas", namespace=""}[2m])) + by (pod) + ``` + + Or `topk(10, ...)` of the same. If every pod is elevated, suspect the backing + store (CRDB) or a shared dependency. If only one pod is elevated while others + sit at single-digit milliseconds, the store is healthy and the problem is + local to that replica. This single comparison eliminates half the hypotheses. + +2. **If isolated to one pod: are reads slow too, or only writes?** + Check a trivial read op: + + ```promql + rate(mz_persist_external_seconds{op="consensus_head", pod=""}[2m]) + / rate(mz_persist_external_started_count{op="consensus_head", pod=""}[2m]) + ``` + + `consensus_head` is a point read. If it averages multiple seconds, the store + cannot be the cause, because the same store serves other pods in microseconds. + Multi-second point reads mean the process is not polling its futures, i.e. the + runtime itself is stalled. Go to the memory-pressure and CPU-starvation + checks. If reads are fast but only writes (`consensus_cas`) are slow, suspect + shard contention (next step). + +3. **Is it shard contention (lost compare-and-set races)?** + A persist command that loses the CaS re-fetches state and retries with no + timeout, so heavy contention inflates wall-clock. + + ```promql + increase(mz_persist_cmd_cas_mismatch_count{pod=""}[4m]) + ``` + + This metric carries a `cmd` label, so you see which command is contending + (e.g. `downgrade_since`, `compare_and_append`). A large mismatch count on the + command named in the warning confirms a retry loop. Contention alone rarely + produces 60s stalls on its own. It usually compounds with a runtime stall: + each retry has to touch state that is slow to access. + +4. **Is the process stalled by memory pressure / swap?** + See `references/memory-pressure.md`. This is the most common root cause of an + isolated replica whose reads AND writes are all slow. + +5. **Is the process CPU-starved or throttled?** + See `references/cpu-and-runtime.md`. + +## Confirming off-CPU stalls with profiles + +When you suspect a runtime stall, a CPU profile is the tie-breaker. In +PolarSignals, list projects and pick the cloud project, then pull an on-CPU +flame graph or table for the pod and time window. + +The key inference: the production cloud project typically exposes ONLY an on-CPU +profile (`parca_agent:samples:count:cpu:nanoseconds:delta`), not an off-CPU / +wallclock profile. So you cannot directly profile a blocked thread. Instead, use +on-CPU as a process of elimination: if the relevant subsystem (e.g. persist) is +near-idle on-CPU during a window where its ops were taking seconds, the time was +spent OFF-CPU (blocked on IO, locks, or page faults), not computing. A near-idle +on-CPU profile during a stall is itself the evidence of a blocking, not +compute-bound, problem. + +Flame graphs for Rust binaries are huge. Filter the table by `filename` (e.g. +the crate name) and start with a tight `time_range` to avoid oversized results. + +## A telling corroboration: scrape blackouts + +When a process stalls hard (paging, blocked runtime), it stops serving its own +`/metrics` endpoint, and often the node's cadvisor loses the container too. In +the raw counter series you will see a gap: timestamps jump across the stall +window with no samples in between. If both the app `/metrics` series and the +node cadvisor series blank out over the same window, that is strong independent +evidence the whole process stalled, not that one dependency was slow. Always +look at raw counter series (not just `rate()`) around the incident, because +`rate()` over a gap can silently return empty or interpolate. + +## Metric cheat-sheet + +* `mz_persist_external_seconds{op,pod}` / `mz_persist_external_started_count{op,pod}` + — average external-op latency. Ops include `consensus_cas`, `consensus_head`, + `consensus_scan`, `consensus_truncate`, `blob_get`, `blob_set`, etc. +* `mz_persist_cmd_cas_mismatch_count{cmd,pod}` — CaS retry / contention per command. +* `mz_persist_cmd_seconds{cmd,pod}` — per-command time, to see which command dominates. +* `mz_metrics_libc_ru_majflt_total{pod}` — major page faults (swap-ins). See memory reference. +* `container_memory_rss`, `container_memory_swap`, `container_memory_working_set_bytes` + — memory footprint. See memory reference. +* `kube_pod_container_resource_limits{resource="memory"}` — the cgroup limit + (dedupe duplicate kube-state-metrics series with `max()`). +* `container_cpu_cfs_throttled_seconds_total`, `mz_metrics_libc_ru_nivcsw_total` + — CPU throttling / involuntary preemption. See CPU reference. + +## Writing it up + +These investigations usually end in a ticket to the team that owns the +subsystem. Lead with the conclusion (root cause), then the evidence chain in the +order that eliminates alternatives: scope (one pod vs fleet), then the +store-is-healthy proof (sibling latencies, fast point reads elsewhere), then the +local cause (memory/CPU), then how it ties back to the original warning. State +plainly that the warning was a symptom, not the cause, so the next responder +does not chase the wrong layer. diff --git a/.agents/skills/mz-debug-replica-latency/references/cpu-and-runtime.md b/.agents/skills/mz-debug-replica-latency/references/cpu-and-runtime.md new file mode 100644 index 0000000000000..fc2229feee7e4 --- /dev/null +++ b/.agents/skills/mz-debug-replica-latency/references/cpu-and-runtime.md @@ -0,0 +1,61 @@ +# CPU starvation and runtime stalls + +A replica can stall even with healthy memory if its threads cannot get CPU, or +if the async runtime is blocked. The symptom overlaps with memory pressure +(every `.await` looks slow), so use these checks to distinguish. + +## CPU throttling (cgroup CPU quota) + +If the container hits its CPU limit, the kernel throttles it: runnable threads +are forcibly descheduled until the next quota period. Heavy throttling stalls +everything, including the futures running persist ops. + +```promql +rate(container_cpu_cfs_throttled_seconds_total{pod=""}[1m]) +rate(container_cpu_cfs_throttled_periods_total{pod=""}[1m]) +/ rate(container_cpu_cfs_periods_total{pod=""}[1m]) +``` + +The second expression is the fraction of scheduling periods that were throttled. +Sustained high values mean the container is CPU-starved by its own quota. + +Involuntary context switches corroborate CPU contention at the process level: + +```promql +rate(mz_metrics_libc_ru_nivcsw_total{pod=""}[1m]) +``` + +A spike in involuntary switches means the scheduler is preempting the process +against its will, i.e. it wants CPU it cannot get. Voluntary switches +(`ru_nvcsw_total`) are the opposite, the process yielding (often blocking on +IO), which points back toward the memory/IO story. + +## Async runtime blocked by synchronous work + +A subtler cause: a blocking operation on a Tokio worker thread (a blocking +syscall, a long synchronous compute section, a contended std mutex held across +work) starves the runtime. Other tasks on that worker, including persist +heartbeats and consensus client futures, cannot make progress until it returns. + +Signals: + +* On-CPU profile shows a single subsystem dominating CPU for the whole window + (real compute), while the stalled subsystem is absent. This differs from the + memory-pressure case, where the on-CPU profile is near-idle overall because + threads are off-CPU on page faults. +* No CPU throttling and no major-fault spike, yet ops are slow: look for a + blocking section in the hot path on-CPU. + +## Distinguishing the three runtime-stall causes + +* Memory/swap: on-CPU near-idle, `ru_majflt` spiking, mem+swap over limit. +* CPU throttle: `cfs_throttled` high, `ru_nivcsw` spiking, on-CPU may be busy. +* Blocking work on runtime: on-CPU shows one subsystem burning CPU, no throttle, + no fault spike. + +## Fixes to recommend + +* Throttling: raise the CPU limit, or reduce concurrent work on the replica. +* Blocking-on-runtime: move the offending work to a blocking thread pool + (`spawn_blocking`), shorten the synchronous section, or remove the lock held + across the await. Identify the exact frame from the on-CPU profile first. diff --git a/.agents/skills/mz-debug-replica-latency/references/memory-pressure.md b/.agents/skills/mz-debug-replica-latency/references/memory-pressure.md new file mode 100644 index 0000000000000..9d2a53acaa678 --- /dev/null +++ b/.agents/skills/mz-debug-replica-latency/references/memory-pressure.md @@ -0,0 +1,72 @@ +# Memory pressure and swap thrashing + +This is the most common root cause of a single replica whose persist reads and +writes are all slow while sibling replicas on the same backing store are fine. +The mechanism: the process working set exceeds physical RAM, the kernel pages +cold memory out to swap, and every later access to a swapped-out page is a major +page fault, a synchronous disk read that blocks the faulting thread. Under heavy +thrashing the runtime spends most of its wall-clock blocked on page-ins, so +every `.await` on an external call appears slow even though the store responded +instantly. + +Production replicas may run on swap-enabled nodes (a dedicated nodepool, local +NVMe used as swap). Swap is meant as a soft cushion for transient spikes, not as +a place to hold a multiple of RAM resident. Sustained heavy swap is the incident. + +## The decisive signal: major page faults + +```promql +rate(mz_metrics_libc_ru_majflt_total{pod=""}[1m]) +``` + +This is the process's own getrusage major-fault counter. Sustained rates on the +order of tens to hundreds of thousands per second mean the process is thrashing: +threads are continuously blocking on swap-in. Correlate the rate against the +incident window. It typically peaks during the stall and decays afterward, +matching when the slow operation finally completed. + +NOTE: this metric is served on the same `/metrics` endpoint that blanks out +during a hard stall, so `rate()` over the exact gap can return empty. Query the +raw counter (`mz_metrics_libc_ru_majflt_total{pod=""}` as a range) and +compute deltas across the surrounding samples by hand. The jump across the gap +is what you want. + +Sibling rusage metrics that corroborate: `mz_metrics_libc_ru_minflt_total` +(minor faults), `mz_metrics_libc_ru_nivcsw_total` (involuntary context switches, +also a CPU-pressure signal), `mz_metrics_libc_ru_maxrss_bytes`. + +## Quantify the footprint + +```promql +container_memory_rss{pod="", container=""} +container_memory_swap{pod="", container=""} +max(kube_pod_container_resource_limits{pod="", resource="memory"}) +``` + +* `container_memory_rss` near the cgroup memory limit means the container is + pinned at its RAM ceiling. +* `container_memory_swap` is the cgroup memory+swap total. When it greatly + exceeds the RAM limit (and physical node RAM), the difference is resident in + swap. Hundreds of GB in swap is unambiguous thrashing. +* Use `max()` on the limit metric. kube-state-metrics often exposes duplicate + series (multiple scrape endpoints), which makes a bare `/` join fail with a + many-to-many error. + +## What it looks like together + +* One replica's external ops all in seconds, including trivial point reads. +* Sibling replicas on the same store at milliseconds. +* `ru_majflt` rate spiking into the tens or hundreds of thousands per second. +* mem+swap far above the RAM limit. +* App `/metrics` and node cadvisor scrapes blanking out over the stall window. +* On-CPU profile near-idle for the stalled subsystem (time spent off-CPU). + +## Fixes to recommend + +* Relieve memory: size the replica up, or reduce the dataflow working set, so it + fits in RAM with swap as headroom rather than primary storage. +* Alert on `rate(mz_metrics_libc_ru_majflt_total)` and `container_memory_swap` + for swap-enabled replicas. A single downstream warning understates how long + the replica was actually thrashing. +* Frame the original "slow op" warning as a symptom so responders fix memory, + not the persist/consensus layer.