The Waterfall That Revealed the Bottleneck: Analyzing a Benchmark Sweep Through Ad-Hoc Instrumentation

Introduction

In the high-stakes world of Filecoin proof generation, every millisecond counts. The SUPRASEAL_C2 Groth16 proving pipeline, a critical component of the Curio storage mining system, had just weathered a failed optimization attempt. Phase 10's ambitious two-lock GPU interlock design had collapsed under the weight of a fundamental CUDA reality: on a 16 GB GPU, you cannot safely overlap pre-staged VRAM allocations across multiple workers without running out of memory. The assistant had reverted to the proven Phase 9 single-lock architecture and, rather than retreating in defeat, had pivoted to something more valuable: a systematic benchmark sweep across concurrency levels to understand the real bottleneck.

The message at index 2680 captures a pivotal moment in this investigation. After running four benchmark configurations (c=5 j=5, c=10 j=10, c=15 j=15, and c=20 j=15) using the Phase 9 codebase, the assistant had accumulated 2,987 TIMELINE events spanning 33 minutes of execution. Now it needed to extract meaning from that raw data — to build a waterfall timing analysis that would reveal where the proving pipeline was actually spending its time. This article examines that single message in depth: the reasoning behind it, the decisions embedded in its code, the assumptions that shaped its output, and the knowledge it produced.

The Context: From Failed Optimization to Systematic Measurement

To understand why message 2680 exists, we must trace the chain of events that led to it. The preceding messages tell a story of disciplined engineering under pressure.

The Phase 10 failure (messages 2661–2664) was a painful but instructive episode. The assistant had designed a two-lock architecture that split GPU resource management into mem_mtx (for VRAM allocation and pre-staging) and compute_mtx (for kernel execution). The goal was to overlap CPU-side preprocessing with GPU kernel execution across multiple workers. But the design collided with a hard physical constraint: the 16 GB VRAM on the target GPU could not simultaneously hold pre-staged buffers from one worker while another worker's kernel pipeline ran. The OOM crashes were not bugs in the implementation — they were violations of a hardware invariant that the design had failed to account for.

What followed was a textbook example of disciplined engineering. Rather than patching the flawed design with increasingly complex workarounds, the assistant stepped back, analyzed the Phase 9 code to confirm it already released the GPU lock before b_g2_msm completed ([msg 2664]), and concluded that Phase 10's two-lock split offered no benefit over Phase 9 for a single-GPU configuration. The code was reverted with a single git checkout command.

The pivot to measurement (messages 2665–2675) was the critical turning point. Instead of chasing another architectural optimization, the assistant recognized that the real path forward was understanding the system's actual behavior under load. It launched a daemon with Phase 9 code and gpu_workers_per_device = 2, then ran a concurrency sweep: c=5 j=5, c=10 j=10, c=15 j=15, and c=20 j=15. The results showed throughput improving from 41.4 s/proof at c=5 to 38.2 s/proof at c=15, then plateauing. But the raw benchmark numbers only told part of the story. The real diagnostic power lay in the TIMELINE events that the daemon had been emitting all along.

The exploration of tooling (messages 2676–2679) set the stage for message 2680. The user requested an exploration of waterfall timing tooling, and the assistant dispatched a task agent that discovered the TIMELINE system — a lightweight CSV-based instrumentation embedded in cuzk-core/src/engine.rs. Events were emitted in the format TIMELINE,<offset_ms>,<event>,<job_id>,<detail>, covering SYNTH_START, GPU_START, and GPU_END events. There were no visualization tools; the raw data required grep, sort, and custom analysis. The assistant then extracted clean TIMELINE events from the daemon log, producing a 2,987-line CSV file spanning the entire 33-minute benchmark sweep.

The Message Itself: Building the Waterfall Analysis

Message 2680 is the assistant's response after the exploration task completed. It opens with a summary of the data available: "Good, 2987 clean events across 4 benchmark runs (c=5 j=5, c=10 j=10, c=15 j=15, c=20 j=15). The entire sweep spans from offset 55670ms to 2055706ms (~33 minutes)."

The assistant then writes an inline Python script — a pattern seen throughout this conversation where ad-hoc analysis is embedded directly in bash commands using heredoc syntax. The script is a self-contained parser that:

Reads the CSV file line by line, splitting on commas to extract offset_ms, event type, job_id, and detail string
Groups events by job_id using a defaultdict(list)
Orders jobs by their first event timestamp to establish a chronological sequence
For each job, computes: first SYNTH_START time, first GPU_START time, last GPU_END time, total duration, sum of per-partition GPU times, and partition count
Prints a formatted table with these metrics The script also declares a gpu_intervals list and iterates over gpu_starts with a comment "# Find matching end" followed by pass — an incomplete attempt to compute GPU utilization intervals that was never finished. The output table shows 52 jobs with columns for job number, truncated job ID, start time, first GPU start, last GPU end, total duration, sum of GPU times, partition count, and average GPU time per partition. The first few rows reveal a pattern: Job 1 starts at 55.7s, its first GPU start is at 91.5s, its last GPU end is at 118.2s, giving a total duration of 62.5s with 49.0s of accumulated GPU time across 10 partitions (averaging 4.90s per partition).

The Reasoning and Motivation

Why did the assistant write this particular script in this particular way? The motivation was diagnostic urgency. The benchmark sweep had produced raw throughput numbers — 41.4 s/proof at c=5, 38.7 s/proof at c=10, 38.2 s/proof at c=15 — but these aggregate numbers concealed the internal dynamics. The assistant needed to answer specific questions:

Was the GPU being fully utilized? The Phase 9 architecture already released the GPU lock before b_g2_msm completed, allowing the next worker to start while CPU-side preprocessing finished. But was this overlap actually working? The waterfall table would show the gap between SYNTH_START and GPU_START (the synthesis lead time) and the gap between GPU_START and GPU_END (the GPU kernel time). If GPU_START was significantly delayed after SYNTH_START, it would indicate that workers were queued waiting for the GPU lock — meaning the GPU was the bottleneck.

Was the GPU kernel time stable under load? The Phase 9 single-proof isolation benchmark showed ~32.1s total proof time, but under concurrency the per-proof time inflated to ~38-41s. The waterfall analysis would reveal whether this inflation came from GPU kernel time (suggesting VRAM contention or PCIe bandwidth saturation) or from CPU-side synthesis/preprocessing (suggesting DDR5 memory bandwidth contention).

What was the per-partition GPU time distribution? The script computes gpu_sum by parsing gpu_ms= from each GPU_END event's detail string. This reveals the actual GPU kernel execution time per partition, independent of queuing or scheduling delays. The output shows average GPU times ranging from 4.86s to 4.94s per partition — remarkably stable, suggesting the GPU itself was not the source of variability.

The assistant's choice to write a Python script rather than use existing tooling reflects the ad-hoc nature of the investigation. There were no pre-built waterfall visualization tools — the TIMELINE system was a minimal instrumentation added during development, not a polished observability platform. The assistant had to build the analysis from scratch, and the script's structure reveals what the assistant considered important: job ordering, timing boundaries, GPU time accumulation, and partition counts.

Assumptions Embedded in the Analysis

Every analysis tool makes assumptions, and this ad-hoc Python script is no exception. Several assumptions shaped what the output table would reveal — and what it would conceal.

Assumption 1: Job IDs uniquely identify proofs. The script groups events by job_id and assumes that each job_id corresponds to exactly one proof. This is correct for the cuzk daemon's architecture, where each proof request gets a unique UUID. However, the script does not verify that all events for a job_id are present — a missing GPU_END event would silently drop the job from the output (the script has if not synth_starts or not gpu_ends: continue).

Assumption 2: The CSV format is consistent across all events. The script splits on commas and assumes fields are in fixed positions: [_, offset_ms, event, job_id, ...detail]. This works for the standard TIMELINE format, but the detail field itself may contain commas (e.g., worker=0,partition=8,gpu_ms=...). The script handles this by joining the remaining fields with ','.join(parts[4:]), which is correct.

Assumption 3: SYNTH_START events mark the beginning of a job's lifecycle. The script uses min(synth_starts) as the job start time. This is reasonable because synthesis is the first phase of proof generation. However, it ignores any queue time before synthesis begins — the benchmark output showed queue times of 257-1614 ms per proof, which are not captured in the TIMELINE events.

Assumption 4: GPU_START and GPU_END events are paired. The script collects all GPU_START timestamps and all GPU_END timestamps for each job, but it does not attempt to pair them. The gpu_intervals list is declared and a loop iterates over gpu_starts with a comment "# Find matching end" followed by pass — this is dead code that was never completed. The script uses max(e[0] for e in gpu_ends) as the last GPU end time, which is correct for computing total job duration, but it cannot compute per-partition GPU utilization intervals.

Assumption 5: The benchmark runs are cleanly separable in the TIMELINE data. The script processes all 2,987 events from all four benchmark runs together, producing a single table of 52 jobs. It does not label which jobs belong to which concurrency level. This means the output mixes c=5, c=10, c=15, and c=20 runs, making it difficult to compare behavior across configurations. The assistant would need to manually correlate job counts and timestamps with the known benchmark parameters.

Mistakes and Incorrect Assumptions

Beyond the assumptions above, the script contains several concrete issues that affect the analysis.

The GPU interval tracking is incomplete. The gpu_intervals list is initialized but never populated. The loop for start_t in gpu_starts: # Find matching end; pass does nothing. This was likely intended to compute GPU utilization by tracking when each GPU worker was busy, but the implementation was abandoned mid-edit. The script still produces useful output — it just doesn't compute the GPU utilization percentage that the variable name suggests.

The job count is suspicious. The script reports 52 jobs, but the benchmark runs were: c=5 (5 jobs), c=10 (10 jobs), c=15 (15 jobs), c=20 (20 jobs) — totaling 50 jobs. The extra 2 jobs might be from a warm-up proof or from jobs that spanned the boundary between benchmark runs. The script does not explain this discrepancy, and the output table shows job numbers 1-52 but skips job numbers 4 and 5 (the table shows 1, 2, 3, 6, 7...). This suggests some jobs were filtered out by the if not synth_starts or not gpu_ends: continue guard, possibly because they were still in progress when the log ended.

The table formatting truncates the GPU sum column. The output shows "GPUSum" values like "49.0s" for Job 1, but the column header says "GPUSum" and the values are in seconds. The script computes gpu_sum in milliseconds and divides by 1000 for display, but the column width is fixed at 7 characters, which may truncate values. More importantly, gpu_sum represents the sum of per-partition GPU times, not the wall-clock GPU time. For a 10-partition proof with 4.9s per partition, the sum is 49s, but the wall-clock GPU time is only ~1.8s because partitions run sequentially on the GPU. This distinction is critical for understanding the pipeline's behavior.

The script does not account for the gap between benchmark runs. The 33-minute span includes idle time between the c=5, c=10, c=15, and c=20 runs. The waterfall table shows jobs with start times ranging from 55.7s to well over 1000s, but it does not indicate where one benchmark ended and the next began. This makes it impossible to compare steady-state behavior across concurrency levels without additional timestamp analysis.

Input Knowledge Required

To understand this message, a reader needs knowledge spanning several domains.

CUDA GPU programming concepts: The message references GPU kernel execution, VRAM allocation, cudaDeviceSynchronize, and the distinction between GPU time and CPU time. Understanding why 4.9s of per-partition GPU time sums to 49s but only represents ~1.8s of wall-clock time requires knowledge of how GPU kernels are dispatched and how the proving pipeline serializes partitions.

The cuzk proving pipeline architecture: The message assumes familiarity with the concept of "partitions" — the SUPRASEAL_C2 pipeline splits each proof into 10 partitions, each of which goes through synthesis (CPU), GPU kernel execution, and CPU-side preprocessing (prep_msm, b_g2_msm). The TIMELINE events track these phases, and the script's output implicitly assumes the reader understands what SYNTH_START, GPU_START, and GPU_END represent.

The Phase 9 locking design: The message builds on the discovery that Phase 9 already releases the GPU lock before b_g2_msm completes. The waterfall analysis is motivated by the question of whether this overlap is effective — whether the next worker's GPU_START happens before the previous worker's b_g2_msm finishes.

Python and CSV parsing: The script uses defaultdict, list comprehensions, and string splitting. The reader needs to understand that parts[0] is discarded (the "TIMELINE" literal), parts[1] is the offset in milliseconds, parts[2] is the event type, parts[3] is the job ID, and parts[4:] is the detail.

The benchmark methodology: The message references "c=5 j=5" notation, where c is the number of concurrent proofs and j is the number of concurrent jobs (which equals c in most runs). The c=20 j=15 run used higher concurrency (20 proofs) but limited parallelism to 15 simultaneous jobs.

Output Knowledge Created

Despite its rough edges, this message produces valuable diagnostic knowledge.

The GPU kernel time is stable across jobs. The average GPU time per partition hovers around 4.9s for all visible jobs. This is a crucial finding: the GPU itself is not the source of throughput variability. Whether the system is processing 5 concurrent proofs or 20, each partition's GPU kernel executes in roughly the same time. This rules out VRAM contention, PCIe bandwidth saturation, or GPU compute capacity as the primary bottleneck.

The total job duration varies significantly. Job 1 completes in 62.5s, while later jobs show durations of 66-67s. This 4-5s inflation is the throughput degradation that the benchmark sweep revealed (from ~32s isolation to ~38s under load). The waterfall analysis shows that this inflation is not in GPU time — it must be in CPU-side synthesis or preprocessing.

The gap between SYNTH_START and GPU_START reveals queuing. Job 1's first GPU_START is at 91.5s, while SYNTH_START is at 55.7s — a gap of 35.8s. This is the synthesis time for the first partition plus any queuing delay. Later jobs show similar patterns, and the assistant would later use this data to identify DDR5 memory bandwidth contention as the root cause.

The number of partitions per job varies. Most jobs show 10 partitions, but Job 2 shows only 9. This could indicate a dropped TIMELINE event, a job that was interrupted, or a pipeline variant that uses fewer partitions. This anomaly would warrant further investigation.

The Thinking Process Revealed

The message's structure reveals the assistant's real-time thinking process. The opening line — "Good, 2987 clean events" — is a moment of validation. The exploration task had confirmed the TIMELINE format, and now the data is confirmed to be parseable and complete.

The decision to write a Python script rather than use bash tools (awk, sort, etc.) reflects a preference for structured data processing. The assistant could have used awk to extract per-job metrics, but Python's defaultdict makes grouping by job_id natural and the formatted table output is easier to read than raw CSV.

The incomplete gpu_intervals code is a revealing artifact. The assistant started to implement GPU utilization tracking — computing busy intervals to determine what fraction of wall-clock time the GPU was actually executing kernels — but abandoned it mid-implementation. This suggests either that the assistant realized the computation was more complex than expected (matching GPU_START to GPU_END requires knowing which worker and partition each event belongs to) or that the output table already provided sufficient insight.

The script's output is truncated in the message — the table shows only 6 of 52 jobs before being cut off with "...". This is likely because the full output was long and the assistant only needed to show a sample. The reader (the user) would have seen the full output in their terminal.

Conclusion

Message 2680 is a snapshot of engineering-in-the-moment: a failed optimization has been abandoned, a benchmark sweep has been run, and now the raw data must be transformed into understanding. The ad-hoc Python script is not production-quality code — it has dead code, unhandled edge cases, and assumptions that limit its conclusions. But it serves its purpose: it reveals that GPU kernel time is stable under load, that the bottleneck lies elsewhere, and that the path forward requires investigating CPU-side contention rather than GPU architecture.

This message exemplifies the iterative nature of performance optimization. Phase 10 was a wrong turn, but the response was not to give up — it was to measure more carefully. The waterfall analysis produced by this script would directly inform the Phase 11 design, which targeted DDR5 memory bandwidth contention with three specific interventions: bounding async deallocation to a single thread, reducing the groth16_pool thread count, and adding a lightweight semaphore interlock during the b_g2_msm window. The knowledge created in this single message — that GPU time is stable, that queuing delays dominate, that the bottleneck is CPU-side memory contention — became the foundation for the next round of optimization.

In the end, the most valuable output of message 2680 is not the table of 52 jobs. It is the confirmation that the system is GPU-bounded in the best possible sense: the GPU is running at full speed, and the path to higher throughput lies in feeding it faster, not in redesigning how it works.