Diagnosing GPU Starvation: The awk Script That Revealed the Bottleneck Shift in Phase 9

Introduction

In the high-stakes world of Filecoin proof generation, every millisecond counts. The SUPRASEAL_C2 Groth16 proving pipeline had just undergone a major optimization — Phase 9's PCIe transfer optimization had slashed GPU kernel time by 71.6%, from 2.4s to 690ms per partition. But when the assistant ran a larger benchmark with 15 concurrent syntheses and 10 proofs, the results were puzzling: throughput had actually regressed to 42.9s per proof, worse than the small-scale run of 32.1s. The GPU, now dramatically faster, appeared to be starving for work.

The user's intuition was sharp: "Would the theory be complete starvation on synths coming in fast enough? Not a bad place to be." But to confirm this hypothesis and quantify the starvation, the assistant needed hard data. This is where message 2497 enters the story — a deceptively simple awk script that would reveal the true state of GPU utilization and set the stage for the next phase of optimization.

The Message

The assistant wrote:

Now let me write a quick analysis script to compute GPU idle gaps and utilization:

>

```bash grep "^TIMELINE" /tmp/cuzk-p9-c15-daemon.log | grep -E "GPU_(START|END)" | sort -t, -k2 -n | awk -F, ' { t = $2+0 if ($3 ~ /GPU_START/) { start = t if (prev_end > 0) { gap = t - prev_end gaps[gap_count++] = gap total_gap += gap } } if ($3 ~ /GPU_END/) { prev_end = t gpu_ms = t - start total_gpu += gpu_ms n_parts++ if (first_start == 0) first_start = start - gpu_ms # approx } } END { # Use actual first GPU_START printf "GPU partitions processed: %d\n", n_parts printf "Total GPU compute: %.1fs\n", total_gpu/1000 printf "Total GPU idle gaps: %.1fs (%d gaps)\n", total_gap/1000, gap_count printf "Avg gap: %.0fms\n", total_gap/gap_count printf "Max gap: " max=0; for(i=0;i<gap_count;i++) if(gaps[i]>max) max=gaps[i] printf "%.0fms\n", max printf "Min gap: " min=999999; for(i=0;i<gap_count;i++) if(gaps[i]<min) min=gaps[i] printf "%.0fms\n", min

>

# Show gap distribution for(i=0;i<gap_count;i++) { if (gaps[i] < 100) b0++ else if (gaps[i] < 500) b1++ else if (gaps[i] < 1000) b2++ else if (gaps[i] < 2000) b3++ else b4++ } printf "\nGap distribution:\n" printf " <100ms: %d\n", b0 printf " 100-500ms: %d\n", b1 printf " 500-1000ms: %d\n", b2 printf " 1-2s: %d\n", b3 printf " >2s: %d\n", b4

>

# GPU utilization span = prev_end - 274115 # first GPU_START from data printf "\nGPU utilization: %.1f%% (compute %.1fs / span %.1fs)\n", 100*total_gpu/(total_gpu+total_gap), total_gpu/1000, span/1000 }' ```

>

Output: ``` GPU partitions processed: 150 Total GPU compute: 550.8s Total GPU idle gaps: 60.5s (149 gaps) Avg gap: 406ms Max gap: 3813ms Min gap: 11ms

>

Gap distribution: <100ms: 57 100-500ms: 52 500-1000ms: 30 1-2s: 7 >2s: 3

>

GPU utilization: 90.1% (compute 550.8s / span 611.4s) ```

Why This Message Was Written

The assistant was in the middle of a systematic optimization campaign. Phase 9 had just been committed with promising single-worker results (32.1s/proof, a 14.2% improvement), but the larger benchmark with c=15 j=10 had produced a disappointing 42.9s/proof. The user had explicitly asked for timing data and waterfall visualizations ([msg 2490]), and had proposed the starvation hypothesis ([msg 2491]). The assistant needed to:

  1. Validate the hypothesis that GPU starvation was the root cause of the throughput regression.
  2. Quantify the starvation — how much idle time, how often, and in what pattern.
  3. Provide actionable data to guide the next optimization step. The TIMELINE instrumentation was already built into the cuzk engine (always-on, emitting events to stderr via eprintln!), and the daemon's stderr had been captured to the log file. The raw data was there — 900 TIMELINE events from 150 GPU partitions across 15 proofs. The assistant needed to extract meaning from this noise.

How the Analysis Was Constructed

The script is a pipeline of Unix text-processing tools: grep, grep -E, sort, and awk. Each stage has a specific purpose:

  1. grep &#34;^TIMELINE&#34; — Extract only TIMELINE-prefixed lines from the daemon log, filtering out all other log output (INFO, WARN, etc.).
  2. grep -E &#34;GPU_(START|END)&#34; — Further filter to only GPU_START and GPU_END events, discarding SYNTH_START, SYNTH_END, and other event types.
  3. sort -t, -k2 -n — Sort numerically by the second comma-separated field, which is a monotonic millisecond timestamp. This ensures events are processed in chronological order even if they arrived out of order in the log.
  4. awk -F, &#39;{...}&#39; — The core analysis engine, using comma as field separator. The awk script itself implements a simple state machine. It tracks prev_end (the timestamp of the last GPU_END) and start (the timestamp of the current GPU_START). When a GPU_START arrives, it computes the gap since the last GPU_END and records it. When a GPU_END arrives, it computes the GPU kernel duration and accumulates it. The END block then computes summary statistics: total partitions, total compute time, total idle gaps, average/max/min gap, a gap distribution histogram, and an overall GPU utilization percentage. The utilization calculation deserves scrutiny. The script computes span = prev_end - 274115 where 274115 is the first GPU_START timestamp observed in the data (hardcoded after inspection). It then computes utilization as total_gpu / (total_gpu + total_gap). This is an approximation — the true span should be from the first GPU_START to the last GPU_END, but the script's approach is reasonable for a quick diagnostic.

Input Knowledge Required

To understand this message, one needs:

  1. The TIMELINE event format: Each event is a comma-separated line like TIMELINE,&lt;timestamp_ms&gt;,&lt;event_type&gt;,&lt;job_id&gt;,&lt;details&gt;. The timestamp is a monotonic millisecond counter. GPU_START and GPU_END events carry partition-level timing data.
  2. The cuzk architecture: A single proof requires 10 partitions. Each partition goes through synthesis (CPU-bound PCE constraint generation) followed by GPU proving (NTT + MSM operations). The pipeline has partition_workers (pw=10) controlling how many syntheses run concurrently, and gpu_workers_per_device (gw=1) controlling GPU workers.
  3. The benchmark setup: c=15 means 15 concurrent proof requests in flight, j=10 means 10 total proofs. The daemon was configured with gw=1, pw=10.
  4. The Phase 9 context: PCIe transfer optimization had dramatically reduced GPU kernel time, shifting the bottleneck from GPU compute to CPU-side work.

Output Knowledge Created

This single script produced several critical insights:

  1. GPU utilization was 90.1% — high, but not perfect. The 9.9% idle time represented 60.5 seconds of wasted GPU capacity across the benchmark.
  2. Average gap was 406ms — significant when GPU kernel time per partition was ~3.7s. Each gap represents ~11% of a partition's GPU time.
  3. Gap distribution revealed the pattern: 57 gaps under 100ms (small scheduling jitter), 52 gaps between 100-500ms (moderate starvation), 30 gaps between 500-1000ms (significant), and 10 gaps over 1s (severe starvation, up to 3.8s).
  4. Theoretical throughput ceiling: With GPU avg at 3.67s/partition and 10 partitions per proof, the theoretical minimum was 36.7s/proof at 100% utilization. The actual 42.9s/proof meant 85.6% effective throughput. This data confirmed the user's starvation hypothesis with concrete numbers. The GPU was spending 60.5 seconds doing nothing across the benchmark, waiting for CPU-side synthesis to produce the next partition's data.

Assumptions and Potential Pitfalls

The script makes several assumptions worth examining:

  1. Perfect event ordering: The sort step assumes timestamps are monotonic and unique. If two events share the same millisecond timestamp, their relative order could be ambiguous, potentially causing a GPU_END to be paired with the wrong GPU_START.
  2. No missing events: The script assumes every GPU_START has a matching GPU_END and vice versa. A dropped event would corrupt the pairing and produce nonsensical gaps.
  3. Hardcoded first timestamp: The value 274115 was determined by inspecting the data and hardcoded into the script. If the script were run on different data, this would need updating. The comment "first GPU_START from data" acknowledges this brittleness.
  4. Utilization formula: Computing utilization as total_gpu / (total_gpu + total_gap) double-counts the first partition's GPU time (it's in both the numerator and the gap denominator). A more accurate formula would be total_gpu / span where span = last_GPU_END - first_GPU_START.
  5. No distinction between within-proof and cross-proof gaps: The script treats all gaps identically, but gaps within a single proof (mid-proof starvation) have different implications than gaps between proofs (pipeline drain). The assistant later refined this analysis in subsequent messages ([msg 2498], [msg 2499]) to distinguish these cases.

The Thinking Process Visible in the Code

The awk script reveals the assistant's thought process in several ways:

Mistakes and Incorrect Assumptions

The most significant limitation is the utilization formula. The script computes 100*total_gpu/(total_gpu+total_gap), which implicitly assumes the span equals compute time plus gaps. But this double-counts the first partition's compute time (it contributes to total_gpu but its corresponding gap is zero, so the denominator is actually total_gpu + total_gap which is slightly larger than the true span). The result is a slight underestimate of utilization — the true GPU utilization was actually slightly higher than 90.1%.

More importantly, the script doesn't normalize for the number of GPU workers. With gw=1, there's exactly one GPU worker, so the single-GPU utilization is meaningful. But the assistant later discovered that the utilization number was misleading because the gaps clustered at proof boundaries rather than being uniformly distributed ([msg 2501]). The 90.1% number suggested "pretty good," but the reality was that synthesis and GPU were almost perfectly balanced at ~36s each — any variance caused a cascade of gaps.

Impact and Legacy

This message was a turning point in the optimization campaign. The 90.1% utilization and 406ms average gap provided the quantitative evidence needed to justify the next phase of work. The assistant immediately followed up with deeper analysis ([msg 2498], [msg 2499], [msg 2501]) that revealed the true bottleneck: with pw=10, synthesis took ~36s for all 10 partitions and GPU processed them in ~37s. They were nearly balanced, meaning any variance caused starvation.

This analysis directly led to the Phase 10 two-lock design, where the assistant restructured the GPU locking protocol to allow multiple workers to overlap CPU-side memory management with GPU kernel execution. The insight that "the bottleneck has moved from PCIe transfers and GPU kernel execution to CPU memory bandwidth contention" — which the assistant articulated in the subsequent chunk — was born from this awk script's cold, hard numbers.

The script itself is a beautiful example of ad-hoc performance analysis: a pipeline of standard Unix tools, a carefully designed state machine in awk, and output that immediately drives decision-making. It's the kind of analysis that every systems programmer should have in their toolkit — quick, dirty, and devastatingly effective.