Wrap handle callbacks with console.createTask(...)

[Qard]

What is the problem this feature will solve?

Currently stack traces are not great with most callback-based code. Some modules exist to produce long stack traces with async_hooks, however the performance impact can be significant. V8 now has its own built-in solution, so we should investigate if that can produce better results.

What is the feature you are proposing to solve the problem?

A recent V8 update has provided the console.createTask(...) API. We can start pairing that with our existing handle callbacks to gain much better stack traces.

See: #44792

It also has the potential to be integrated with the AsyncContext spec in the future to be used as an equivalent to AsyncResource. This could mean we get context-linkage of callback-based code automatically in the future.

cc @nodejs/diagnostics

What alternatives have you considered?

No response

[Qard]

(Leaving this issue mostly as a note to myself to investigate, but others can feel free to look into it on their own and/or comment here on the idea.)

[targos]

I'd be happy to have a look. What would be a simple example of code that can benefit from it?

[legendecas]

If we run the following script in the latest Chrome:

function makeScheduler() {
  const tasks = [];

  return {
    schedule(f) {
      const task = console.createTask(f.name);
      tasks.push({ task, f });
    },

    work() {
      while (tasks.length) {
        const { task, f } = tasks.shift();
        task.run(f); // instead of f();
      }
    },
  };
}

const scheduler = makeScheduler();
scheduler.schedule(function myTask() {
  console.log(new Error('foo'));
});

setTimeout(() => {
  scheduler.work()
}, 1);

The output of the console should be: (notice that the stacktrace only contains where the task is processed)

Error: foo
    at task (script:21:15)
    at Object.work (script:13:14)
    at script:25:13

However, if we set a breakpoint in the myTask function, the debugger captures the stacktrace when the task is scheduled too. The debuger call stack tab should shows the following call frames:

Error: foo
    at task (script:21:15)
    at Object.work (script:13:14)
    at script:25:13
    myTask (async)      <---  async stack tagged
    at schedule (script:6)
    at script:20

[Qard]

My basic thinking was to have a wrapper something like this:

function makeCallbackTask(name, callback) {
  const task = console.createTask(name);
  return function callbackTask(...args) {
    return task.run(() => callback.apply(this, args));
  };
}

Which could be used to replace this: (https://github.com/nodejs/node/blob/main/lib/fs.js#L230-L231)

  const req = new FSReqCallback();
  req.oncomplete = callback;

with something like this:

  const req = new FSReqCallback();
  req.oncomplete = makeCallbackTask('FSReq', callback);

Basically anywhere that we attach those on* property callbacks onto handle objects we would do an extra step to wrap the callback up as a task.

We would probably want something a bit more performant than making a closure every time, so could be we make a task class or something like that, but this illustrates the general idea.

[targos]

I tried it with a simple script:

const fs = require('fs');

fs.access(__filename, fs.constants.F_OK, () => {
  throw new Error('test')
});

With Node.js 19.8.1:

$ node try.js  
/Users/mzasso/git/nodejs/node/try.js:4
  throw new Error('test')
  ^

Error: test
    at /Users/mzasso/git/nodejs/node/try.js:4:9
    at FSReqCallback.oncomplete (node:fs:185:23)

Node.js v19.8.1

With your suggestion:

$ ./node try.js
/Users/mzasso/git/nodejs/node/try.js:4
  throw new Error('test')
  ^

Error: test
    at /Users/mzasso/git/nodejs/node/try.js:4:9
    at FSReqCallback.<anonymous> (node:fs:186:23)
    at node:fs:238:36
    at FSReqCallback.callbackTask [as oncomplete] (node:fs:238:17)

Node.js v20.0.0-pre

Am I missing something?

[Qard]

From what @legendecas was saying, it will only do the longer stack trace when using the debugger. Just throwing an error will not produce the longer stack trace. A bit less useful than I was hoping. It would be amazing if it could always produce the longer stack trace.

[targos]

I also tried the debugger, and in that case I already got a long stacktrace without even applying the patch (on v19.8.1).

[joyeecheung]

Basically anywhere that we attach those on* property callbacks onto handle objects we would do an extra step to wrap the callback up as a task.

I think even if we implement console.createTask() ourselves (so that we do not rely on the V8 implementation, which only really does anything when the debugger is on), this should probably be opt-in instead of being wrapped by default, since the book-keeping probably comes with a non-trivial cost. In the V8 inspector console implementation it needs to capture the current stack trace and calculate the async chain, which looks non-trivial even implemented internally in V8.

[Qard]

I also tried the debugger, and in that case I already got a long stacktrace without even applying the patch (on v19.8.1).

Ah, could maybe use some clarification then on if there's something we're already doing that is getting us that. Could be it's just only usable for userland then.

Basically anywhere that we attach those on* property callbacks onto handle objects we would do an extra step to wrap the callback up as a task.

I think even if we implement console.createTask() ourselves (so that we do not rely on the V8 implementation, which only really does anything when the debugger is on), this should probably be opt-in instead of being wrapped by default, since the book-keeping probably comes with a non-trivial cost. In the V8 inspector console implementation it needs to capture the current stack trace and calculate the async chain, which looks non-trivial even implemented internally in V8.

Agreed. At the least we should implement such an experiment behind a flag so we can measure perf impact, how successful it actually is at producing these better stack traces, etc.

As I tried to convey in my initial messaging, I haven't looked very closely at this yet. It's as much a note to my future self to see if it's even a reasonable idea as it is a feature suggestion. It sounds like there's possibly some value there, but yet to be seen if it's worth whatever tradeoffs would be needed.

[legendecas]

Yeah, async tasks tracked by async hooks are already reported to the inspector: #13870.

IMO, the point here is that if we should expose console.createTask API to userland, the same as Chrome does.

Updated: It is exposed already.

[Qard]

It already is exposed.

[github-actions]

There has been no activity on this feature request for 5 months and it is unlikely to be implemented. It will be closed 6 months after the last non-automated comment.

For more information on how the project manages feature requests, please consult the feature request management document.