Async Hook instrumentation significantly increases response time for Promise-heavy calls

[blimmer]

Describe the bug

We noticed a significant increase in response times for GraphQL queries that produce large payloads after we enabled dd-trace for our project.

Here's what we've seen:

Date	Node Version	dd-trace Version	scope Setting	Response Size	Response Time without dd-trace	Response Time with dd-trace	Percentage Increase
8/12/2020	13.14.0	0.20.3	async_hooks	~1.8MB	2.8s	30s	971.4%
8/12/2020	14.8.0	0.24.0	async_local_storage	~1.8MB	2.7s	7.4s	174.1%
8/12/2020	14.8.0	0.24.0	async_local_storage	~150kb	140ms	220ms	57.1%
9/23/2020	14.8.0	0.26.0	async_local_storage	~3.2MB	3.7s	8.7s	135.1%
9/23/2020	14.8.0	0.26.0	noop	~3.2MB	3.7s	3.8s	2.7%
9/23/2020	14.8.0	async_resource branch	async_resource	~3.2MB	3.7s	9.9s	167.6%
9/23/2020	14.8.0	N/A (disabled) const { createHook } = require('async_hooks'); createHook({ init() {} }).enable();	N/A (disabled)	~3.2MB	3.7s	7.4s	100%

As you can see, it looks like async_hooks are the primary reason we see the slowdown, and not necessarily anything specific to dd-trace.

The logic that triggers this especially pronounced behavior uses the following:

• Joist ORM, which uses dataloader under the hood
• TypeScript transpiled code, targetting ES2019, meaning we're using async/await vs. Promise

The query itself produces many promises (I'm unsure of the exact number, but probably in the thousands), which we believe is exacerbating the problem.

I was working synchronously with @rochdev and @stephenh on this issue via the Datadog Slack. He mentioned that he'll add some additional detail to this issue.

Environment

• Operation system: Docker - node:14.8.0 image running on macOS host
• Node version: 14.8.0
• Tracer version: 0.26.0
• Agent version: 7.22.0

[rochdev]

For context, here is a bit of history behind this issue since it's been problematic for a while now.

Historically, context propagation APIs for Node have been using monkey patching on asynchronous code to track the asynchronous context. This approach has been used successfully by APM vendors for many years, even though it didn't support native code and could lose the context in some cases.

When async/await landed, monkey patching was no longer an option so everyone had to switch to async_hooks which is the official construct provided by Node to track the asynchronous context. Even though the module is still experimental to this day, it's the only way currently to do this. This is why it's always been the default implementation used by our scope manager in versions of Node that support it.

The main issue with async_hooks is that it's very heavy when used with promises. This is because the promise hooks exposed by v8 require a jump from JavaScript to native and back for every promise. There has been work done in the past few months to make async_hooks significantly lighter when a destroy hook is not used, for example when using AsyncLocalStorage, but there is still a fair bit of overhead when a lot of promises are created in quick successions. This means that even though we have a new scope manager that no longer relies on the destroy hook, we still incur this overhead.

Since the overhead comes from Node and not from the tracer, and we have to use this feature to support automatic context propagation, this is unfortunately an overhead we can't realistically avoid at the tracer level. It's also worth noting that in most cases, the overhead is low enough that it's not problematic.

In order to fix this completely, we'll have to fix async_hooks in Node itself, and also the corresponding promise hooks in v8. This is not small task and will take a while, but we'll update this issue as progress is done.

[rochdev]

Progress for the v8 change can be tracked here.

[rochdev]

Progress on the Node side can be tracked in nodejs/node#36394

[bengl]

In Node.js v16.2.0, significant performance improvements in async_hooks are present, so if you can test with this version of Node.js, hopefully that alleviates a lot of the overhead.

[artur-ma]

@bengl I dont think there will be any improvement, even worse, I assume there will be some degradation
according to this PR
nodejs/node#36394
when using destroy hook (you are using it), there is some small degradation in performance

Before:

$ ./node-master benchmark/async_hooks/promises.js
async_hooks/promises.js asyncHooks="enabled" n=1000000: 348,189.5714361237
async_hooks/promises.js asyncHooks="enabledWithDestroy" n=1000000: 212,124.80165853762
async_hooks/promises.js asyncHooks="enabledWithInitOnly" n=1000000: 391,763.36348583025
async_hooks/promises.js asyncHooks="disabled" n=1000000: 1,670,456.5232560865

After:

$ ./node benchmark/async_hooks/promises.js  
async_hooks/promises.js asyncHooks="enabled" n=1000000: 1,153,166.7820469614
async_hooks/promises.js asyncHooks="enabledWithDestroy" n=1000000: 207,516.71584447258
async_hooks/promises.js asyncHooks="enabledWithInitOnly" n=1000000: 1,043,624.1457311497
async_hooks/promises.js asyncHooks="disabled" n=1000000: 1,603,204.3180576847

Here u set the destroy hook
https://github.com/DataDog/dd-trace-js/blob/master/packages/dd-trace/src/scope/async_hooks.js#L37

[rochdev]

Here u set the destroy hook

The async_hooks scope manager is only used in old versions of Node. Any recent versions such as latest 12.x, 14.x or 16.x use instead the async_resource scope manager which only uses init.

[stephenh]

Fwiw today we tried bumping to node 16.2.0 to get this perf fix, and are seeing errors in our app that does this ~admittedly somewhat esoteric pattern with async_hooks:

import { AsyncLocalStorage } from "async_hooks";
...
export const currentFlushSecret = new AsyncLocalStorage<{ flushSecret: number }>();
....
currentFlushSecret.run({ flushSecret: this.flushSecret }, async () => {
  // ...call various methods that do...
  const { flushSecret } = currentFlushSecret.getStore() || {};
  // ...and ensure flushSecret is the expected value
  if (flushSecret !== this.flushSecret) {
    throw new Error("invalid usage detected");
  }
});

Where the idea is that only code that is specifically ran within the run callback is allowed to touch/mutate the this / EntityManager instance, and all others mutations will be rejected. Basically we're using it as a hacky thread-local-ish mutex/lock.

Previously this "invalid usage detected" wasn't hit in our application's code, but it is being hit now in our test suite, either insinuating that a) our application code had a bug that node 16.1.0 wasn't catching because this AsyncLocalStorage was propagating a flushSecret when it wasn't supposed to, or b) node 16.2.0 has a regression where AsyncLocalStorage is not propagating flushSecret (to one of the methods invoked directly in, or transitively from, the run callback) when it is supposed to.

The ^ code is part of an open source project:

https://github.com/stephenh/joist-ts/blob/main/packages/orm/src/EntityManager.ts#L202

Although our currently failing tests are in an internal project. If we run the joist-ts public tests on node 16.2.0, they work just fine (and we do have tests that specifically exercise the flush secret behavior), so we don't have a repro yet.

We're going to work more tomorrow on getting a repro done, in the public joist project, and verifying whether it is truly a regression in 16.2.0 or else just a bug/misuse of AsyncLocalStorage (in this joist project) or a big/misuse in our application itself (that is now getting correctly detected).

So, I dunno, this is not a super-useful update yet, but mostly wanted to post as an FYI in case anyone on the datadog/nodejs side of things would look at the AsyncLocalStorage usage and immediately intuit "oh yes we're doing something wrong" or "oh shoot something in the node 16.2.0 change over looked this".

[rochdev]

cc @Qard who would have the most insight to determine at a glance if there could be a regression causing this issue.