The Hidden Cost of spawn_blocking: Tracing a 1.8s Gap in GPU Proving Performance

In the course of optimizing the SUPRASEAL_C2 Groth16 proof generation pipeline for Filecoin PoRep, a persistent mystery had been eating at the engineering team. The GPU utilization numbers didn't add up. The TIMELINE instrumentation reported an average of 3.7 seconds per partition inside the GPU_START→GPU_END window, but the C++ kernel timing—measuring only the actual NTT, MSM, and batch addition operations—averaged just 1.8 seconds. That left a gap of roughly 1.9 seconds per partition that was unaccounted for, occurring somewhere between the start and end markers but outside the compute kernels. The user had observed that actual GPU compute, visible through power draw and memory activity, appeared to be active only about 50% of the time. Something was swallowing nearly half the GPU time, and nobody knew what.

This is the story of how message [msg 2521] cracked that mystery wide open.

The Message

Here is the message exactly as it appeared in the conversation:

[assistant] Found it! Line 1352: GPU_START is emitted before spawn_blocking. Then inside the blocking task, gpu_prove() is called which includes the entire C++ function — pre-staging, mutex acquisition, kernel execution, cleanup, mutex release, host unregister, AND then the Rust-side proof serialization. GPU_END is emitted after gpu_prove() returns.

>

So TIMELINE gpu_ms includes: pre-staging overhead + mutex acquire + C++ kernels + cleanup + mutex release + host unregister + Rust proof serialization. Plus spawn_blocking scheduling delay.

>

Let me check gpu_prove to see what it does after the C++ call: [grep] fn gpu_prove" No files found

The Investigation Trail

To understand why this message was written, we must trace the investigation that led to it. The team had just implemented Phase 9 of their GPU optimization effort—a PCIe transfer optimization that used cudaHostRegister to pin host memory and enable faster DMA transfers to the GPU. Initial benchmarks showed a 14.2% throughput improvement in single-worker mode, but dual-worker mode revealed new bottlenecks. The user observed that GPU utilization looked closer to 50% than the 90% reported by TIMELINE metrics, and the assistant set out to understand why.

The first hypothesis was that the pre-staging overhead—the cudaDeviceSynchronize, pool trim, cudaMemGetInfo, 12 GiB allocation, and 12 GiB async upload that happened inside the mutex before any kernel ran—was eating the time. The assistant added fine-grained timing instrumentation to the pre-staging path in groth16_cuda.cu and ran a benchmark. The result was surprising: pre-staging took only 12–17 milliseconds per partition, not the ~1.8 seconds that would explain the gap.

This forced a re-examination. The assistant compared gpu_total_ms (measured inside C++ from t_gpu_start to t_tail_msm_end, covering ntt_msm_h_ms + barrier wait + batch_add_ms + tail_msm_ms) against the TIMELINE gpu_ms (measured from GPU_START to GPU_END events). The numbers were stark: C++ kernel time averaged 1,834ms, but TIMELINE reported 3,760ms—a gap of 1,926ms per partition. Something between the event markers was consuming nearly as much time as the actual GPU compute.

The assistant then traced where GPU_START and GPU_END were emitted in the Rust engine code. A grep for GPU_START|GPU_END found matches in /home/theuser/curio/extern/cuzk/cuzk-core/src/engine.rs at lines 1352 and 1366. Reading the surrounding code revealed the critical detail.

The Discovery

Message [msg 2521] is the moment of revelation. The assistant found that GPU_START is emitted at line 1352—before the spawn_blocking call that dispatches the GPU work to a blocking thread. Then, inside that blocking task, gpu_prove() is called, which executes the entire C++ FFI function: pre-staging, mutex acquisition, kernel execution, cleanup, mutex release, host unregister, and then the Rust-side proof serialization. Only after gpu_prove() returns does GPU_END fire.

This means the TIMELINE gpu_ms measurement was never a pure measure of GPU kernel time. It was a measure of everything that happened between dispatching the GPU job and getting the result back, including:

Assumptions and Misconceptions

This discovery exposed several assumptions that had been guiding the investigation:

The TIMELINE events measure what they say they measure. The team had been interpreting GPU_START and GPU_END as brackets around GPU kernel execution. The names suggested that GPU_START fired when GPU work began and GPU_END fired when it finished. In reality, GPU_START fired when the Rust engine dispatched work to a blocking thread, and GPU_END fired when the entire gpu_prove() function returned. The GPU could be idle for significant portions of that window.

The gap must be in the pre-staging path. When the 1.8s discrepancy first appeared, the natural suspect was the new pre-staging code added in Phase 9. The cudaDeviceSynchronize, pool trim, and 12 GiB allocation looked expensive. Adding fine-grained timing proved this assumption wrong—pre-staging was only 14ms. This forced the investigation to look elsewhere.

The C++ kernel timing covers all GPU work. The gpu_total_ms variable was measured from t_gpu_start to t_tail_msm_end, which the assistant initially believed covered all GPU kernel execution. But the gap between this and TIMELINE gpu_ms revealed that significant non-kernel work was happening inside the TIMELINE window.

spawn_blocking is a negligible scheduling detail. The Rust spawn_blocking call is designed to offload blocking work to a dedicated thread pool, but the scheduling delay—the time between when the work is submitted and when a thread actually picks it up—is not zero. At high concurrency with many workers competing for threads, this delay can become significant.

Input Knowledge Required

To fully understand this message, several pieces of context are necessary:

The Phase 9 PCIe optimization. The team had implemented pinned host memory transfers using cudaHostRegister to improve DMA bandwidth. This added pre-staging logic that allocated 12 GiB of GPU memory and uploaded data asynchronously before kernel execution.

The TIMELINE instrumentation system. The engine uses a timeline_event() function that emits structured log events with timestamps, job IDs, and partition details. These events are used to compute per-partition timing metrics like gpu_ms.

The spawn_blocking mechanism. Rust's tokio or futures ecosystem provides spawn_blocking to run blocking operations on a dedicated thread pool without blocking the async runtime. The GPU proving work is dispatched this way because CUDA operations are blocking from the CPU perspective.

The gpu_prove() function. This is the Rust-side function that calls into the C++ FFI to execute the Groth16 proof generation on the GPU. It handles the full lifecycle: acquiring the GPU mutex, calling the C++ groth16_prove function, and then serializing the result.

The architecture of the cuzk proving engine. The engine uses a partition-based approach where each proof is split into 10 partitions, each processed independently. Multiple workers (controlled by partition_workers and gpu_workers_per_device parameters) compete for GPU access through a mutex.

Output Knowledge Created

This message produced several critical insights:

The TIMELINE metrics are misleading for GPU utilization analysis. The gpu_ms metric cannot be used to compute GPU utilization because it includes CPU-side orchestration overhead. True GPU compute utilization requires measuring kernel execution time directly, which the C++ gpu_total_ms provides.

The bottleneck has shifted from GPU compute to CPU orchestration. With kernel time at ~1.8s and total TIMELINE time at ~3.7s, nearly half the per-partition wall time is spent on CPU-side work. This means optimizing GPU kernel performance further would yield diminishing returns—the CPU overhead would become the dominant term.

The spawn_blocking scheduling delay is a real cost. While not measured separately in this message, the discovery that GPU_START fires before spawn_blocking means the scheduling delay is included in gpu_ms. At high concurrency, this could be significant.

Proof serialization is part of the critical path. The Rust-side proof serialization happens inside the TIMELINE window, meaning it competes with GPU work for the CPU's attention. If serialization is expensive, it directly extends the time before the next partition can start.

The investigation must now focus on the Rust-side orchestration. The next steps would involve instrumenting gpu_prove() to measure each phase separately: mutex acquisition time, C++ execution time, and proof serialization time. This would reveal which component dominates the 1.9s overhead.

The Thinking Process

The message reveals a methodical debugging process. The assistant starts with a hypothesis (the pre-staging is the cause of the gap), tests it with instrumentation (pre-staging is only 14ms), and when the hypothesis fails, traces the actual event emission points to understand what the TIMELINE metrics really measure. This is textbook performance debugging: when the numbers don't add up, verify the measurement itself before chasing phantom bottlenecks.

The assistant's thinking is visible in the progression from message [msg 2507] (identifying the gap and blaming pre-staging), through [msg 2517] (discovering pre-staging is negligible), to [msg 2519] (tracing the event emission points), and finally [msg 2521] (the root cause). Each step narrows the search space by ruling out hypotheses with data.

The grep for GPU_START|GPU_END is a pivotal moment—it's the point where the assistant stops guessing and starts reading the source code that produces the measurements. This shift from data analysis to code analysis is what ultimately reveals the truth. The assistant then reads the relevant section of engine.rs to confirm the finding.

The final line—a grep for fn gpu_prove that returns "No files found"—shows the assistant immediately following the thread of the investigation. Having identified that gpu_prove() is the function that contains all the hidden overhead, the next step is to find and instrument it. The "No files found" result is a minor setback (perhaps the function is named differently or lives in a different crate), but the direction is clear.

Implications for the Optimization Effort

This discovery fundamentally changed the trajectory of the optimization work. The team had been focused on GPU-side bottlenecks: PCIe transfer bandwidth, kernel execution time, and memory allocation overhead. The Phase 9 optimization had improved PCIe transfers, but the overall throughput gains were limited because the real bottleneck was elsewhere.

The insight that GPU_START fires before spawn_blocking meant that any optimization that reduced GPU kernel time would only address part of the TIMELINE window. To make meaningful progress, the team would need to either:

  1. Move the GPU_START event to fire after spawn_blocking (fixing the measurement, not the problem)
  2. Reduce the CPU-side overhead by overlapping it with GPU work (the two-lock design that became Phase 10)
  3. Eliminate the spawn_blocking scheduling delay by keeping GPU work on dedicated threads The Phase 10 two-lock architecture that the team designed next was a direct response to this discovery. By using separate mutexes for memory management and compute, they could overlap CPU-side orchestration (allocating memory, uploading data) with GPU kernel execution from a previous partition. This attacked the root cause exposed in message [msg 2521]: the CPU overhead that was serialized inside the TIMELINE window.

Conclusion

Message [msg 2521] is a masterclass in performance debugging. It demonstrates the critical importance of understanding what your instrumentation actually measures, not just what its name suggests. The 1.9s gap that had puzzled the team wasn't a slow operation or a resource bottleneck—it was a measurement artifact caused by GPU_START firing too early. But it was an artifact that revealed a real problem: the CPU-side orchestration overhead was a significant fraction of the per-partition wall time, and optimizing GPU kernel performance alone would never close the gap.

The message also illustrates the value of following the data wherever it leads. When pre-staging turned out to be negligible, the assistant didn't give up or force the data to fit the hypothesis. Instead, they traced the measurement system itself, reading the source code that produced the TIMELINE events. This willingness to question the tools of measurement is what separates effective debugging from guesswork.

For the broader optimization effort, this discovery was a turning point. It shifted the team's focus from GPU kernel optimization to pipeline architecture, leading to the two-lock design that would eventually achieve significant throughput improvements. Sometimes the most important thing a performance investigation can discover is that you've been measuring the wrong thing all along.