Skip to content

fix(ingest): discover Dynamo's rotated request-trace shards and read them as one stream - #416

Closed
nv-yna wants to merge 1 commit into
NVIDIA:mainfrom
nv-yna:yna/ingest-request-trace-shards
Closed

nv-yna wants to merge 1 commit into
NVIDIA:mainfrom
nv-yna:yna/ingest-request-trace-shards

Conversation

@nv-yna

@nv-yna nv-yna commented Sep 10, 2026

Copy link
Copy Markdown
Collaborator

What

The request-trace axis of the ingest never found its input on real runs. Dynamo's request-trace sink is a rotating gzip JSONL appender: with DYN_REQUEST_TRACE_FILE_PATH=<log_dir>/dynamo-request-trace (what observability.enabled sets via ANALYTICS_REQUEST_TRACE_ENV) it writes dynamo-request-trace.000000.jsonl.gz, .000001.jsonl.gz, ... and never a bare dynamo-request-trace file. run_request_trace looked only for the bare name.

  • ingest.run_request_trace: default discovery is now the bare file plus dynamo-request-trace.*.jsonl* (gz or not, REQUEST_TRACE_DEFAULT_PATTERNS); every match is handed to the processor. --request-trace-input still overrides.
  • request_trace.process accepts a path or a list of shard paths, opens .gz transparently (errors="replace", so a torn last line in the shard being written when the frontend was killed is skipped, not fatal) and merges the shards before the existing received_ms sort. The CLI takes IN_PATH... OUT_PATH.
  • docs/component-dashboard.md names the real input files.

Evidence

hecate 565811 (2026-09-09, AgentX baseline recipe, observability.enabled: true, 8 VR200 nodes). The log dir holds 12 shards and no bare file:

129532417 dynamo-request-trace.000000.jsonl.gz
127623635 dynamo-request-trace.000001.jsonl.gz
...
127810520 dynamo-request-trace.000010.jsonl.gz
 55345872 dynamo-request-trace.000011.jsonl.gz

(zcat dynamo-request-trace.000000.jsonl.gz | wc -l → 10,983 records; first record is a dynamo.request.trace.v1 / request_end event with session_id, x_request_id, kv_transfer_estimated_latency_ms, ...)

and the sweep log:

21:22:53 INFO [L2 req-trace] WARN no request trace matched 'dynamo-request-trace' under /lustre/.../565811/logs; skipping
21:37:57 INFO [done] bundle ready in 1318.2s: aiperf=True traces=True metrics=True request_trace=False

The same request_trace=False appears on 565810 and 565854 (default visibility, no trace written — correct there). Only the observability run lost data.

Validation

  • pytest tests/test_request_trace.py → 9 passed: shard merge order across shards, plain file, torn last line, CLI with several inputs, discovery (rotated / bare / uncompressed shard / unrelated dynamo-request-trace.lock ignored), explicit glob precedence over discovery, skip path logs the WARN, --request-trace none.
  • src/ingest/ingest.py and src/ingest/request_trace.py were already ruff format-dirty on main (checked with git show HEAD:<file> | ruff format --check --stdin-filename), so this diff does not reformat them; the new test file is clean.
  • A run of the processor on one real shard of 565811 is in progress; will attach rows/time as a comment.

Why draft

Scaling caveat worth a reviewer's opinion: process() keeps every request's input_sequence_hashes in memory until the end to compute prefix_reuse_ratio (by design, see the module docstring). Now that the shards are actually read, an hour of AgentX at 8 nodes is ~140k requests × ~1.2k hashes — several GB on the postprocess node. This PR does not change that; if it is a problem in practice the hashes could be reduced per session incrementally instead of held globally.

🤖 Generated with Claude Code

…them as one stream

Dynamo's request-trace sink is a rotating gzip JSONL appender. With
DYN_REQUEST_TRACE_FILE_PATH=<log_dir>/dynamo-request-trace (what
observability.enabled sets) it writes dynamo-request-trace.000000.jsonl.gz,
.000001.jsonl.gz, ... and never a bare `dynamo-request-trace` file. The
ingest looked only for the bare name, so on every observability run the
axis was silently empty: hecate 565811 (2026-09-09) left 12 shards of
~128 MB / ~11k requests each on disk and the sweep log said

  [L2 req-trace] WARN no request trace matched 'dynamo-request-trace' under ...
  [done] bundle ready ...: request_trace=False

- ingest.run_request_trace: default discovery is the bare file plus
  `dynamo-request-trace.*.jsonl*` (gz or not); every match is handed to
  the processor. --request-trace-input still overrides.
- request_trace.process accepts a path or a list of shard paths, opens
  .gz transparently (errors="replace" so a torn last line in the shard
  being written at kill time is skipped, not fatal), and merges shards
  before the existing received_ms sort. The CLI takes IN_PATH... OUT_PATH.
- docs/component-dashboard.md names the real input files.
- tests/test_request_trace.py: shard merge order, plain file, torn line,
  CLI, discovery (rotated / bare / uncompressed / unrelated-prefix files),
  explicit glob precedence, skip path, disabled axis.

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
Signed-off-by: Yuewei Na <nv-yna@users.noreply.github.com>
@nv-yna

nv-yna commented Sep 10, 2026

Copy link
Copy Markdown
Collaborator Author

Validation on the real capture (hecate, checkout of main e60c64a + this commit applied with git am)

Discovery with the new default patterns over the three run directories from 2026-09-09:

565810 0 file(s)                       # default visibility: no trace written, correctly skipped
565811 12 file(s): dynamo-request-trace.000000.jsonl.gz .. dynamo-request-trace.000011.jsonl.gz
565854 0 file(s)

Processor on one shard of 565811 (login node, nice, /usr/bin/time -v):

$ python -m src.ingest.request_trace dynamo-request-trace.000000.jsonl.gz out.jsonl
22:22:06 INFO request_trace -> out.jsonl: 10983 rows from 1 file(s), 2993 sessions, 7990 turns with prefix reuse
	Elapsed (wall clock) time: 0:07.63
	Maximum resident set size (kbytes): 720056
	Exit status: 0

First output row (fields as emitted): prefill_ms 6935.4, kv_transfer_ms 6710.3, ttft_prefill_ms 6974.2, total_ms 13705.9 on a 39,795-token input — the KV-transfer band the request trace exists to expose.

Scaling note from the same numbers: 720 MB peak for one shard of ~11k requests is dominated by the held input_sequence_hashes; the full 12-shard capture (~130k requests) extrapolates to several GB on the postprocess node. I did not run the 12-shard ingest on the login node for that reason; that is the "why draft" item in the description.

@codecov-commenter

Copy link
Copy Markdown

Codecov Report

✅ All modified and coverable lines are covered by tests.
⚠️ Please upload report for BASE (main@d0529aa). Learn more about missing BASE report.

Additional details and impacted files
@@           Coverage Diff           @@
##             main     #416   +/-   ##
=======================================
  Coverage        ?   73.85%           
=======================================
  Files           ?      101           
  Lines           ?    14110           
  Branches        ?        0           
=======================================
  Hits            ?    10421           
  Misses          ?     3689           
  Partials        ?        0           

☔ View full report in Codecov by Harness.
📢 Have feedback on the report? Share it here.

🚀 New features to boost your workflow:
  • ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.
  • 📦 JS Bundle Analysis: Save yourself from yourself by tracking and limiting bundle sizes in JS merges.

@nv-yna

nv-yna commented Sep 10, 2026

Copy link
Copy Markdown
Collaborator Author

Full-scale validation inside a real postprocess (hecate 567531, observability.enabled: true, 8 VR200 nodes, 2026-09-10)

The run's checkout carried this commit (applied with git am on main e60c64a). Dynamo wrote 13 rotated shards (dynamo-request-trace.000000.jsonl.gz.000012.jsonl.gz, ~128 MB each). The in-job ingest on the compute node found and merged them:

03:52:43 INFO [L2 req-trace] dynamo -> request_trace.jsonl: 152780 requests from 13 file(s)
04:08:34 INFO [done] bundle ready in 1745.4s: aiperf=True traces=True metrics=True request_trace=True

request_trace=True for the first time on an observability run (the identical run on unpatched main, 565811 the day before, logged WARN no request trace matched 'dynamo-request-trace' and request_trace=False with 12 shards on disk). The dashboard rendered in-job; total job wall time 2:24:03 under a 2:45 limit. Ingest took 29 minutes on this run (vs 8–17 min on default-visibility runs), so the "several GB for the hash arrays" caveat is a wall-time cost too — fine on a Vera compute node, not something to run on a login node.

@nv-yna nv-yna closed this Sep 12, 2026
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.

2 participants