Strange performance hiccups in V8 with vsnprintf()

[evanw]

Compiling the following code:

#include <emscripten.h>
#include <stdio.h>
#include <stdarg.h>

static int iteration = 0;

static double now() {
  return EM_ASM_DOUBLE({
    return performance.now();
  }, 0);
}

static void test(const char *format, ...) {
  static char buffer[512];

  double start = now();
  va_list args;
  va_start(args, format);
  vsnprintf(buffer, sizeof(buffer), format, args);
  va_end(args);
  double total = now() - start;

  if (total > 1) {
    printf("iteration %d: %.1fms\n", iteration, total);
  }
}

int main() {
  while (iteration++ < 100000) {
    test("");
  }
  printf("done\n");
  return 0;
}

with the command emcc -O1 -fno-rtti -fno-exceptions temp.c -o temp.js and opening the web page <script src="temp.js"></script> in Chrome (stable and canary) gives the following console output:

iteration 1: 5.7ms
iteration 598: 8.0ms
iteration 3063: 180.3ms
iteration 35189: 8.6ms
iteration 37657: 171.8ms
iteration 70780: 8.2ms
iteration 73207: 171.0ms
iteration 106799: 8.4ms
iteration 109271: 172.5ms
iteration 141731: 8.5ms
iteration 144159: 170.2ms
iteration 177855: 8.4ms
iteration 180296: 169.2ms
iteration 217022: 168.7ms
iteration 251655: 8.7ms
iteration 254115: 170.9ms
iteration 287883: 8.6ms
iteration 290350: 172.7ms
iteration 324183: 8.3ms
iteration 326610: 172.8ms
iteration 360437: 8.3ms
iteration 362870: 176.5ms
iteration 396508: 8.2ms
iteration 398983: 173.7ms
iteration 430299: 8.3ms
iteration 432744: 175.3ms
iteration 466987: 8.3ms
iteration 469445: 176.0ms
done

Calling vsnprintf(), even on an empty string, periodically causes delays of up to 175ms. This means that calling vsnprintf() anywhere in a rendering loop with -O1 is catastrophic for performance. It's not an issue in Firefox, only in Chrome. This wasn't an issue with older versions of emscripten because vsnprintf() was implemented in JavaScript.

[evanw]

It looks like all of the time is being spent in the first call to printf_core() inside MUSL_vfprintf(). Running chrome with --js-flags="--trace-opt --trace-deopt --trace-bailout" gives output that indicates printf_core() is being constantly recompiled:

...
[marking 0x34a760fd <JS Function _printf_core (SharedFunctionInfo 0x34a42a09)> for recompilation, reason: not much type info but very hot, ICs with typeinfo: 73/2873 (2%)]
[marking 0x34a760fd <JS Function _printf_core (SharedFunctionInfo 0x34a42a09)> for recompilation, reason: not much type info but very hot, ICs with typeinfo: 73/2873 (2%)]
[marking 0x34a760fd <JS Function _printf_core (SharedFunctionInfo 0x34a42a09)> for recompilation, reason: not much type info but very hot, ICs with typeinfo: 73/2873 (2%)]
[marking 0x34a760fd <JS Function _printf_core (SharedFunctionInfo 0x34a42a09)> for recompilation, reason: not much type info but very hot, ICs with typeinfo: 73/2873 (2%)]
[marking 0x34a760fd <JS Function _printf_core (SharedFunctionInfo 0x34a42a09)> for recompilation, reason: not much type info but very hot, ICs with typeinfo: 73/2873 (2%)]
[marking 0x34a760fd <JS Function _printf_core (SharedFunctionInfo 0x34a42a09)> for recompilation, reason: not much type info but very hot, ICs with typeinfo: 73/2873 (2%)]
[marking 0x34a760fd <JS Function _printf_core (SharedFunctionInfo 0x34a42a09)> for recompilation, reason: not much type info but very hot, ICs with typeinfo: 73/2873 (2%)]
[marking 0x34a760fd <JS Function _printf_core (SharedFunctionInfo 0x34a42a09)> for recompilation, reason: not much type info but very hot, ICs with typeinfo: 73/2873 (2%)]
[marking 0x34a760fd <JS Function _printf_core (SharedFunctionInfo 0x34a42a09)> for recompilation, reason: not much type info but very hot, ICs with typeinfo: 73/2873 (2%)]
[marking 0x34a760fd <JS Function _printf_core (SharedFunctionInfo 0x34a42a09)> for recompilation, reason: not much type info but very hot, ICs with typeinfo: 73/2873 (2%)]
...

This is strange because I would think that printf_core() is receiving the exact same inputs every time, in which case the type information shouldn't be changing at all. Is this a known issue with emscripten output of certain functions?

[juj]

Oh, wow! I would recommend raising this on Chromium tracker and referring here. This is the first time I hear of a relatively small asm.js function getting constantly recompiled, although I haven't used the js debugging flags on Chrome in a long time to debug. Let's see what their developers say.

[evanw]

Chromium issue added: https://code.google.com/p/chromium/issues/detail?id=415788.

[kripken]

Side note, you can just call emscripten_get_now, that would be faster than using EM_ASM to run performance.now. But it doesn't make much of a difference here.

Another side note, building with -O2 instead of -O1 makes this much better in chrome. However, even there pauses show up (over 30ms over here, which is enough to miss two frames at 60fps).

[stale]

This issue has been automatically marked as stale because there has been no activity in the past 2 years. It will be closed automatically if no further activity occurs in the next 7 days. Feel free to re-open at any time if this issue is still relevant.