torch.profiler schedule produces overlapping traces and inflated kernel times — how to configure it correctly

1. Where to call profiler.step()

Place profiler.step() at the very end of your logical training iteration – after the forward pass, backward pass, optimizer step, and any explicit torch.cuda.synchronize() you may have. This guarantees that each step() marks a *complete* iteration.

With a schedule such as schedule(wait=1, warmup=1, active=3, repeat=2), the profiler behaves as follows:

• WAITING – the first wait iteration is ignored.
• WARMUP – the next warmup iteration is recorded but not exported.
• ACTIVE – the following active iterations are exported to TensorBoard.
• REPEAT – the cycle repeats repeat times, creating a distinct trace folder for each cycle.

Because each repeat cycle writes to a new sub‑directory (e.g., runs/run_0, runs/run_1), overlapping traces occur only if you call step() inside the warmup phase or forget to call it for a full iteration. Keeping step() at the loop end eliminates this problem.

Example

from torch.profiler import profile, schedule, tensorboard_trace_handler

profiler = profile(
    schedule=schedule(wait=1, warmup=1, active=3, repeat=2),
    on_trace_ready=tensorboard_trace_handler("runs")
)

profiler.start()
for epoch in range(num_epochs):
    for batch in loader:
        # forward, loss, backward, optimizer step
        optimizer.step()
        torch.cuda.synchronize()  # optional but ensures timing is accurate
        profiler.step()  # <– end of iteration
profiler.stop()

2. Minimal‑overhead configuration for accurate GPU timing

Overhead stems from two sources: kernel launch latency tracking and additional bookkeeping when extra knobs are enabled. The following settings give operator‑level CUDA self‑time with the least distortion:

• record_shapes=True – keeps shape information, which is useful for most analyses. It adds very little overhead.
• with_stack=False – disabling stack traces removes the cost of capturing call‑stack information.
• profile_memory=False – avoids memory‑allocation tracking, which can inflate self‑time for small kernels.
• Keep profile_memory and with_stack turned off unless you specifically need those metrics.

Typical minimal configuration:

profiler = profile(
    schedule=...,
    record_shapes=True,
    with_stack=False,
    profile_memory=False,
    on_trace_ready=...
)

3. Quantifying the profiler’s own cost

To see how much the profiler is adding, compare a plain CUDA event measurement with the profiler’s reported self‑time for the same iteration.

1. Measure a single iteration without the profiler:

start = torch.cuda.Event(enable_timing=True)
end = torch.cuda.Event(enable_timing=True)
start.record()
# forward, backward, optimizer step, synchronize
end.record()
torch.cuda.synchronize()
raw_time_ms = start.elapsed_time(end)

1. Run the same iteration inside the ACTIVE phase of the profiler and capture the trace. In the trace, locate the self_cuda_time_ms for the operator(s) that dominate the iteration.
2. Subtract raw_time_ms from the summed self_cuda_time_ms. The difference is the profiler’s overhead for that iteration.

For well‑tuned minimal settings, the overhead should be a few milliseconds for small kernels and grow proportionally with the number of operators. If the difference is large, revisit the record_shapes and with_stack knobs.

4. Practical tips

• Always call torch.cuda.synchronize() before profiler.step() if your training loop contains asynchronous operations that may still be in flight.
• When using DistributedDataParallel, place profiler.step() after the collective sync to keep the schedule aligned.
• Check profiler.state after each step() during debugging to confirm that the profiler is cycling through WAITING → WARMUP → ACTIVE as expected.