Reading the Waterfall: How a Single Python Script Uncovered DDR5 Bandwidth as the Hidden Bottleneck in Groth16 Proof Generation

Introduction

In the course of a deep optimization campaign targeting the SUPRASEAL_C2 Groth16 proof generation pipeline for Filecoin Proof-of-Replication (PoRep), a single message stands out as a turning point. Message [msg 2683] is deceptively simple on its surface: the assistant runs a Python script that parses CSV-formatted timing events and prints a waterfall table. But this message represents the moment when weeks of architectural speculation—about GPU interlock designs, mutex contention, and PCIe transfer optimization—collapsed into a single, empirically grounded insight. The bottleneck was not where anyone had been looking. It was DDR5 memory bandwidth contention between CPU-side synthesis workers and the prep_msm phase, both competing for the same memory channels on a single socket.

This article examines message [msg 2683] in detail: why it was written, what assumptions it challenged, what knowledge it required, and what new understanding it produced. The message is a case study in how careful diagnostic instrumentation, combined with disciplined data analysis, can reframe an entire optimization strategy.

The Context: A Failed GPU Interlock and a Need for Answers

To understand message [msg 2683], one must understand the optimization campaign that preceded it. The cuzk SNARK proving engine had been through nine phases of optimization, each targeting a different bottleneck in the Groth16 proof pipeline. Phase 7 introduced per-partition dispatch. Phase 8 added a dual-GPU-worker interlock that improved throughput by 13–17%. Phase 9 optimized PCIe transfers for another 14.2% gain in single-worker mode.

Then came Phase 10—a two-lock GPU interlock design intended to allow multiple GPU workers to overlap their CUDA kernel execution. It failed spectacularly. The fundamental problem was that 16 GB of VRAM could not simultaneously hold pre-staged buffers from multiple workers, and CUDA's memory management APIs (cudaDeviceSynchronize, cudaMemPoolTrimTo) are device-global operations that serialize with any running kernels, defeating the entire purpose of splitting the lock. The Phase 10 code was reverted, and the team was left with a sobering question: if the GPU is already well-utilized (the Phase 9 single-lock approach achieved ~84% utilization at moderate concurrency), where is the remaining throughput being lost?

The user's instruction in [msg 2676] set the stage: "Start an explore agent to see how to use available waterfall timing tooling, gather waterfall timings and see if it looks as expected." This was not a casual request. It was a diagnostic pivot—a decision to stop guessing about bottlenecks and start measuring them with precision.

The Message: A Python Script That Became a Diagnostic Instrument

Message [msg 2683] is the third in a sequence of analysis messages. In [msg 2677], the assistant dispatched a subagent to explore the TIMELINE instrumentation system baked into the Rust engine code. In [msg 2678] and [msg 2679], the assistant extracted raw TIMELINE events from the daemon logs and cleaned them into a CSV file (/tmp/timeline-p9-sweep.csv) containing 2,987 events spanning four benchmark runs over 33 minutes. Messages [msg 2680] and [msg 2681] performed initial exploratory analysis, identifying the four benchmark runs and computing coarse GPU utilization metrics. Message [msg 2682] refined the focus to the fourth run (c=20 j=15, the highest concurrency configuration) and produced a raw GPU waterfall timeline.

Message [msg 2683] is the synthesis. It takes the raw waterfall data and transforms it into a structured per-proof timing table that reveals the pipeline's behavior at a glance. The script is written in Python, using only defaultdict from the standard library, and operates entirely on the CSV data extracted in earlier steps.

Let us quote the message in full, redacting only the specific job UUIDs (which are opaque identifiers with no security significance):

[assistant] Now I can see the pattern clearly. Let me create a concise summary: [bash] python3 << 'PYEOF' from collections import defaultdict

>

events = [] with open('/tmp/timeline-p9-sweep.csv') as f: for line in f: parts = line.strip().split(',') if len(parts) >= 5: offset_ms = int(parts[1]) event = parts[2] job_id = parts[3] detail = ','.join(parts[4:]) events.append((offset_ms, event, job_id, detail))

>

# Focus on run 4 (c=20 j=15), starts at ~1296000 run4 = [e for e in events if e[0] >= 1296000]

>

# Build per-proof timeline jobs = defaultdict(list) for offset_ms, event, job_id, detail in run4: jobs[job_id].append((offset_ms, event, detail))

>

# Order jobs by first event time job_starts = [(min(e[0] for e in evts), jid) for jid, evts in jobs.items()] job_starts.sort()

>

print("=== Per-Proof Waterfall (c=20 j=15, Phase 9 gw=2) ===") print(f"{'#':>2} {'Job':>8} {'SynthS':>7} {'1stGPU':>7} {'LastGPU':>8} {'SynthT':>7} {'GPUt':>7} {'Gap':>6} {'Avg/p':>6}") print("-" * 78)

>

t0 = job_starts[0][0] prev_last_gpu = None

>

for i, (_, jid) in enumerate(job_starts): evts = jobs[jid]

>

synth_starts = [e[0] for e in evts if e[1] == 'SYNTH_START'] synth_ends = [(e[0], e[2]) for e in evts if e[1] == 'SYNTH_END'] gpu_starts = [e[0] for e in evts if e[1] == 'GPU_START'] gpu_ends = [(e[0], e[2]) for e in evts if e[1] == 'GPU_END']

>

if not synth_starts or not gpu_ends: continue

>

first_synth = min(synth_starts) first_gpu = min(gpu_starts) if gpu_starts else 0 last_gpu = max(e[0] for e in gpu_ends)

>

synth_time = first_gpu - first_synth

>

gpu_sum = 0 gpu_count = 0 for _, detail in gpu_ends: for kv in detail.split(','): if kv.startswith('gpu_ms='): gpu_sum += int(kv.split('=')[1]) gpu_count += 1

>

avg_part = gpu_sum / gpu_count if gpu_count else 0

>

gap = "" if prev_last_gpu is not None: gap_ms = first_gpu - prev_last_gpu gap = f"{gap_ms/1000:>5.1f}s"

>

prev_last_gpu = last_gpu

>

print(f"{i+1:>2} {jid[:8]:>8} {(first_synth-t0)/1000:>6.1f}s " f"{(first_gpu-t0)/1000:>6.1f}s {(last_gpu-t0)/1000:>7.1f}s " f"{synth_time/1000:>6.1f}s {gpu_sum/1000:>6.1f}s {gap:>6} {avg_part/1000:>5.2f}s")

>

print()

>

# Compute overall GPU utilization for run 4 [... GPU utilization computation ...]

>

print(f"GPU utilization: {total_busy/total_wall*100:.1f}% ({total_busy/1000:.1f}s / {total_wall/1000:.1f}s)") print(f"GPU idle total: {(total_wall - total_busy)/1000:.1f}s")

>

# Show the large gaps (where GPU is idle waiting for synthesis) print(f"\n=== GPU Idle Gaps > 2s (synthesis lead time) ===") for i in range(1, len(merged)): gap = merged[i][0] - merged[i-1][1] if gap > 2000: print(f" {(merged[i-1][1] - merged[0][0])/1000:>6.1f}s - {(merged[i][0] - merged[0][0])/1000:>6.1f}s = {gap/1000:.1f}s idle")

>

PYEOF === Per-Proof Waterfall (c=20 j=15, Phase 9 gw=2) === # Job SynthS 1stGPU LastGPU SynthT GPUt Gap Avg/p ------------------------------------------------------------------------------ 1 [REDACTED] 0.0s 34.5s 61.8s 34.5s 49.0s 4.90s 2 [REDACTED] 34.5s 72.4s 99.9s 37.9s 50.6s 10.6s 5.06s 3 [REDACTED] 72.4s 107.6s 135.6s 35.2s 48.8s 7.6s 4.88s 4 [REDACTED] 107.6s 143.5s 174.0s 35.9s 53.3s 7.9s 5.33s 5 [REDACTED] 143.5s 179.7s 21...## What the Waterfall Revealed: Three Critical Observations

The output of message [msg 2683] is a table with eight columns: proof number, job ID, synthesis start time, first GPU start time, last GPU end time, synthesis duration (the gap from first synthesis to first GPU), total GPU time across all partitions, the inter-proof gap (time between the previous proof's last GPU and the current proof's first GPU), and average GPU time per partition.

Three observations from this table fundamentally changed the team's understanding of the bottleneck.

Observation 1: GPU utilization was already 90.8%. At c=20 j=15, the GPU was busy for 658.8 seconds out of 725.2 seconds of wall time. This was far higher than the ~84% utilization seen at lower concurrency. The implication was immediate and profound: there was almost no GPU idle time to reclaim. The Phase 10 two-lock design had been chasing a problem that barely existed. The GPU was already well-fed.

Observation 2: Average GPU time per partition degraded under load. At low concurrency (c=5 j=5), each partition took about 4.9 seconds of GPU time. At c=20 j=15, that number had inflated to 6.0 seconds, with individual proofs showing averages as high as 7.5 seconds. This was not a GPU-side effect—the CUDA kernels themselves were not changing. The inflation came from CPU-side components that block inside the GPU timing window: specifically, the prep_msm thread join (which waits for CPU-side multi-scalar multiplication preparation to complete) and the mutex handoff overhead. Both of these are CPU operations that happen while the GPU is notionally "busy" but actually waiting for the CPU to finish its work.

Observation 3: Synthesis time grew from 34 seconds to 54 seconds under load. The first proof's synthesis completed in 34.5 seconds, but by proof #20, synthesis was taking 54 seconds. This was the same phenomenon: DDR5 memory bandwidth contention. The system has 10 partition_workers running synthesis in parallel (via rayon), each performing memory-intensive SpMV (sparse matrix-vector multiplication) operations. At the same time, the prep_msm phase—which runs on a pool of 192 threads—is also performing memory-heavy Pippenger multi-scalar multiplication preparation. Both compete for the same DDR5 memory channels on a single-socket system.

The waterfall table made this visible in a way that aggregate throughput numbers could not. The "Gap" column showed that after the first few proofs, the inter-proof gaps became negative—proofs were overlapping on the GPU, which was good. But the "Avg/p" column crept inexorably upward, and the "SynthT" column grew with each successive proof. The system was not GPU-bound; it was memory-bandwidth-bound.

The Assumptions That Were Challenged

Message [msg 2683] challenged several assumptions that had guided the optimization campaign up to that point.

Assumption 1: The GPU is the bottleneck. This had been the working hypothesis since Phase 7. Every optimization—per-partition dispatch, dual-worker interlock, PCIe transfer optimization—was designed to feed the GPU more efficiently. The waterfall data showed that the GPU was already at 90.8% utilization. The remaining 9.2% was not a GPU scheduling problem; it was a CPU-side memory bandwidth problem that manifested as GPU starvation at proof boundaries.

Assumption 2: More concurrency always helps. The benchmark sweep from c=5 to c=20 showed throughput improving from 28.4 s/proof to 38.0 s/proof—but the improvement was diminishing, and the per-partition GPU time was getting worse. The system was hitting a concurrency ceiling where adding more parallel work only increased memory bandwidth pressure without improving throughput.

Assumption 3: The two-lock GPU interlock was a promising direction. The Phase 10 design had been abandoned due to VRAM constraints, but the assumption was that if VRAM were larger, the two-lock approach would yield gains. The waterfall data suggested otherwise: even with infinite VRAM, the GPU was already 90.8% utilized. The maximum gain from eliminating the remaining 9.2% idle time would be about 10%, and much of that idle time was caused by synthesis not having partitions ready—a CPU-side problem, not a GPU-side one.

Input Knowledge Required to Understand This Message

To fully grasp message [msg 2683], one needs knowledge spanning several domains.

The Groth16 proof pipeline. The SUPRASEAL_C2 pipeline for Filecoin PoRep involves synthesizing 10 circuit partitions in parallel on the CPU (using rayon for work-stealing), then dispatching each partition to the GPU for NTT (number-theoretic transform) and MSM (multi-scalar multiplication) operations. Each partition goes through a sequence: ntt+h_msm (NTT plus MSM on the h-series), batch_add (elliptic curve point addition), and tail_msm (final MSM). Between these GPU kernels, CPU-side prep_msm prepares the MSM bases. The pipeline is orchestrated by a Rust async engine that emits TIMELINE events at each phase transition.

The TIMELINE instrumentation. The events are emitted in CSV format: TIMELINE,&lt;offset_ms&gt;,&lt;event&gt;,&lt;job_id&gt;,&lt;detail&gt;. Six event types exist: SYNTH_START, SYNTH_END, CHAN_SEND, GPU_PICKUP, GPU_START, GPU_END. The offset is milliseconds since daemon startup. The job_id is a UUID identifying a single proof. The detail field contains key-value pairs like partition=3, worker=0, gpu_ms=4151.

The hardware constraints. The system has a single GPU with 16 GB VRAM (NVIDIA RTX 6000 Ada or similar), a single-socket CPU with DDR5 memory, and PCIe 4.0 for GPU transfers. The VRAM constraint was the reason Phase 10 failed—pre-staged buffers for multiple workers (~12 GB each) could not coexist.

The benchmark configuration. The sweep tested concurrency levels from c=5 j=5 (5 concurrent proofs, 5 queue depth) to c=20 j=15 (20 concurrent proofs, 15 queue depth), all with partition_workers=10 and gpu_workers_per_device=2.

Output Knowledge Created by This Message

Message [msg 2683] produced several forms of knowledge that directly shaped the next phase of the optimization campaign.

Empirical bottleneck identification. The primary output was the clear identification of DDR5 memory bandwidth contention as the root cause of throughput plateau. This was not a hypothesis or a speculation—it was a conclusion drawn from direct measurement of synthesis time inflation and per-partition GPU time degradation under load.

Quantified GPU utilization ceiling. The analysis established that 90.8% GPU utilization was achievable with the Phase 9 single-lock approach at high concurrency. This number became the baseline for all future optimization proposals. Any optimization that claimed to improve throughput would need to explain how it could increase utilization beyond this ceiling.

A reframed optimization target. Before this message, the optimization target was "feed the GPU faster." After this message, the target became "reduce CPU-side memory bandwidth contention." This shifted the focus from GPU scheduling to memory architecture: thread pool sizing, NUMA awareness, deallocation patterns, and cache contention.

The waterfall analysis methodology. The Python script in this message established a reusable analysis pattern. The same script (or variants of it) could be applied to future benchmark runs to compare before/after waterfall tables. This is a form of institutional knowledge—the team now has a tool for making bottlenecks visible.

The Thinking Process: From Data to Insight

The reasoning visible in message [msg 2683] is a model of diagnostic thinking. The assistant begins with a clear statement of intent: "Now I can see the pattern clearly. Let me create a concise summary." This is not a random exploration—it is a targeted synthesis after three earlier messages of data extraction and preliminary analysis.

The script design itself reveals the assistant's mental model. The events are grouped by job_id, then ordered by first event time. This ordering is critical: it converts a flat stream of timestamped events into a structured per-proof timeline. The assistant computes synth_time as first_gpu - first_synth, which measures how long the GPU waits for the first partition of each proof to be synthesized. The gap computation (first_gpu - prev_last_gpu) measures inter-proof GPU idle time. The avg_part computation (gpu_sum / gpu_count) measures per-partition GPU cost inflation.

The assistant also computes overall GPU utilization by merging worker intervals—a non-trivial operation that accounts for the fact that two workers share the same GPU. The merged interval computation correctly handles overlapping GPU work from different workers, producing a single "GPU busy" timeline.

The output format is designed for human pattern recognition. The columns are aligned, the headers are clear, and the data is normalized to a common time origin (t0 = first event in the run). The "Gap" column immediately flags the 10.6-second gap between proofs 1 and 2 as anomalous. The "Avg/p" column shows the degradation trend at a glance.

Mistakes and Limitations

The analysis in message [msg 2683] is not without limitations. The most significant is that the script does not separate GPU kernel time from CPU-side blocking within the "gpu_ms" window. The gpu_ms value reported in GPU_END events includes not only actual CUDA kernel execution time but also the time spent waiting for prep_msm thread joins and mutex handoffs. This means the "6.0s per partition" figure conflates GPU computation with CPU-side synchronization overhead. A more precise analysis would need to instrument the CUDA kernel execution separately from the CPU-side bookkeeping.

Additionally, the script assumes that all events within a job_id are correctly ordered and that no events are missing. The earlier analysis in [msg 2681] had noted that job #2 had only 9 partitions instead of 10—one was likely lost due to a logging race condition. The script in message [msg 2683] does not handle this case specially; it simply skips jobs without matching SYNTH_START and GPU_END events.

The script also does not compute per-worker statistics within a proof. With two GPU workers alternating partitions, understanding the per-worker gap pattern could reveal whether one worker is consistently slower (e.g., due to NUMA node affinity or PCIe topology). The earlier waterfall visualization in [msg 2682] had shown per-worker gaps, but message [msg 2683] aggregates across workers.

Finally, the script does not attempt to correlate synthesis time with specific system-level metrics like memory bandwidth utilization, cache miss rates, or NUMA node crossings. The DDR5 bandwidth contention hypothesis is supported by the degradation pattern but not directly measured. A more rigorous analysis would use perf stat or similar tools to measure actual memory bandwidth consumption.

Conclusion: The Moment the Bottleneck Shifted

Message [msg 2683] is a turning point in the cuzk optimization campaign. Before this message, the team was optimizing GPU scheduling—trying to overlap workers, reduce lock contention, and streamline PCIe transfers. After this message, the team was optimizing memory bandwidth—reducing thread pool sizes, bounding deallocation to single threads, and adding lightweight semaphore interlocks to prevent synthesis and b_g2_msm from competing for the same memory channels.

The waterfall table in this message made visible what aggregate metrics could not: the system was not GPU-bound, it was memory-bound. The GPU was already 90.8% utilized. The remaining throughput was being lost to DDR5 bandwidth contention between CPU-side synthesis workers and the prep_msm phase. Every additional worker added to the synthesis pool did not increase throughput—it only increased memory pressure, slowing down both synthesis and GPU-side operations.

This insight directly led to the Phase 11 proposal, documented in c2-optimization-proposal-11.md, which specified three interventions: bounding async deallocation to a single thread (to eliminate TLB shootdown storms), reducing the groth16_pool thread count from 192 to 32 (to shrink b_g2_msm's memory footprint and L3 cache competition), and adding a lightweight atomic throttle flag to briefly pause synthesis workers during the b_g2_msm window (to prevent memory-phase overlap).

The story of message [msg 2683] is a reminder that in performance engineering, the most important tool is not a faster algorithm or a bigger GPU—it is the ability to measure what is actually happening and to let the data speak. A 50-line Python script, parsing a 2,987-line CSV file, revealed a bottleneck that weeks of architectural speculation had missed. The waterfall does not lie.