TIL putting Box in a hot inner loop can cost you half your runtime

183 points InvadersMustLive 39 comments

One of those "I should have known better" posts but the numbers surprised me enough to write up.

I'm working on murrdb, a small Redis-like cache for ML workloads. The hot path takes an Arrow IPC RecordBatch and flips it from columnar to row-wise layout we later write to RocksDB.

Decoder roughly:

  pub trait ColumnDecoder: Send + Sync {
      fn write_to_row(&self, index: usize, row: &mut WriteRow);
  }

  // one decoder per column, built once per batch:
  let decoders: Vec<Box<dyn ColumnDecoder>> = build_decoders(&schema, &batch);

  for i in 0..n_rows {
      let mut row = WriteRow::new(&segment, key_array.value(i));
      for d in &decoders {
          d.write_to_row(i, &mut row);
      }
      sink(row.into());
  }

One decoder implementation per column type (f32, utf8, etc.), boxed as dyn so I can put them in a Vec, very ergonomic and idiomatic. The bench writes 1M rows across 10 f32 columns, which I expected to be fast given how little real work the encoder is doing per row.

Instead I got ~30 Melem/s, which felt low, so I threw it under perf record expecting to see memcpys or allocator overhead at the top of the report. What I actually got was this

  38.64%  <Decoder<T> as ColumnDecoder>::write_to_row
  23.92%  criterion::Bencher::iter 

The second line confused me until I opened the annotated disassembly and saw that 43% of iter's self-time was just one instruction:

 2e4001:   call   *0x18(%rax)

That call is the vtable indirection into write_to_row, which means the dyn dispatch is eating about 48% of the whole bench once you combine the body's own time with the call site itself!

The body is where it gets interesting. It's roughly 25 instructions of completely trivial work: null check, flip a bit in the bitset, move four bytes. No single instruction in the body crosses 7% of
self-time. What dominates instead is the function prologue and epilogue, which between them eat about 25% of the function's wall-clock cost.

The reason is straightforward in retrospect:

  • The body is tiny and gets called 10 million times through a vtable.
  • The compiler cannot inline across that boundary, cannot fuse the inner loop, cannot vectorize the f32 stores, so every iteration pays the full function-call tax (indirect jump, ABI dance, register saves, prologue, epilogue) to do about three byte writes of useful work.

So TLDR: your Box<dyn> is an inlining barrier. When the method body is small enough to amortize against, virtual function call overhead becomes a massive slice of your runtime.

As I'm coming from the Java world where JVM is smart enough to de-virtualize and inline calls across such a boundary, this situation made sad and miss managed runtimes a little.