Skip to content

perf(train): render console logs off the training thread - #1297

Draft
orestis-z wants to merge 4 commits into
perf/fused-kl-single-passfrom
perf/log-off-training-thread
Draft

orestis-z wants to merge 4 commits into
perf/fused-kl-single-passfrom
perf/log-off-training-thread

Conversation

@orestis-z

@orestis-z orestis-z commented Oct 21, 2026 •

Copy link
Copy Markdown
Collaborator

Purpose

The root logger's RichHandler formats and writes synchronously inside whatever thread logged. With the default log_freq of 1 that lands in every training step: flattening the metric dict, formatting ~20 values, and rendering rich markup costs milliseconds, and the GIL it holds while doing so delays the next step's first CUDA call. This puts a QueueHandler on the root and runs the RichHandler from a QueueListener thread, so the step pays an enqueue and the rendering happens while the device is busy.

QueueHandler.prepare renders the message to a string before enqueuing, which would hand FormatDictFilter a str and print a bare dict repr instead of the train/k=v form downstream tooling greps. _SnapshotQueueHandler instead flattens mapping messages into a fresh dict, which also freezes the values at log time so a caller that reuses its metrics dict cannot have later values printed against an earlier step. The listener only starts when the root has no handlers yet — the case where basicConfig would otherwise be a no-op, leaving a listener thread with nothing feeding it — and is stopped at exit so queued records still reach the console.

Measured

Single H100, eagle3, synthetic batches, full 151936-token vocab, total_seq_len 2048, 10 warmup + 50 measured steps, 3 reps, median of the per-run means, log_freq=1, scripts/benchmark.py. This PR against #1296:

Qwen3-0.6B Qwen3-1.7B Qwen3-8B Qwen3-32B
1.029x 1.042x 1.015x 1.006x

A local wall-clock harness that drives the same trainer with the step timer's torch.accelerator.synchronize() patched out — so the device is free to run ahead of the host — reports the opposite sign, 0.990x at 2048 and 0.987x at 4096 on Qwen3-0.6B. Read together: a 1–4% win when the host is on the critical path, a wash when it is not. The benchmark's console is a fast local pipe, so most of what is measured here is the GIL the rendering holds rather than the write itself; whether it is worth more when logs go somewhere slower is untested.

It touches only train/logger.py, so it stands or falls on its own.

Tests

pytest tests/unit/train/test_logger.py

New cases cover that records reach the handler through the listener, that mapping messages still format as train/k=v, that the values are snapshotted at log time, that nothing is installed when the root already has handlers, and that the listener is stopped at exit. Passes.

Checklist

I have filled in:

  • The purpose of the PR, such as "Fix some issue (link existing issues this PR will resolve)".
  • The test plan/results, such as providing test command and pasting the results.
  • (Optional) The necessary documentation update.
  • I (a human) have written or reviewed the code in this pr to the best of my ability.

🤖 Generated with Claude Code

@coderabbitai

coderabbitai Bot commented Oct 21, 2026

Copy link
Copy Markdown
Contributor

Important

Draft PR not reviewed

Draft PRs are not automatically reviewed by default.

  • Trigger a manual review

To automatically review draft PRs, update your CodeRabbit configuration:

reviews:
  auto_review:
    drafts: true
  • Autofix · Keep fixing CodeRabbit findings and required CI, and resolving merge conflicts

Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out.

❤️ Share

Comment @coderabbitai help to get the list of available commands.

@orestis-z
orestis-z added this pull request to stack #1302 October 21, 2026 17:19
@mergify

mergify Bot commented Oct 21, 2026

Copy link
Copy Markdown
Contributor

Merge Protections

🔴 1 of 1 protections blocking · waiting on 👀 reviews

Protection Waiting on
🔴 Require approval from approved reviewers list 👀 reviews

🔴 Require approval from approved reviewers list

Waiting for any of

  • approved-reviews-by = dsikka
  • approved-reviews-by = fynnsu
  • approved-reviews-by = orestis-z
  • approved-reviews-by = rahul-tuli
  • approved-reviews-by = shanjiaz
This rule is failing.

All pull requests must have at least one approving review from a member of the approved reviewers list before merging.

  • any of:
    • approved-reviews-by = dsikka
    • approved-reviews-by = fynnsu
    • approved-reviews-by = orestis-z
    • approved-reviews-by = rahul-tuli
    • approved-reviews-by = shanjiaz

orestis-z and others added 4 commits October 22, 2026 16:34
Every training step built a handful of metric scalars with
``torch.tensor(<python scalar>, device=cuda)``. That is a copy from
pageable host memory, so it cannot be issued asynchronously -- the
caller blocks until the work already queued on the device drains. The
same step also ran ``torch.masked_select`` on the accuracy mask, whose
output size depends on the mask's values, forcing another device->host
sync before the count could be read.

Build those scalars with ``torch.full``/``torch.zeros``/``torch.ones``,
which fill on the device, and count masked positions with a reduction
over the mask instead of selecting it. The numbers are identical; the
step no longer waits on the device to produce them.

``full_total`` and ``cond_total`` stay separate tensors so a caller
reducing the metrics dict in place cannot count one of them twice.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Signed-off-by: Orestis Zambounis <orestis.zambounis@gmail.com>
Each TTT step took three argmax passes over a
``[total_seq_len, draft_vocab_size]`` tensor: one over the draft logits
for the accuracy metrics, one over the targets for the same, and one
over the draft logits again to pick the next step's input ids. At a
~32k draft vocab that is three full streams of a tensor that does not
fit in cache, for two distinct results.

Take the draft argmax once, before the metrics, and hand it to
``compute_metrics``. The targets do not change across TTT steps, so
their argmax moves out of the loop entirely and is computed once per
forward.

``compute_metrics`` takes the ids unaligned and applies the same
slicing ``align_for_step`` applies to the tensors they came from, so
the reported per-step accuracies are unchanged.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Signed-off-by: Orestis Zambounis <orestis.zambounis@gmail.com>
The fused forward read each ``[1, vocab]`` row three times: once for the
draft's online softmax stats, once for the target's, and once more to
accumulate the divergence now that both log-sum-exps were known. At
Qwen3's 151936-wide vocab the row does not fit in cache, so the kernel
is bandwidth-bound and pays for all three streams.

Neither direction needs more than one. Because the probabilities sum to
one, each reduces to a single cross term over an online-normalized
exponential:

    KL(tp || dp)  = s / z_t + lse_d - lse_t,  s = sum e^(y-m_t)(y-x)
    RKL(tp || dp) = s / z_d + lse_t - lse_d,  s = sum e^(x-m_d)(x-y)

and ``s`` rescales by ``exp(m_old - m_new)`` exactly as the sum-exp
``z`` does, so it accumulates alongside the two online softmaxes without
needing either log-sum-exp up front. jsd and tv keep the multi-pass
structure: their per-element terms depend on both final normalizers.

The stats rows the backward reads are unchanged, so the gradient path is
untouched. The now-unreachable kl/rkl arms are dropped from the joint
jsd/tv loop.

The reassociated summation reorders floating-point adds, so the loss
moves within fp32 rounding. The existing fused-vs-eager test covers the
saturated point-mass and 151936-vocab regimes; a new case pins the
rescale by putting a maximum in the final block, for both directions.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Signed-off-by: Orestis Zambounis <orestis.zambounis@gmail.com>
The root logger's RichHandler formats and writes synchronously inside
whatever thread logged. With the default ``log_freq`` of 1 that lands in
every training step: flattening the metric dict, formatting ~20 values,
and rendering rich markup to a pipe costs milliseconds, and the GIL it
holds while doing so delays the next step's first CUDA call on top of
that.

Put a QueueHandler on the root and run the RichHandler from a
QueueListener thread. The step now pays an enqueue; the rendering
happens while the device is busy.

``QueueHandler.prepare`` renders the message to a string before
enqueuing, which would hand FormatDictFilter a str and print a bare
dict repr instead of the ``train/k=v`` form downstream tooling greps.
``_SnapshotQueueHandler`` instead flattens mapping messages into a
fresh dict, which also freezes the values at log time so a caller that
reuses its metrics dict cannot have later values printed against an
earlier step.

The listener only starts when the root has no handlers yet -- the case
where ``basicConfig`` would otherwise be a no-op, leaving a listener
thread with nothing feeding it -- and is stopped at exit so queued
records still reach the console.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Signed-off-by: Orestis Zambounis <orestis.zambounis@gmail.com>
@orestis-z
orestis-z force-pushed the perf/log-off-training-thread branch from a910c0e to b10a393 Compare October 22, 2026 14:34
orestis-z added a commit that referenced this pull request Oct 27, 2026
<!-- markdownlint-disable -->

## Purpose

Split out of the measurements in #1259 / #1262 / #1263, one change per
PR.

Every training step built its metric scalars with `torch.tensor(<python
float>, device=cuda)`, which copies from pageable host memory and so
cannot be issued asynchronously — the host blocks until the work already
queued on the device drains. The same step ran `torch.masked_select` on
the accuracy mask, whose output size depends on the mask's values,
forcing another device-to-host sync before the count could be read.
Building those scalars with `torch.full`/`torch.zeros`/`torch.ones` and
counting masked positions with a reduction gives identical numbers
without either sync.

`full_total` and `cond_total` stay separate tensors so a caller reducing
the metrics dict in place cannot count one of them twice.

### Measured

Single H100, eagle3, synthetic batches, full 151936-token vocab,
`total_seq_len` 2048, 10 warmup + 50 measured steps, 3 reps, median of
the per-run means, `log_freq=1` (the default), `scripts/benchmark.py`.
This PR against main:

| Qwen3-0.6B | Qwen3-1.7B | Qwen3-8B | Qwen3-32B |
|---|---|---|---|
| **1.111x** | **1.110x** | **1.030x** | **1.013x** |

<details>
<summary>Where the gain comes from, change by change</summary>

Same harness and settings, each change measured against its parent
commit, so every cell is one PR's marginal contribution at that verifier
size. Run-to-run spread within a cell is under 1% everywhere except main
at 0.6B.

| PR | | Qwen3-0.6B | Qwen3-1.7B | Qwen3-8B | Qwen3-32B |
|---|---|---|---|---|---|
| #1294 | metrics off host | **1.111x** | **1.110x** | **1.030x** |
**1.013x** |
| #1295 | reuse the argmax | **1.076x** | **1.026x** | **1.013x** |
1.007x |
| #1296 | single-pass fused KL | **1.047x** | **1.017x** | **1.012x** |
1.003x |
| #1297 | logs off the thread | **1.029x** | **1.042x** | **1.015x** |
1.006x |
| #1298 | one metric readback | 0.980x | 1.004x | 0.997x | 0.999x |
| #1299 | H2D prefetch † | 1.024x | 1.013x | 1.029x | 1.021x |
| #1300 | skip dropped positions | 0.997x | 0.988x | 0.980x | 0.988x |
| #1301 | precast frozen heads | **1.055x** | **1.096x** | **1.059x** |
**1.036x** |
| | **cumulative** | **1.358x** | **1.329x** | **1.141x** | **1.077x** |

† #1299's row is not the prefetch. That commit also pins the synthetic
batch in `scripts/benchmark.py`, and the real `DataLoader` already sets
`pin_memory=True`, so it is a benchmark-fidelity fix rather than a
training speedup. Applying only the pinning hunk on top of #1298 gives
1.017x / 1.017x / 1.030x / 1.022x — the whole row. Discounting it, the
cumulative row is **1.335x / 1.307x / 1.108x / 1.054x**.

Reading it:

- **#1294 and #1301 carry most of the gain.** They are the two largest
at every size, and #1301 is the only one that also moves peak memory
(−1.5 GB at 0.6B to −7.4 GB at 32B).
- **#1295, #1296 and #1297 fade with verifier size** but stay positive —
1–2% at 8B, 0.3–0.7% at 32B.
- **#1298 is a tie at every size.** One sync per step instead of a few
dozen is the right shape, but it does not show up here.
- **#1299's prefetch is inside noise** in this regime once the harness
fix is separated out, though it does pay once the metric log emit is
deferred — see #1299.
- **#1300 is negative at `seq_len` 2048 at every size** and costs
0.3–1.5 GB of peak; it needs both long sequences and a small hidden size
to pay.

Only #1300 and #1301 change peak allocated memory at all; the other six
are flat to the megabyte.

Most of these changes remove fixed per-step host and metric overhead, so
the relative win shrinks as the verifier grows even though the absolute
saving does not. At 8B and 32B the step is dominated by the optimizer
(42% and 58%, all Muon Newton–Schulz), which nothing here touches — the
same point #1111's side note made.

</details>

## Tests

```bash
pytest tests/unit/models/test_metrics.py
```

New cases cover that the metric tensors are built without a
host-to-device copy and that the masked counts match `masked_select`.
Passes.

## Checklist

I have filled in:

- [x] The purpose of the PR, such as "Fix some issue (link existing
issues this PR will resolve)".
- [x] The test plan/results, such as providing test command and pasting
the results.
- [ ] (Optional) The necessary documentation update.
- [x] I (a human) have written or reviewed the code in this pr to the
best of my ability.

🤖 Generated with [Claude Code](https://claude.com/claude-code)

---------

Signed-off-by: Orestis Zambounis <orestis.zambounis@gmail.com>
Signed-off-by: Orestis Zambounis <23146389+orestis-z@users.noreply.github.com>
Co-authored-by: Claude Opus 5 <noreply@anthropic.com>
@mergify

mergify Bot commented Oct 27, 2026

Copy link
Copy Markdown
Contributor

This pull request has merge conflicts that must be resolved before it can be
merged. Please rebase the PR, @orestis-z.

https://docs.github.com/en/pull-requests/collaborating-with-pull-requests/working-with-forks/syncing-a-fork

@mergify mergify Bot added the needs-rebase label Oct 27, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant