Skip to content

feat(trace): thread names + opt-in per-pack stage tracing (stacked on #10) - #11

Draft
dougnukem wants to merge 5 commits into
bench/codec-io-decompositionfrom
bench/pack-trace
Draft

dougnukem wants to merge 5 commits into
bench/codec-io-decompositionfrom
bench/pack-trace

Conversation

@dougnukem

@dougnukem dougnukem commented Sep 29, 2026 •

Copy link
Copy Markdown
Owner

Stacked on #10. Measures stage costs inside one run, pack by pack: which thread is the critical path, and what each stage costs per read. This is the "trace build" #9 lists as a next step.

Source changes:

  • Thread names, always on: fp-read-L/R, fp-read, fp-read-I, fp-work-N, fp-bgzf, fp-bgzf-io, fp-write. perf --sort comm, top -H, pidstat and gdb then attribute CPU per stage.
  • make TRACE=1 builds ./fastp-trace from its own obj-trace/, so normal and trace objects never mix. It uses per-thread lock-free span buffers written as TSV at exit to $FASTP_TRACE_FILE. Without it the macros compile to nothing.

Analysis:

  • scripts/trace_analyze.py: exclusive time per role, per-read CPU per stage, busy/wait timeline, pack backlog, and a bottleneck verdict. The window starts at the first reader pack, and detection-phase spans are reported separately.
  • scripts/trace_run.sh: runs over datasets × -w × input kind and records trace overhead.

Checked:

  • Outputs are byte-identical to the normal build, and fastp test passes.
  • Header builds warning-free with -std=c++11 -Wall -Wextra, with and without -DFASTP_TRACE.
  • Trace overhead on full-size data is within run-to-run noise (−3% to +5%).

Results (16 traced cells; benchmark/trace.md and benchmark/results/trace-2026-09/):

  • With ordinary gzip input, 6 of 8 cells are reader-bound. The reader is 87–96% busy while workers wait. The reader's cost is parsing into Read objects (670–1100 ns/read), 3–5× the ISA-L inflate.
  • At -w 48 every stage is 15–40% slower per read; the serial reader shares a physical core with a worker.
  • Per-read work is ~65–80 ns per base, SE and PE alike. perf on workers: Matcher::matchWithOneInsertion 33%, trimBySequence 36% inclusive, compression ~20%, statRead 11%.
  • Bug found upstream: trimBySequence's one-gap loops never offset rdata by pos (since eb461d5, v0.26.0), so indel-tolerant adapter matching only tests position 0. With + pos, 2M-read runs trim 0.5–0.7% more reads, and the fix costs +28–42% CPU, so it needs a faster search alongside it. Not filed upstream yet.

Self-review fixes already in: separate trace build target, exit-dump race on error_exit(), and detection-phase BGZF-pool spans excluded from the window.

Remaining

  • Upstream: the thread-naming part could go as its own tiny PR; the gap-search bug as an issue plus a fix with a faster search.

🤖 Generated with Claude Code

Threads are named by role (fp-read-L/R, fp-work-N, fp-bgzf, fp-write, ...) so
top -H, pidstat, perf and gdb attribute CPU to pipeline stages.

`make TRACE=1` records timed spans per thread (read_pack, decompress,
bgzf_block, process, compress, offset_wait, write, and reader/worker waits)
into lock-free per-thread buffers, written as TSV at exit to
$FASTP_TRACE_FILE. Without TRACE=1 the macros compile to nothing.

benchmark/scripts/trace_analyze.py reports exclusive time per role, per-read
CPU cost per stage, a busy/wait timeline, pack backlog and a bottleneck
verdict; trace_run.sh runs it over datasets and thread counts and records
trace overhead.

Outputs are byte-identical to the normal build; `fastp test` passes; overhead
was not measurable (median 3.82 s vs 3.83 s, 5 alternating runs).

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
- make TRACE=1 now builds ./fastp-trace from obj-trace/: -DFASTP_TRACE changes
  no timestamps, so switching builds in one tree silently kept the other
  build's objects (or mixed both).
- The exit dump sets an atomic flag that stops further recording and writes a
  size snapshot of each buffer, so error_exit() from a worker while others
  still run no longer iterates vectors being appended to.
- trace_analyze.py starts the window at the first reader pack and reports
  earlier spans separately: for BGZF input the evaluator starts its own
  fp-bgzf pool during detection, which stretched the window and inflated
  BGZF per-read cost.
- trace_run.sh accepts "default" (no -w).

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
…rch bug

16 traced cells: reader-bound in 6 of 8 gz cells, reader cost is parsing (3-5x
inflate), every stage slower per read at -w 48 (24 cores x 2 SMT). perf on
workers: matchWithOneInsertion 33%, trimBySequence 36% inclusive.
trimBySequence's one-gap loops never offset by pos (since eb461d5, v0.26.0):
fixing it trims +0.5-0.7% more reads and costs +28-42% CPU.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

This branch has not been deployed

No deployments
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