Another slow(er) throw performance case

[mhart]

Even after applying the SetCaptureStackTraceForUncaughtExceptions fix from https://github.com/cloudflare/workerd/issues/5332 I'm still seeing some disparity with Node.js when dealing with thrown objects.

Here's a reproduction:

https://github.com/mhart/throw-microbench

The results from there:

workerd:

{ totalTime: 44.74, throwTime: 41.74 }
{ totalTime: 44.75, throwTime: 41.73 }
{ totalTime: 44.75, throwTime: 41.73 }
{ totalTime: 44.74, throwTime: 41.73 }

node:

{ totalTime: 7.49, throwTime: 5.26 }
{ totalTime: 7.49, throwTime: 5.26 }
{ totalTime: 7.49, throwTime: 5.26 }
{ totalTime: 7.49, throwTime: 5.26 }

I'm wondering if it's exacerbated by tasks running over queueMicrotask – ie, are the call stacks being constructed across queueMicrotask boundaries on workerd, but not on node? And if so, is this (another) v8 setting/config somewhere?

(note there are only 100 queueMicrotask calls in the benchmark)

[mhart]

Comparing profiles, I see a lot more time spent in Throw->ComputeLocation->GetValidTopFrame->Summarize on workerd (12% of the overall profile):

vs on Node.js (0.2% of the overall profile):

[mhart]

The presence of queueMicrotask is definitely pertinent in some way, reducing the amount of effort performed in Node.js

If you remove the queueMicrotask in worker.js (and make remaining something that won't overflow the stack, like 6000), then you can see that Node.js is as slow if not slower than workerd. ie, in the synchronous case it's much slower.

As soon as you introduce queueMicrotask every 500 calls (so only 12 calls overall), Node.js spends 6x less time throwing, but workerd barely changes.

workerd:

Sync:
{ totalTime: 5.05, throwTime: 4.79 }

Async (queueMicrotask every 500 calls):
{ totalTime: 4.99, throwTime: 4.62 }

node:

Sync:
{ totalTime: 6.2, throwTime: 5.98 }

Async:
{ totalTime: 1.28, throwTime: 1.01 }

[jasnell]

so this is our implementation of queueMicrotask... there is some complexity involved.

void ServiceWorkerGlobalScope::queueMicrotask(jsg::Lock& js, jsg::Function<void()> task) {
  auto fn = js.wrapSimpleFunction(js.v8Context(),
      JSG_VISITABLE_LAMBDA((this, fn = kj::mv(task)), (fn),
          (jsg::Lock& js, const v8::FunctionCallbackInfo<v8::Value>& args) {
            js.tryCatch([&] {
              // The function won't be called with any arguments, so we can
              // safely ignore anything passed in to args.
              fn(js);
            }, [&](jsg::Value exception) {
              // The reportError call itself can potentially throw errors. Let's catch
              // and report them as well.
              js.tryCatch([&] { reportError(js, jsg::JsValue(exception.getHandle(js))); },
                  [&](jsg::Value exception) {
                // An error was thrown by the 'error' event handler. That's unfortunate.
                // Let's log the error and just continue. It won't be possible to actually
                // catch or handle this error so logging is really the only way to notify
                // folks about it.
                auto val = jsg::JsValue(exception.getHandle(js));
                // If the value is an object that has a stack property, log that so we get
                // the stack trace if it is an exception.
                KJ_IF_SOME(obj, val.tryCast<jsg::JsObject>()) {
                auto stack = obj.get(js, "stack"_kj);
                if (!stack.isUndefined()) {
                js.reportError(stack);
                return;
                }
                } else {
                }  // Here to avoid a compile warning
                // Otherwise just log the stringified value generically.
                js.reportError(val);
              });
            });
          }));

  js.v8Isolate->EnqueueMicrotask(fn);
}

(excuse the awful formatting imposed by clang-format)

First, we need to allocate a jsg::Function that arranges to have any non-terminal errors that occur reported to the reportError API, then we wrap that in a JS function that is actually scheduled with the isolte task queue.

The reportError handling here might be responsible for the performance issue you're seeing or it might not. It adds another tryCatch into the mix... but notice that it's just using the default v8::TryCatch, not changing anything there like setting verbose, etc. When the error is thrown, however, if it is an object we will extract the stack property (which has a definite cost) and will send that to js.reportError(stack).

What we should try is removing this additional handling in a test benchmark to see what the overall additional overhead of it is. I can explore ways of making it less expensive but this is just about the only way we have available to ensure that errors that occur in queueMicrotask are reliably reported and are therefore debuggable.

One idea I can think of is to make extraction of the stack lazier so that it is not directly in the hot path of executing the microtasks. We can see if js.reportError can reasonably defer the work just slightly to take it out of that path