DEV Community

Cover image for Where 46 Seconds Go When a g7.4xlarge Worker Starts
Konstantin Tikhaev
Konstantin Tikhaev

Posted on

Where 46 Seconds Go When a g7.4xlarge Worker Starts

A worker in this service starts while somebody is already waiting for it. Not in the abstract: there is a face on a screen, a person has just spoken to it, and until the worker is up, the face says nothing back.

I render that face in real time, twenty-five frames a second, one GPU per session. So "how long does a worker take to start" is not an engineering nicety here. It is the length of the silence.

For a long time the answer was "about forty-five seconds, I think". Nobody had sat down and measured where those seconds went. When I finally did, two runs landed on 45.59 and 46.05 seconds. That agreement was the first useful thing I learned: the number was stable, so it could be attacked.

The machine, because the numbers mean nothing without it

Everything below was measured on a g7.4xlarge: one Blackwell card, 32 GB of VRAM, compute capability sm_120, driver 595.71.05. Storage is a 300 GB gp3 volume at 6000 IOPS and 500 MB/s. One avatar loaded, page cache dropped before each run, on a throwaway bench instance rather than a live one.

Production runs four of these workers on a g7.12xlarge, which is why the per-process numbers further down matter more than the totals: they decide how many sessions fit on a card.

The one exception is the weight-loading benchmark, which I ran on a different box with an RTX PRO 6000 to find the ceiling of the bus rather than of my code. It is marked where it appears.

Here is where all of it went, and what four of the famous levers actually bought when I pulled them.

What forty-six seconds is made of

 0.00 →  8.24   python and torch imports          8.24 s   18%
 8.24 → 11.02   building the renderer models      2.78      6%
11.02 → 23.38   ← the line I labelled wrong      12.36     27%
23.38 → 24.56   remaining weights                 1.18
24.56 → 28.04   face analysis and landmark warmup 3.48      8%
28.04 → 30.80   TRT engines for warp and decode   2.76      6%
30.80 → 40.58   a third-party SDK                 9.78     21%
40.58 → 42.11   avatar template from cache        1.53
42.11 → 45.38   warmups and stream priming        3.27      7%
45.38 → 46.05   reference frame and a small model 0.67
                                                 ──────
                                                 46.05 s
Enter fullscreen mode Exit fullscreen mode

One detail about method, because it cost me a morning. I first tried to stamp these timings from inside the process by wrapping sys.stdout. That misses everything a library writes through its own console handler, and the profile came out full of holes. Stamping from the outside, line by line on a subprocess, gave a profile that added up.

The line I labelled wrong

Look at the third row. Twelve and a third seconds, twenty-seven percent of the whole start, sitting on what I had confidently written down as "deserializing the big engine, 1.36 GB".

It was not that. Deserializing that engine takes between 0.15 and 0.28 seconds. Reading the file from a cold disk adds 4.33 seconds, and on a warm one, 0.59. Nothing close to twelve.

What actually lived in that window was a vendored dependency quietly loading a second audio encoder that nothing downstream ever calls. Its constructor loads the thing unconditionally. Its only consumer appears exactly once in the entire worker: in its own definition.

Dead weight, then, and an easy twelve seconds. I put an environment switch around it and ran the bench again with the cache dropped, one variable changed:

control                     46.67 s
SKIP_UNUSED_ENCODER=1       44.13 s
SKIP_UNUSED_ENCODER=1       44.16 s     health check still 200
Enter fullscreen mode Exit fullscreen mode

Two and a half seconds. Not twelve.

The rest of that window is a shared import that the dead code merely got to first. It costs 7.05 seconds on a cold cache and 0.87 on a warm one, and another component needs it regardless. Deleting the caller does not delete the cost. It just moves it down the profile, where I would have "discovered" it next week and written the same triumphant note.

I keep this one around as a reminder. A profile line is a hypothesis with a timestamp attached, and the label on it is mine, not the machine's.

The snapshot bought thirty seconds, and hid the real bill

The heavy artillery for cold start is checkpointing the process itself: freeze it with its GPU memory intact, thaw it somewhere else. I built that. It works. Same machine, same image, one variable, the restore unit stubbed out for the control:

with snapshot   kernel → both slots green   167 s
cold            kernel → both slots green   197 s
Enter fullscreen mode Exit fullscreen mode

Thirty seconds, for a system that has to be kept alive across driver upgrades and image rebuilds. Worth it or not, that is a real number. But the interesting part is inside the 129 seconds the restore unit spends:

pulling 23 GB of state from object storage   ~115 s
thawing the first process                      14 s
thawing the second                              6 s
Enter fullscreen mode Exit fullscreen mode

The thaw, the exotic part, the part with the clever driver calls, is fifteen percent of it. The rest is a file transfer.

And there is a second reading of the same fact. In the cold control, warming the models took 48 seconds. Warming the models on its own, away from the snapshot, takes far less. The two paths were competing for the same pipe, so the snapshot was partly paying for its own restore twice.

Which pointed at the thing I should have looked at first.

Weights: seventy-six times below the bus

I benchmarked the transfer itself on the second box, the RTX PRO 6000, with six gigabytes of fp16 weights, to find the ceiling of the hardware rather than of my loader:

unpinned host memory   11.22 GB/s
pinned host memory     52.76 GB/s
my loader              0.69 GB/s
Enter fullscreen mode Exit fullscreen mode

Seventy-six times below what the hardware will do, for free, with no exotic infrastructure at all.

The cause was one idiom, repeated in eight places, every one of them written by me, copying the example in a README:

torch.load(path, map_location=lambda storage, loc: storage)   # → host RAM
Enter fullscreen mode Exit fullscreen mode

That lands the tensors in host memory, and then something else copies them to the device afterwards. Five ways of doing the same job, measured end to end:

method time
load to host RAM, then .to(cuda) 12.06 s
torch.load(map_location="cuda") 2.76 s
safetensors straight to device 3.22 s
pinned buffer with async copy 3.37 s
one shared pinned buffer, reused 4.22 s

Nine and a third seconds, from deleting a lambda.

Underneath the totals, the split matters more than the winner. Reading the bytes off disk is 1.3 to 3.3 seconds depending on cache. The transfer to the card is 8.5 to 8.8 of the 12. For years I had been vaguely optimizing the part that was already fast.

Two warnings, both earned.

Parallel reads are not a recipe, they are a property of your storage layer. On my own instances, reading with many threads helps considerably. On the other platform, thirty-two threads took 6.35 seconds against 2.80 sequential, because its filesystem is a network cache and I was fighting it.

And mmap is not free either. It gave the fastest read in the benchmark, 1.26 seconds. On my bench it made deserialization of a large engine five times slower. Faster to open, slower to use.

Precision: a road already taken

Quantization is the first thing everyone suggests, so I asked the engines themselves what precision they were built at, rather than trusting the file names.

engine size precision
renderer, segments A/B/C 0.00 / 0.09 / 0.11 GB HALF
warping and decode 0.20 GB HALF
audio encoder 1.36 GB FLOAT
motion model 0.18 GB FLOAT + INT64

The render path, the hot one, went to half precision long ago. The audio path never did, and my single largest engine is sitting in it. fp8 appears nowhere at all.

So: rebuild the audio encoder smaller. I had thought so before, apparently. There was a half-finished build script sitting on the box, written by me and forgotten, with a comment explaining why bf16 and not fp16: the eight-bit exponent keeps the range of fp32, so layer norm and softmax inside a transformer do not overflow. Sound reasoning. No engine file next to it.

It died twice over, and both deaths are worth knowing.

The tooling moved. The TensorRT version I am on dropped the builder precision flags that script was written against. Getting bf16 now means a different toolchain entirely.

And it would not have bought throughput anyway. That engine is launch-bound: 3.92 milliseconds, flat, whatever you feed it. The cost is in getting kernels onto the card, not in the arithmetic. Smaller numbers do not make a queue shorter.

It would still cut the file in half, and half of 1.36 GB is real cold-start time. But it is a loading win wearing a performance win's clothes, and I nearly filed it in the wrong drawer.

MPS: thirteen percent, and a door it closes

If a single stream cannot fill the card, run several. NVIDIA's Multi-Process Service lets processes share a GPU context instead of taking turns.

Six runs, N independent render processes, real-time budget 40 ms per frame:

processes without MPS with MPS gain
1 16.36 ms, rt 2.44 16.38 ms, rt 2.44 0% (control)
2 32.90 ms, rt 1.22 28.47 ms, rt 1.40 13.5%
3 48.41 ms, rt 0.83 42.92 ms, rt 0.93 11.3%

End to end the card does 61 frames a second without MPS no matter how many processes you point at it, and 70 with it. So MPS is real, and it is thirteen percent, and thirteen percent is not a third live session. I need 1.0 and I reach 0.93. Seven percent short is the most annoying result in this whole article.

Then there is the part I have not seen written down anywhere, which is why I am writing it here. Under MPS, checkpointing the process does not work:

cuda-checkpoint --action lock --pid <worker under MPS>
  → "operation not supported"   rc=1
Enter fullscreen mode Exit fullscreen mode

Blackwell, driver 595.71.05, sm_120. The service has to be off at both ends, at capture and at restore.

So the two levers are mutually exclusive. Pack more sessions onto a card, or bring a session back quickly when a worker dies. Not both. That is not a performance trade-off, it is an availability one, and it belongs on a different page of the spreadsheet than a throughput number does.

MPS carries one more cost that no benchmark shows: the processes now share a server, so one client crashing takes the others with it. Mine had a habit of crashing.

Serverless, as a measuring stick

Before committing further, I measured the floor on a managed GPU platform, to know what I was competing with. I am deliberately not naming it. Fourteen launches is enough to learn something about my own workload and nowhere near enough to characterise somebody's service.

An empty payload, cold:

queue, sandbox and image   5.24 s
import torch               1.51
CUDA init                  0.21
import tensorrt            0.38
one TRT engine + context   0.28
                          ──────
                           7.27 s
Enter fullscreen mode Exit fullscreen mode

Two and a half of those seconds are mine. The other five belong to the floor.

The median cold start across fourteen launches was 4.94 seconds. The minimum was 4.42. The maximum was 20.17, and the queue alone accounted for 18.90 of it. A spread of 356 percent, which in product terms means roughly one visitor in six waits three times longer than the rest, and there is nothing in your code to fix.

The surprise was image weight. I expected a fat image to cost seconds. Bare debian reached my module in 5.58 seconds; a CUDA runtime with torch, 3.58; a CUDA devel image with torch and TensorRT, 3.56. The fat image was not slower. Layers are fetched lazily, so what matters is what you touch, not what you ship.

Two things I was certain of, and wrong about

The volume. My bench disk is created from a snapshot, and volumes like that fetch blocks on first touch. Obviously that inflated the reads. I ran a third pass on a fully warmed volume: 46 seconds again, same as before. The big line was never the disk.

The occupancy. For months I argued that there was nothing to reclaim on the card, because utilization.gpu sat at 97.5 percent. That metric is the fraction of time during which at least one kernel is resident. It says nothing about how full the card is. A single tiny kernel, looping, reports the same 97.5 percent as a card packed to the walls.

The conclusion survived, but on a different measurement: 157 watts drawn out of a 165 watt cap, with the software cap active. Empty blocks do not burn power. I had been right by accident, which is worse than being wrong, because it does not teach you to check.

The order I would try them in now

For a service like mine, with the profile above, in cost order:

  1. Load weights straight to the device. One idiom, eight call sites, 9.3 seconds in the benchmark and 6.3 of the 14.7 spent on weights at startup. No new infrastructure, nothing to operate.
  2. Delete what nobody calls — but measure the deletion, not the profile line. My twelve seconds were two and a half.
  3. Shrink the largest engine, and file it as a loading win, not a speed one.
  4. Checkpointing, if and only if the transfer underneath it is already fast. Otherwise you build a snapshot system to avoid a file copy, and then spend 115 seconds on a file copy.
  5. MPS, last, and only after deciding you will never need fast restore.

Three things were dead ends worth naming, so nobody spends a week on them: lazy CUDA module loading did nothing measurable; green contexts are single-process and I am not; CUDA graphs returned 1.05 to 1.15x at high utilization, which is inside the noise of a bad afternoon.

The broader lesson is duller than I would like. Four of these five levers are famous, and the one that paid best was a keyword argument. I would not have found it without a profile that added up to the total, and the profile was worth less than I thought until I checked what its biggest line actually contained.

What is the largest line in your startup profile, and when did you last open it instead of trusting the label?

Top comments (2)

Collapse
 
raknaos profile image
Raknaos

The mutually exclusive pair is what I'd have missed: MPS gives you 13% and takes cuda-checkpoint off the table, so it isn't a throughput decision at all, it's an availability one. And the honesty about 0.93 against a required 1.0 is rarer than the result itself.

The loader number stays with me too — 0.69 GB/s against 52 on the same hardware, from a map_location lambda copied out of a README. Before you rewrote it, did you ever measure how much of the 115 s object-storage pull was a single-stream read rather than the transfer being slow? That's the part I'd want the distribution for, not just the median.

Collapse
 
remi_etien profile image
Konstantin Tikhaev

No, and you've put your finger on the weak spot of that number. The 115 s was one wall-clock figure for two snapshot pulls (12 GB and 11 GB) with s5cmd at its default settings, and the second pull overlapped a CRIU restore and a parallel read-through of the lazily loaded EBS volume. So it was never a clean transfer measurement, and there's no per-object or per-stream distribution behind it.

What I can add is a later data point on the same instance type, bucket in the same region: 39 GB of zstd tarballs with 64 workers and 16 parts per object landed in 34 s, about 1.15 GB/s. So the pipe wasn't the limit at ~200 MB/s. But that run changed several things at once: object layout, part concurrency, and nothing competing for the disk. I can't honestly split the old 115 s into "single-stream" and "slow transfer" after the fact. On that path the bottleneck has now moved to decompression (79 s), which is where I'd collect the distribution next