Reducing printf call overhead with variadic templates

A few days ago I learned about a cool new project called printpp which is a printf format string preprocessor. It rewrites format strings from brace-delimited format into printf format at compile time. Although the project mentions Python formatting, the only thing they seem to have in common is delimiters.

Great thing about this approach is that it doesn’t add any overhead to printf. For example, the code

int main() {
  pprintf("{} hello {s}! {}\n", 1, "world", 2);
}

where pprintf is a macro defined by pprintpp, compiles to

0000000000400450 <main>:
  400450:       48 83 ec 08             sub    $0x8,%rsp
  400454:       41 b8 02 00 00 00       mov    $0x2,%r8d
  40045a:       b9 04 06 40 00          mov    $0x400604,%ecx
  40045f:       ba 01 00 00 00          mov    $0x1,%edx
  400464:       be 10 06 40 00          mov    $0x400610,%esi
  400469:       bf 01 00 00 00          mov    $0x1,%edi
  40046e:       31 c0                   xor    %eax,%eax
  400470:       e8 bb ff ff ff          callq  400430 <__printf_chk@plt>
  400475:       31 c0                   xor    %eax,%eax
  400477:       48 83 c4 08             add    $0x8,%rsp
  40047b:       c3                      retq

This is very nice in terms of binary code size, but can we do better in terms of performance if we don’t limit ourselves to printf? Notice that the compiler generated a call to __printf_chk. Let’s have a look at this function:

/* Write formatted output to stdout from the format string FORMAT.  */
int
___printf_chk (int flag, const char *format, ...)
{
  va_list ap;
  int done;

  _IO_acquire_lock_clear_flags2 (stdout);
  if (flag > 0)
    stdout->_flags2 |= _IO_FLAGS2_FORTIFY;

  va_start (ap, format);
  done = vfprintf (stdout, format, ap);
  va_end (ap);

  if (flag > 0)
    stdout->_flags2 &= ~_IO_FLAGS2_FORTIFY;
  _IO_release_lock (stdout);

  return done;
}

Unsurprisingly this function does little but call vfprintf. Calling an overload that takes va_list is common for functions that use varargs. Let’s use Google Benchmark to measure the effect of this extra call and vararg processing:

int __attribute__((noinline)) test_vprintf(const char *f, std::va_list) {
  benchmark::DoNotOptimize(f);
  return 0;
}

int test_printf(const char *format, ...) {
  std::va_list args;
  va_start(args, format);
  int result = test_vprintf(format, args);
  va_end(args);
  return result;
}

void varargs(benchmark::State& state) {
  while (state.KeepRunning())
    test_printf("%d", 42);
}

BENCHMARK(varargs);

and let’s compare this to a method of passing formatting arguments via variadic templates implemented in the fmt library:

void __attribute__((noinline)) test_vprint(const char *f,
                                           fmt::format_args) {
  benchmark::DoNotOptimize(f);
}

typedef fmt::BasicFormatter<char> Formatter;

template <typename ... Args>
inline void test_print(const char *format, const Args & ... args) {
  test_vprint(format, fmt::make_format_args<Formatter>(args...));
}

void fmt_variadic(benchmark::State &state) {
  while (state.KeepRunning())
    test_print("{}", 42);
}

BENCHMARK(fmt_variadic);

Note that I’m using the experimental std branch of the fmt library for cleaner C++11 API, but the results should be the same for the stock version which is C++98 compatible.

The test_print function calls make_format_args to place formatting arguments in an fmt::format_args object that is passed to test_vprint. This looks very similar to the printf case but because test_print and fmt::make_format_args are inline, compiler optimizes them away and the effect is that the arguments are placed into fmt::format_args at the caller site. And since fmt::format_args is not parameterized on format argument types, there is no template code bloat.

Running this benchmark on my Early 2015 MacBook Pro gives the following result:

Run on (4 X 3100 MHz CPU s)
2016-11-05 17:32:39
Benchmark                 Time           CPU Iterations
-------------------------------------------------------
varargs                   5 ns          5 ns  133920031
fmt_variadic              2 ns          2 ns  355192920

The fmt_variadic method that uses variadic templates is 2.5 times faster but the absolute difference is just 3ns per call. Does it really matter? To answer this question, let’s compare it to the total formatting time:

void test_sprintf(benchmark::State &state) {
  char buffer[64];
  while (state.KeepRunning())
    std::sprintf(buffer, "%d", 42);
}

BENCHMARK(test_sprintf);

void test_format(benchmark::State &state) {
  while (state.KeepRunning())
    fmt::format("{}", 42);
}

BENCHMARK(test_format);
Benchmark                 Time           CPU Iterations
-------------------------------------------------------
varargs                   5 ns          5 ns  133920031
fmt_variadic              2 ns          2 ns  355192920
test_sprintf             73 ns         72 ns    9571341
test_format              47 ns         47 ns   14373805

As you can see formatting is so fast that even varargs overhead is nontrivial. Using varargs would slow down fmt::format by more than 6% and this is not even the most efficient API fmt provides, because it returns std::string.

The situation becomes even more interesting when you take into account positional arguments. The arguments in va_list can only be accessed sequentially and need to be copied by a printf-like function to an array for efficient access by index.

With variadic templates nothing prevents storing arguments in an array on the caller side and this is exactly what fmt does. The effect is easy to see on this benchmark:

void test_sprintf_pos(benchmark::State &state) {
  char buffer[64];
  while (state.KeepRunning())
    std::sprintf(buffer, "%1$d", 42);
}

BENCHMARK(test_sprintf_pos);

void test_format_pos(benchmark::State &state) {
  while (state.KeepRunning())
    fmt::format("{0}", 42);
}

BENCHMARK(test_format_pos);
Benchmark                 Time           CPU Iterations
-------------------------------------------------------
varargs                   5 ns          5 ns  133920031
fmt_variadic              2 ns          2 ns  355192920
test_sprintf             73 ns         72 ns    9571341
test_format              47 ns         47 ns   14373805
test_sprintf_pos         97 ns         97 ns    7242253
test_format_pos          49 ns         49 ns   13841652

Using positional arguments slows down sprintf by 33% and fmt::format by only 4%.

Of course you don’t get all this performance improvement completely for free. The formatting code

int main() {
  fmt::print("{} hello {}! {}\n", 1, "world", 2);
}

compiles to the following binary code:

$ g++ test.cc -O3 -Lfmt -lfmt -fno-stack-protector
$ objdump -d a.out
...
0000000000401210 <main>:
  401210:       48 83 ec 38             sub    $0x38,%rsp
  401214:       be a2 02 00 00          mov    $0x2a2,%esi # <- type info
  401219:       bf c4 3a 41 00          mov    $0x413ac4,%edi
                                          # <- "{} hello {}! {}\n"
  40121e:       48 89 e2                mov    %rsp,%rdx # <- arg array ptr
  401221:       c7 04 24 01 00 00 00    movl   $0x1,(%rsp) 3 <- 1 (1st arg)
  401228:       48 c7 44 24 10 d5 3a    movq   $0x413ad5,0x10(%rsp)
  40122f:       41 00                     # <- "world" (2nd arg)
  401231:       c7 44 24 20 02 00 00    movl   $0x2,0x20(%rsp)
  401238:       00                        # <- 2 (3rd arg)
  401239:       e8 32 0c 00 00          callq  401e70 <_ZN3fmt5printENS_15BasicCStringRefIcEENS_7ArgListE>
  40123e:       31 c0                   xor    %eax,%eax
  401240:       48 83 c4 38             add    $0x38,%rsp
  401244:       c3                      retq

Since the earlier printpp’s objdump output seem to be obtained with GCC on Linux I use the same platform here to get a meaningful comparison. I also passed -fno-stack-protector to gcc because there was no stack protection code in printpp’s case either.

Compared to printf, fmt::print requires 9 extra bytes to place arguments in the array on stack, 3 more bytes to pass the pointer to the argument array, and 3 fewer bytes due to no return value. So the total difference is just 9 bytes and the number of CPU instructions is the same.

The cool thing is that the type information is effectively passed for free (compared to printf) because it takes the same amount of code as passing the flag argument to __printf_chk.

So replacing varargs with variadic templates may give nontrivial performance improvement if you are willing to accept small increase in binary code. If you want to keep your binaries as small as possible, but still want to enjoy somewhat improved type safety compared to printf, check out pprintpp.

Not relying on printf also facilitates extensibility and, in particular, formatting of user-defined types, but that’s a topic for another blog post.

Benchmarks used in this post are available in the format-benchmark repository (see vararg-benchmark.cc).

comments powered by Disqus