Quantifying Profiler Overhead
For high-frequency, lightweight operators, the torch.profiler.profile context manager introduces a non-linear overhead. Because the profiler records entry and exit events for every single kernel launch, the CPU-side cost of event logging and timestamp synchronization can exceed the actual execution time of the operator itself. This results in a "measurement skew" where small kernels appear significantly more expensive than they are in a production environment.
Likely Sources of Latency
While exact overhead varies by hardware and PyTorch version (assuming v2.0+), the latency is typically driven by:
- Event Logging: The Kineto backend must write event data to a buffer for every operator call.
- Stack Walking: If
with_stack=True is enabled, the profiler captures the Python call stack for every event, which is computationally expensive.
- Metadata Collection:
record_shapes=True adds overhead by querying tensor dimensions at each call.
- Synchronization: The need to align CPU and GPU timestamps can introduce stalls in the execution pipeline.
Configurations to Minimize Overhead
To maintain operator-level granularity while reducing instrumentation skew, apply the following constraints to your profiler configuration:
- Disable Stack Traces: Set
with_stack=False. This is the single most impactful change for high-frequency operators.
- Disable Shape Recording: Set
record_shapes=False to avoid the cost of metadata retrieval.
- Optimize the Schedule: Use a
torch.profiler.schedule to skip the first few iterations (warmup) and only capture a small window of execution (e.g., 1-2 iterations) to prevent the event buffer from overflowing.
- Limit Scope: Instead of profiling the entire training loop, wrap only the specific suspected bottleneck module in the profiler context.
Verification Workflow
To determine if your results are skewed by profiling overhead, run this scoped comparison:
# 1. Baseline: Measure wall-clock time without profiler
import time
start = time.perf_counter()
for _ in range(1000):
torch.add(a, b)
print(f"Baseline: {time.perf_counter() - start}")
# 2. Profiler: Measure total time with minimal config
with torch.profiler.profile(with_stack=False, record_shapes=False) as prof:
start = time.perf_counter()
for _ in range(1000):
torch.add(a, b)
print(f"Profiler Total: {time.perf_counter() - start}")
If the "Profiler Total" is significantly higher than the "Baseline," the reported latency for individual operators in the trace is likely inflated by the instrumentation cost.
Diagnostic Detail Needed: Are you profiling primarily on CPU or CUDA? The synchronization overhead differs significantly between the two, which may change the recommended approach to timestamping.