The Native Flame: Moving from Guesswork to Grounded Evidence in GPU Training Profiling

Introduction

In the high-stakes world of distributed GPU training, performance optimization often begins with intuition and ends with instrumentation. Between these two poles lies a critical transition: the moment when a team stops guessing about what is consuming CPU cycles and starts measuring it with objective, reproducible evidence. Message [msg 10579] captures this transition in microcosm. In it, an AI assistant running a distributed DFlash training pipeline on an 8-GPU system executes a py-spy recording with the --native flag to capture quantitative data about the C-level stack frames consuming CPU time. This single message—containing one agent reasoning block and one compound bash command—represents the culmination of a multi-message profiling campaign triggered by the user's demand for "seriously objective with grounded evidence" ([msg 10570]). The message is notable not for what it accomplishes in isolation, but for how it crystallizes a methodological shift from speculation to measurement, and for the technical sophistication of the profiling approach it deploys.

The Context: A Pipeline Under Scrutiny

To understand why this message was written, we must reconstruct the situation that led to it. The DFlash training pipeline—a distributed system training a speculative decoding model across 8 GPUs (5 target, 3 drafter)—had been running with highly volatile GPU utilization. The user reported that GPU memory and utilization were "really volatile / spotty," while over 10 CPU threads were pinned at 100% usage ([msg 10570]). This is a classic symptom of a pipeline bottleneck: the GPUs are not being fed fast enough, and the CPUs are working overtime to prepare data, synchronize streams, or launch kernels.

The team had been operating on hypotheses. Perhaps the CPU time was being eaten by Python-level queue operations—the hs_queue that passes hidden states between target and drafter GPUs. Perhaps it was the document-ID construction logic. Perhaps it was the create_block_mask calls. These were educated guesses, but guesses nonetheless. The user explicitly rejected this mode of reasoning: "We were guessing so far, we need to get seriously objective with grounded evidence about this."

This demand set off a profiling campaign. In [msg 10571], the assistant installed py-spy (a sampling profiler for Python processes) and began collecting data. In [msg 10575], it ran a Python-only profile that showed the top leaf frames: _chunk_fwd (10.5%), get_hidden_states_packed (9.2%), and forward on linear layers (8.6%). But Python-only profiling has a blind spot: any time spent in C extensions, CUDA runtime calls, or native library functions is invisible. The assistant recognized this limitation and in [msg 10578] ran a py-spy dump --native to get per-thread native stack traces. The results were illuminating: the hot threads were labeled "target-0" through "target-4" and their stacks were dominated by cuLaunchKernel, cuStreamSynchronize, and CUDA memory allocator functions—not Python queue or list operations.

This was the critical insight: the CPU burn was not in Python logic at all. It was in CUDA driver calls—kernel launches, stream synchronization, memory allocation. The threads were busy telling the GPU what to do.

The Subject Message: What It Does

Message [msg 10579] is the logical next step after this discovery. The assistant had seen native stack dumps showing CUDA calls, but these were point-in-time snapshots. What was needed was quantitative data: what fraction of samples land in each native function? The py-spy record --native command produces exactly this—a raw flamegraph data file where each line is a stack trace followed by a sample count. By parsing this file with Counter, the assistant could produce precise percentages for cuLaunchKernel, cuStreamSynchronize, CUDACachingAllocator, and other key functions.

The command issued in this message is:

ssh -o ConnectTimeout=10 root@10.1.2.6 "pct exec 200 -- /bin/bash -lc 'source /root/venv/bin/activate && py-spy record --pid 26982 --duration 30 --rate 49 --native --format raw --output /workspace/pyspy_phase012_native_raw.txt && python3 - <<\"PY\"
from collections import Counter
p=\"/workspace/pyspy_phase012_native_raw.txt\"
leaf=Counter(); anyf=Counter(); total=0
for line in open(p, errors=\"replace\"):
    if not line.strip(): continue
    stack_s,n_s=line.rsplit(\" \",1); n=int(n_s); total+=n
    frames=stack_s.split(\";\")
    leaf[frames[-1]]+=n
    for fr in frames: anyf[fr]+=n
print(\"TOTAL\", total)
print(\"TOP_LEAF\")
for k,v in leaf.most_common(30): print(f\"{v:6d} {v/total*100:5.1f}% {k}\")
print(\"TOP_ANY_NATIVE_OR_KEY\")
keys=[\"cuLaunchKernel\",\"cuStreamSynchronize\",\"CUDACachingAllocator\",\"malloc\",\"_local_scalar_dense\",\"create_block_mask\",\"forward (dflash_model.py\",\"_chunk_fwd\",\"get_hidden_states_packed\",\"modeling_qwen3_5.py\",\"queue\"]
for key in keys:
    s=sum(v for f,v in anyf.items() if key in f)
    print(f\"{s:6d} {s/total*100:5.1f}% {key}\")
PY'"

This is a sophisticated compound command. It first records 30 seconds of native stack samples at 49 Hz, then immediately parses the output with an inline Python script that computes two kinds of statistics: top leaf frames (the deepest function in each sampled stack) and top aggregated counts for specific keywords of interest. The keyword list is itself a window into the assistant's mental model: it includes CUDA runtime functions (cuLaunchKernel, cuStreamSynchronize, CUDACachingAllocator), memory allocation (malloc), scalar tensor access (_local_scalar_dense), attention mask construction (create_block_mask), and specific Python functions from the training pipeline (get_hidden_states_packed, _chunk_fwd).

The Reasoning Process: A Window into Debugging Methodology

The agent reasoning block in this message reveals a careful, iterative thought process. The assistant begins by synthesizing the evidence already gathered: "I'm seeing strong evidence that hot threads mostly target libcuda/cuLaunch/allocator/sync, with some connections to grad_norm and idle queues." This is a summary of the native dump from [msg 10578], which showed thread stacks dominated by CUDA driver calls.

The assistant then identifies the gap in the current evidence: "I think I need to parse the native raw data using --native, since we only used the dump so far." This is a crucial methodological insight. A py-spy dump gives you a snapshot of what each thread is doing right now, but a py-spy record with --native gives you a statistical sample over time. The dump can tell you what is happening, but only the record can tell you how much of the CPU time each activity consumes.

The assistant also considers the sampling rate: "I might need to run this at a lower rate for better results." This reflects an understanding of py-spy's limitations—at high sampling rates, py-spy itself can fall behind, introducing measurement error. The chosen rate of 49 Hz (just under 50) is a pragmatic compromise: high enough to get statistically meaningful samples in 30 seconds, but low enough that py-spy doesn't fall hopelessly behind.

The reasoning also reveals what the assistant expects to find: "This should show the C stack and could highlight high overhead issues." The word "could" is telling—the assistant is genuinely uncertain about what the data will reveal. The whole point of this exercise is to replace hypotheses with measurements.

Assumptions and Their Validity

Several assumptions underpin this message, and it is worth examining each.

Assumption 1: The CPU threads are the bottleneck. The user reported 10+ CPU threads at 100%, and GPU utilization was volatile. The assistant assumes that understanding what those threads are doing will point to a fixable bottleneck. This is reasonable, but it is worth noting that high CPU utilization could also be a consequence of GPU-side stalls (e.g., threads spinning on synchronization). The native stacks showing cuStreamSynchronize and sched_yield suggest this is indeed happening—threads are busy-waiting for GPU operations to complete.

Assumption 2: py-spy with --native can capture the relevant C stacks. This is true for user-space functions, but py-spy cannot profile kernel code or hardware-level GPU execution. The CUDA runtime calls visible in the stacks are CPU-side driver calls—the actual GPU kernel execution is invisible. This is a fundamental limitation: py-spy tells you what the CPU is doing while waiting for the GPU, not what the GPU is doing.

Assumption 3: The sampling rate of 49 Hz is adequate. The output shows py-spy falling progressively behind: 1.10s, 1.91s, 2.79s, 3.54s, 4.26s behind. This is a warning sign. When py-spy falls behind, it means the sampling intervals are stretching, and the statistical properties of the sample may degrade. The assistant anticipated this ("I might need to run this at a lower rate for better results") but proceeded anyway. This is a pragmatic trade-off: even imperfect data is better than no data.

Assumption 4: The keyword-based aggregation is a useful analysis strategy. The assistant pre-selects a list of keywords to search for in the native stacks. This is both a strength and a weakness. It focuses the analysis on the most likely culprits, but it also creates a confirmation bias risk—if the real bottleneck is something not in the keyword list, it will be missed. The assistant mitigates this by also printing the top 30 leaf frames unconditionally, which provides a safety net.

Input Knowledge Required

To fully understand this message, a reader needs:

  1. Knowledge of the DFlash training architecture: The pipeline involves target models (computing forward passes) and drafter models (speculative decoding), with hidden states passed between them via a queue. The message references get_hidden_states_packed, _chunk_fwd, and specific model files (dflash_model.py, train_dflash_pipeline.py).
  2. Familiarity with py-spy: Understanding that --native enables C-level stack frame capture, that --format raw produces parseable text output, and that sampling rate and duration affect data quality.
  3. Understanding of CUDA runtime architecture: The keywords cuLaunchKernel, cuStreamSynchronize, and CUDACachingAllocator are CUDA driver API functions. Knowing what each does is essential to interpreting the results.
  4. Knowledge of the training environment: The command runs inside an LXC container (via pct exec 200) on a remote host (10.1.2.6), with a Python virtual environment at /root/venv.
  5. Context from prior messages: The user's demand for objective evidence ([msg 10570]), the installation of py-spy ([msg 10571]), the Python-only profile ([msg 10575]), and the native dump ([msg 10578]) all provide essential background.

Output Knowledge Created

This message produces a raw flamegraph data file (/workspace/pyspy_phase012_native_raw.txt) containing 30 seconds of native stack samples at 49 Hz (approximately 1,470 samples). The inline Python script then transforms this into two quantitative summaries:

  1. Top leaf frames: The deepest function in each sampled stack, ranked by frequency. This identifies what each thread was doing at the moment of sampling, rather than what called it.
  2. Keyword-aggregated counts: The total samples containing each keyword anywhere in the stack, across all threads. This answers questions like "what fraction of samples involved cuLaunchKernel?" or "how much time is spent in create_block_mask?" The output is truncated in the message (py-spy was still running when the output was captured), so the actual quantitative results are not visible in this message. They would appear in the next round, when the command completes.

Mistakes and Limitations

Several issues deserve critical examination.

The sampling rate was too high. The py-spy output explicitly warns that it is falling behind, and the gap grows throughout the 30-second window. This means the sampling intervals are not uniform, and the later samples may be biased toward states that are more persistent (since py-spy is more likely to catch long-running operations when it's behind). A rate of 10-20 Hz would likely have produced more reliable data.

The compound command is fragile. Running py-spy record followed immediately by a Python parsing script means that if the recording fails (e.g., because the PID exits), the parsing script will fail too, and the error will be hard to diagnose. A more robust approach would be to run the recording and parsing as separate commands.

The keyword list may miss important functions. The assistant's pre-selected keywords are reasonable, but they are based on prior hypotheses. If the real bottleneck is, say, cudaMemcpyAsync or cuEventSynchronize (which are not in the keyword list), the aggregated output would not highlight them. The unconditional top-30 leaf list provides a partial safety net, but the keyword aggregation could give a false sense of completeness.

The analysis conflates "time spent" with "samples captured." Py-spy is a sampling profiler, which means it estimates the fraction of wall-clock time spent in each function. But if py-spy is falling behind, the samples are not uniformly distributed in time, and the estimates may be biased. The assistant acknowledges this implicitly ("Try reducing the sampling rate") but does not correct for it.

The Broader Significance

This message represents a methodological turning point in the optimization campaign. Before it, the team was operating on hypotheses about Python-level bottlenecks. After it, they had quantitative evidence that the real bottleneck was CUDA kernel launch and synchronization overhead—a fundamentally different class of problem. This evidence directly led to the implementation of an async postprocess pipeline (described in the chunk summary) that moved hidden-state packing and GPU-to-CPU transfer off the target forward critical path, allowing target GPUs to launch the next verifier forward immediately.

The message also exemplifies a disciplined approach to performance debugging: start with user-reported symptoms, formulate hypotheses, gather preliminary data, identify gaps in the data, design a more targeted measurement, execute it, and let the results guide the next intervention. The assistant does not jump to conclusions or implement fixes based on intuition. It insists on measurement first.

Conclusion

Message [msg 10579] is, on its surface, a simple profiling command. But in the context of the broader optimization campaign, it is the moment when guesswork gave way to evidence. The assistant's reasoning shows a clear understanding of the limitations of point-in-time native dumps and the need for statistical sampling over time. The compound command design—recording native stacks and immediately parsing them with targeted keyword aggregation—reflects a sophisticated mental model of both the profiling tool and the system under investigation.

The message is not without flaws: the sampling rate was too aggressive, the compound command is fragile, and the keyword list may introduce blind spots. But these are limitations of execution, not of methodology. The core insight—that you must measure before you optimize, and that you must measure at the right level of abstraction—is sound. In the high-pressure environment of distributed GPU training, where every hour of GPU time represents significant cost, this discipline is not just good practice. It is essential.