Skip to content

feat(observability): add sync pressure and source-cost flame graphs - #2005

Open
Bojan131 wants to merge 6 commits into
feat/w1-sync-measurementfrom
codex/grafana-worker-queue-flamegraph-2003
Open

feat(observability): add sync pressure and source-cost flame graphs#2005
Bojan131 wants to merge 6 commits into
feat/w1-sync-measurementfrom
codex/grafana-worker-queue-flamegraph-2003

Conversation

@Bojan131

@Bojan131 Bojan131 commented Jul 31, 2026

Copy link
Copy Markdown
Contributor

Dependency

This PR is temporarily based on feat/w1-sync-measurement and depends on #2033. After #2033 merges, retarget this PR to testnet-canary; the resulting diff is only the observability extension.

What changed

Loki worker-pressure diagnostics

  • route PR feat(observability): unify scheduler backpressure diagnostics #2003 [backpressure] records through the daemon's structured logger so they reach the existing redacted Loki path
  • add a native Grafana flame graph split into active/admitted and queued/waiting branches, grouped by scheduler, lane, and operation source
  • bound all five instant flamegraph queries to a disclosed fixed one-hour snapshot so widening Grafana to 6h/24h cannot multiply Loki splits or queue time
  • keep separate active-pressure and queued-pressure age heatmaps on the full selected historical range, plus the raw Loki evidence panel
  • execute every generated flamegraph and heatmap query against pinned Loki 3.3.2 in CI, checking exact values/labels, slot movement, empty slots, and query resource statistics

W1 source-attributed sync cost

  • add a generated DKG Nodes — Sync Cost Grafana dashboard using feat(sync): W1 measurement contract — source-attributed sync instruments (I1–I9) #2033's I1–I9 OpenTelemetry instruments
  • expose source/lane/outcome filters and cover physical attempts, request/response bytes, active logical-operation occupancy, rejections, single-flight joins, catch-up requests/jobs, and catch-up duration
  • add a source → lane → outcome flame graph whose width is accumulated active wall-clock occupancy, not CPU time
  • add real Prometheus histogram heatmaps for logical-operation duration, scheduler queue wait, and catch-up job duration
  • render all six W1 evidence gates and the source-family materiality/share decision panels
  • generate a parser fixture directly from the dashboard query catalog and require pinned promtool CI to parse both the fixed W1 packet and every dashboard expression
  • unit-test the generated dashboard expressions against synthetic counters and histogram buckets, including request-only failure windows, so parseable but wrong calculations fail CI
  • assert two-series I5/I7/I8 fixtures that differ only by reason, include_shared_memory, or admission, preserving their exact grouping and rates
  • extend profile/semantic verification, the generator, runbook, and operator documentation

Why

The Loki views show where queue pressure accumulated from bounded transition/summary records without letting a long dashboard time range overload Loki. The fixed one-hour flamegraph is the recent pressure snapshot, while the heatmaps remain the selected-range historical view.

The new metrics dashboard complements that with #2033's source-attributed sync accounting, so operators can see what work was attempted, how much payload moved, how much active occupancy it consumed, and whether W1 has enough trustworthy evidence to draw a conclusion. A failed W1 gate is shown as inconclusive, not healthy; byte metrics are encoded application payload rather than wire bandwidth, and operations rejected before starting appear in I5 instead of receiving a fake zero-duration I4 sample.

Validation

  • complete workspace build: 22/22 build tasks plus node UI build passed
  • W1 packet verification: all 16 named suites resolve under their pinned configs
  • focused CLI logger-bridge test: 1/1 passed
  • focused core backpressure tests: 5/5 passed
  • generated artifact and clean-check mode verification passed
  • default and alternate node-label profile verification passed
  • W1 semantic verification passed: I1–I9, 66 decision rules, 106 selectors
  • pinned Loki 3.3.2 integration passed: all 5 flamegraph targets and both heatmaps returned exact scheduler/lane/phase/operation labels and expected values; empty slots were excluded
  • fixed-window Loki resource contract passed locally with 0 internal splits and 0.061s maximum queue time (CI ceiling: 0 splits and 2s)
  • the real-Loki test rejects the parseable missingAgeMs mutant with zero returned samples
  • dashboard PromQL result tests passed for flame widths, label grouping, worker-equivalent conversion, byte totals/rates, evidence gates, request-only failures, histogram buckets, catch-up p95, and exact I5/I7/I8 label grouping
  • removing reason, include_shared_memory, or admission from its respective grouping makes the matching test fail
  • workflow YAML/actionlint, generated artifact checks, and git diff --check passed

No scheduler admission policy, worker limit, queue behavior, or DKG runtime data path is changed by this PR.

Comment thread tools/observability/verify-profile-render.mjs
Comment thread tools/observability/lib/dashboards.mjs
Comment thread tools/observability/lib/queries.mjs
Comment thread tools/observability/lib/dashboards.mjs
Comment thread packages/cli/src/daemon/backpressure-log.ts
Comment thread packages/cli/src/daemon/lifecycle.ts
@Bojan131 Bojan131 changed the title feat(observability): add worker pressure flame graph feat(observability): add worker pressure flame graph and heatmaps Aug 3, 2026
@Bojan131 Bojan131 changed the title feat(observability): add worker pressure flame graph and heatmaps feat(observability): add sync pressure and source-cost flame graphs Aug 3, 2026
@Bojan131
Bojan131 changed the base branch from testnet-canary to feat/w1-sync-measurement August 3, 2026 09:29
Comment thread tools/observability/lib/dashboards.mjs
Comment thread tools/observability/lib/queries.mjs
Comment thread tools/observability/lib/w1.mjs
@Jurij89

Jurij89 commented Aug 3, 2026

Copy link
Copy Markdown
Contributor

PR #2005 observability merge-readiness review

PR: OriginTrail/dkg#2005
Reviewed head: a12ab44bd540573c8d929406ad802c217fd53c95
Reviewed base: 4ce70ec574a3f101c9dec2360beb869711432d6d (feat/w1-sync-measurement, the final W1 head)
Review comment: issuecomment-5165447730

Verdict

Not merge-ready: one introduced P1 remains. The worker-pressure flamegraph executes five instant Loki metric queries whose lookback is the entire Grafana-selected range. Against the repository's pinned Loki 3.3.2, one leaf query over only two representative log records expanded to 192 internal splits at 24 hours and reported 36–50 seconds of aggregate queue time. The panel repeats the expensive active and queued expressions three times each. That is an observability-induced backend load problem, and it directly contradicts this repository's runbook warning not to use long-range instant Loki metric queries.

The actual short-window LogQL semantics are correct: the real Loki parser extracted moved array slots, preserved scheduler/lane/phase/operation labels, and returned the expected peaks. The W1 PromQL groupings are also correct at the reviewed head. The remaining two findings are regression-test gaps, not current production defects.

Ground truth and scope

  • PR feat(observability): unify scheduler backpressure diagnostics #2003's merged backpressure producer is already an ancestor of this PR's base. W1 head 4ce70ec5… is the PR base. The authored delta is therefore exactly 4ce70ec5…a12ab44b, not base drift.
  • Authored delta: 16 files, +3243/-6. The load-bearing changes are the daemon structured-logger bridge, LogQL builders, Grafana panel models, W1 query model, generated dashboards/rule fixtures, and their CI verifiers.
  • GitHub reports head a12ab44b… mergeable/clean. The generated-artifact and SPARQL checks are green. CI green is not evidence against the P1 because CI never executes the LogQL against Loki.
  • The isolated review worktree was clean after all experiments. Every source/query mutation was reversed with an exact inverse edit and a zero body diff.

Findings

[P1 / blocking / introduced by PR #2005] Selected-range instant LogQL makes the dashboard a source of Loki pressure

The flamegraph uses $__range inside eight max_over_time branches per phase in queries.mjs, then evaluates the resulting expression as five instant targets in dashboards.mjs. Active and queued are each recomputed for the root, their parent, and their leaves.

flowchart LR
    R["Grafana selected range"] --> T["Five instant targets"]
    T --> A["Active expression evaluated three times"]
    T --> Q["Queued expression evaluated three times"]
    A --> AS["Eight fixed-slot max_over_time branches"]
    Q --> QS["Eight fixed-slot max_over_time branches"]
    AS --> L["Loki splits the long lookback"]
    QS --> L
Loading

This is the exact pattern the repository already warns about in RUNBOOK.md: long-range instant Loki metric queries are internally split and can reach the 500-series limit even at small stream counts.

I launched the repository's pinned grafana/loki:3.3.2, pushed two representative [backpressure] records, and ran the real exported query builder. The operation moved between slots across the two records, so this also exercised the slot/outer-max behavior rather than a toy single-slot case:

active-10m status=200 splits=0   queue=0.037s result=[catchup-foreground=2400,reconcile=1500]
queued-10m status=200 splits=0   queue=0.069s result=[on-connect=3400]
active-6h  status=200 splits=48  queue=2.267s result=[catchup-foreground=2400,reconcile=1500]
active-24h status=200 splits=192 queue=49.922s result=[catchup-foreground=2400,reconcile=1500]

A second cold-ish pass reported 36.54 seconds aggregate queue time for the same 24-hour query. These are Loki's aggregate query statistics, not claimed wall-clock latency; they demonstrate backend scheduling work. This was two log records and only one of the five Grafana targets.

Recommended fix direction: make the flamegraph lookback explicitly short and bounded—one hour is consistent with the dashboard default and the runbook—and state that fixed scope in the panel title/description. Keep the heatmaps as the selected-range historical view. I verified the literal query change: the same 24-hour dashboard context with a fixed [1h] instant lookback returned the same expected peaks with splits=0 and queue=0.023s.

If full selected-range flame widths are a hard requirement, treat that as a query/telemetry redesign and benchmark it at 6/24 hours before merging. Do not apply “change instant to range and add a reduce transform” literally as the whole fix. I tested that shape with one-minute windows over 24 hours; it still produced 25 splits and 11–19 seconds aggregate queue time for one phase, before accounting for the repeated hierarchy targets. It also changes the returned frame from one value per series to many time samples; without a correctly ordered per-series max reduction before seriesToRows, the current flame transform would emit duplicate rows or misleading widths.

Acceptance evidence should include the real Loki test described in the next finding, a 24-hour resource bound, and a rendered flamegraph check after any transform change.

[P2 / non-blocking test hardening / introduced by PR #2005] CI proves generated query text, not executable LogQL results

The current verifier checks target count, substrings, eight array indexes, and transform IDs. It never asks Loki to parse/evaluate the query or verifies returned labels and values. I changed only the generated query source from oldestAgeMs to a nonexistent missingAgeMs, regenerated the dashboards, and ran all current artifact verifiers:

check OK: all generated artifacts match the generator output
profile render verify OK
w1 render verify OK: instruments=9 rules=66 selectors=106

The real pinned Loki execution then returned:

active-10m status=200 result=[]
queued-10m status=200 result=[]

The mutant reached the actual exported query builder and the generated dashboard, but every current check accepted it. This is especially relevant because the P1 fix must modify the same query mode/window/transform contract.

Recommended fix direction: add a pinned Loki integration check to the observability workflow. Push two or three representative [backpressure] records that cover active and queued arrays, an operation moving between slots, and an empty slot. Evaluate the exported expressions and assert the exact scheduler/lane/phase/operation labels and peak values. Also exercise the chosen maximum supported range and fail on an excessive split/queue/resource bound.

A parser-only request is not enough: the missingAgeMs mutant is valid LogQL and returns HTTP 200; only result assertions expose it. Pin the container digest and retain the current fast structural verifier for inexpensive coverage.

[P2 / non-blocking test hardening / introduced by PR #2005] Three decision panels lack result-level grouping tests

The reviewed W1 dashboard queries correctly retain:

  • I5: lane, source, reason
  • I7: result, include_shared_memory
  • I8: status, admission

However, w1-dashboard-rules.test.yaml has no result assertion for those panel records. I mutation-tested all three:

drop I5 reason:                 current generator/verifiers/promtool tests PASS
drop I7 include_shared_memory: current generator/verifiers/promtool tests PASS
drop I8 admission:             current generator/verifiers/promtool tests PASS

Temporary result fixtures with two series differing only in the dropped label killed the mutants:

I5 expected reason={queue-full,timeout}; got one merged sample value=3
I7 expected include_shared_memory={true,false}; got one merged sample value=3
I8 expected admission={walk,synthetic}; got one merged sample value=3

Recommended fix direction: add those three two-series cases to the existing promtool dashboard-result fixture. Each pair must share all retained labels and differ only in the label being protected; otherwise dropping that label can still pass. This is small, local hardening and can land with the P1 fix, but the current production expressions are correct, so I would not block solely on it.

Load-bearing code reviewed with no current defect found

  • The daemon constructs BackpressureMonitor with createBackpressureLogEmitter(new Logger('backpressure'), createOperationContext('system')), installs the logger sink before backpressureMonitor.start(), and stops the monitor during shutdown. Logger resolves its static sink at emit time, so construction before sink installation is safe.
  • The log bridge preserves warn transitions/summaries and info recovery. Its focused test is meaningful: forcing all records through logger.info failed at the expected logger.warn assertion. The core monitor test likewise killed an all-info emitter mutant. Both mutants executed source, not stale dist, and both source bodies were restored cleanly.
  • The real Loki query returned the correct maximum when reconcile moved from array slot 0 to slot 1, confirming that the temporary slot label prevents or collision and the outer max removes the slot dimension.
  • W1 source/lane/outcome filters are applied only to interactive workload panels; fixed evidence/materiality gates retain the decision contract. Histogram heatmaps consume cumulative server-side buckets and use range queries.

Executed evidence at the restored head

The first dependency install and closure-build invocations exceeded their local command time caps without a compiler/test failure. Per the review rule, I did not trust those partial runs. Rerunning the same closure after dependencies were present completed cleanly:

pnpm install --frozen-lockfile                         exit 0
pnpm --filter "@origintrail-official/dkg..." build   17/55 selected packages, exit 0
generator --check                                     PASS
check-mode verifier                                   6/6 expected outcomes
default profile verifier                              PASS
alternate UID/node-label render + verifier            PASS
W1 render verifier                                    9 instruments, 66 rules, 106 selectors
promtool check rules                                  66 W1 rules + 32 dashboard rules, PASS
promtool dashboard result tests                       PASS
CLI backpressure bridge                               1/1 PASS
core backpressure producer/monitor                    5/5 PASS
git diff --check                                      PASS

Mutation evidence:

logger warn -> info mutant             1/1 test failed at logger.warn (reached src)
core emitter level -> info mutant      1/5 failed at expected warn (reached src)
LogQL age-field mutant                 all current artifact gates passed; real Loki returned []
I5/I7/I8 grouping mutants              current gates passed; targeted result assertions failed
restored worktree                      clean; no tracked body diff

Immediately before writing this review, GitHub and the isolated checkout both reported head a12ab44bd540573c8d929406ad802c217fd53c95; all current required checks were complete and green.

Merge readiness

Request one fix round. Bound or redesign the flamegraph query so a wider incident time range cannot multiply expensive instant Loki work, and prove the chosen shape against real Loki 3.3.2 at the maximum supported range. The real-LogQL result test should land with that fix because the current structural checks demonstrably accept an empty-result field mutation. The I5/I7/I8 promtool assertions are worthwhile low-cost hardening but are not independently blocking.

No finding above is inherited from W1 or PR #2003. The Loki long-range behavior is an existing backend constraint already documented by this repository; the incompatible unbounded instant-query use is introduced by PR #2005.

@Bojan131

Bojan131 commented Aug 3, 2026

Copy link
Copy Markdown
Contributor Author

@Jurij89 addressed all three findings in 62e2b1e3e:

  • The worker-pressure flamegraph now uses a fixed [1h] lookback in all five instant targets, and both the title and description disclose that scope. The two heatmaps remain range queries over the full Grafana-selected history.
  • CI now starts pinned Loki 3.3.2 by digest, pushes representative active/queued records, and evaluates all five generated flame targets plus both heatmaps. It checks moved slots, empty slots, exact scheduler/lane/phase/operation labels and values, and enforces splits=0 with aggregate queue time at most 2s. Local evidence was 0 splits and 0.061s maximum queue time; the parseable missingAgeMs mutant is rejected because it returns no samples.
  • The promtool result fixture now includes two-series I5/I7/I8 cases differing only by reason, include_shared_memory, and admission. Each exact grouping/rate is asserted, and removing any one of those labels makes its test fail.

The panel/runbook documentation and PR description were updated to explain the fixed-snapshot versus selected-history split. Fresh GitHub CI is green, including the new real-Loki step and all generated PromQL result tests: https://github.com/OriginTrail/dkg/actions/runs/30808581609

// with representative safe values. verify-profile-render.mjs independently
// performs the same substitution and compares the complete expression set,
// so this parser target cannot drift away from the dashboard it certifies.
const dashboardExprForPromtool = (expr) => expr

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🟡 Issue: Use one Grafana-macro substitution contract for rendering and verification

What's wrong
The renderer and verifier are supposed to prove exact expression parity, but the normalization step that defines parity is duplicated. That weakens the abstraction: future dashboard variables or macro changes become a two-file coordination task in the most contract-sensitive part of the observability generator.

Example
Adding a new dashboard variable such as ${sync_transport:regex} would require updating both functions. If only the renderer is updated, the verifier compares against a differently substituted expression set; if only the verifier is updated, the promtool fixture still carries an unparsable Grafana token.

Suggested direction
Centralize the substitution list instead of copying it into both the renderer and verifier. This keeps the promtool fixture relationship explicit without relying on parallel hand-maintained replacement chains.

For Agents
Move the Grafana-to-promtool substitution map/function into a shared observability helper used by renderDashboardRules and verify-profile-render.mjs. Preserve the exact current substitutions for node/source/lane/outcome/rate_interval/range, and keep the expression-set comparison proving fixture parity.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants