Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Report async tasks to V8 Inspector #13870

Closed
wants to merge 5 commits into from

Conversation

bajtos
Copy link
Contributor

@bajtos bajtos commented Jun 22, 2017

Implement a special async-hook listener that forwards information about async tasks to V8Inspector asyncTask* API.

Fixes: #11370

screen shot 2017-06-22 at 11 14 09

Note: this is an initial (incomplete) version to gather feedback early.

Here are few important items that I would like to discuss besides whatever other feedback you can provide:

  • Test coverage. Ideally, we should cover most/all major scenarios, not only setTimeout and Promises. OTOH, I'd rather avoid duplicating all async_hook/async_wrap tests, because that would add too much maintenance burden IMO. Initially, I added only two simple tests - one for promises, the second one for setTimeout. What other scenarios should I add?

  • Test assertions. Right now, the tests are only checking whether async stack information is present, the correctness of this information is not verified. Do we want the tests to verify it?

  • How to enable/disable inspector async hook when the inspector is started/stopped? I think it's important to enable this hook only when debugging in order to avoid the performance costs of async hooks. However, I was not able to find the right place where to add enable/disable call. Can anybody point me to the right direction please?

There are two test failures right now, I believe they are caused by the fact that inspector async hook is always enabled, while the tests are relying on the async hook machinery to be disabled by default.

People that may be interested in reviewing these changes, based on the git history (the list is almost certainly incomplete):
@trevnorris @addaleax @AndreasMadsen @matthewloring @eugeneo

Checklist
  • make -j4 test (UNIX), or vcbuild test (Windows) passes
  • tests and/or benchmarks are included
  • documentation is changed or added
  • commit message follows commit guidelines
Affected core subsystem(s)

async_hooks, async_wrap, inspector

@nodejs-github-bot nodejs-github-bot added async_hooks Issues and PRs related to the async hooks subsystem. async_wrap c++ Issues and PRs that require attention from people who are familiar with C++. inspector Issues and PRs related to the V8 inspector protocol labels Jun 22, 2017
@addaleax addaleax added the wip Issues and PRs that are still a work in progress. label Jun 22, 2017
Copy link
Member

@addaleax addaleax left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

/cc @nodejs/async_hooks @nodejs/v8-inspector

if (!args[2]->IsBoolean())
return env->ThrowTypeError("third argument must be a boolean");

Local<String> taskName = args[0]->ToString(env->context()).ToLocalChecked();
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Since you already checked args[0]->IsString(), there’s no need for an explicit cast here; you can just use taskName = args[0].As<String>().

String::Value taskNameValue(taskName);
StringView taskNameView(*taskNameValue, taskNameValue.length());

int64_t taskId = args[1]->IntegerValue(env->context()).FromJust();
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Same here, .As<Integer>()->Value() should be fine instead of a cast.

Also, intptr_t?


int64_t taskId = args[1]->IntegerValue(env->context()).FromJust();
void* task = reinterpret_cast<void*>(taskId);
bool recurring = args[2]->BooleanValue();
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If you use BooleanValue(), you’ll want the overload that takes a context argument like above (but again, no need for casting; I’m going to stop commenting that now).

@@ -527,6 +527,28 @@ class NodeInspectorClient : public v8_inspector::V8InspectorClient {
return channel_.get();
}

// Async stack traces instrumentation.
void AsyncTaskScheduled(const StringView& taskName, void* task,
bool recurring) {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Style nit: Can you align the arguments vertically?


// TODO(bajtos): enable the hook when Inspector is started,
// disable it when Inspector is stopped
inspectorHook.enable();
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think this code might be better in lib/inspector.js?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I definitely like the idea here but we should definitely ask the question: should this be turned on by default or on demand only? Should there be an API for disabling it if it is on by default?

I'd vote for on by default, no api for disabling.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

IMO, the hook should be always enabled when debugging with no public API to control this hook. By default, the hook should be disabled. When the Inspector is started, the hook should be enabled. When the Inspector is stopped, the hook should be disabled.

The reason why this is not implemented in my patch yet, is that I haven't figured out how to make that happen.

Here is my current thinking:

  • I'll move the hook to lib/internal/inspector-async-hook.js and export the hook returned by createHook.
  • Then I need to access this exported hook (a javascript object) from src/inspector_agent.cc - how to do this?
  • Agent::Start should call enable on the exported hook
  • Agent::Stop should call disable on the exported hook

Thoughts?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

For accessing the hook; you could set up 2 persistent Function properties on the Environment (like the async_hooks_blah functions in env.h), then add a binding method to the inspector module/inspector_agent.cc that takes two parameters and sets the fields on the Environment accordingly.

One of these functions would be basically () => hook.enable(), the other () => hook.disable(). You could then grab those methods in Agent::Start or Agent::Stop off the Environment instance.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@addaleax Thank you, this make sense. There is one missing piece - where to place the JS code glueing this all together. I think it should go to lib/internal/bootstrap_node.js, right?

Since the environment always have an instance of inspector Agent, I feel it's better to setup these two persistent Functions properties on Agent class instead. What do you think, can you foresee any issues with that?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There is one missing piece - where to place the JS code glueing this all together. I think it should go to lib/internal/bootstrap_node.js, right?

@bajtos I guess? Maybe just do it that way for now and see whether somebody has anything to comment on that.

Since the environment always have an instance of inspector Agent, I feel it's better to setup these two persistent Functions properties on Agent class instead. What do you think, can you foresee any issues with that?

Not really, but I’m not as familiar with the inspector’s semantics as with the rest of the C++ code. It’s a bit easier to do it on the environment because there are already quite a few of these that can be accessed in a standard way.

env->SetMethod(target, "asyncTaskScheduled", AsyncTaskScheduled);
env->SetMethod(target, "asyncTaskCanceled", AsyncTaskCanceled);
env->SetMethod(target, "asyncTaskStarted", AsyncTaskStarted);
env->SetMethod(target, "asyncTaskFinished", AsyncTaskFinished);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Same here, I think it would be better to keep this code in the inspector cc files?

@bajtos
Copy link
Contributor Author

bajtos commented Jun 22, 2017

@addaleax hey, that was fast, thank you for the review! I fixed the coding style issue you have pointed, see the two new commits above.

Regarding where to keep the AsyncTask-related code: I guess it makes sense to move the C++ stuff from src/async_wrap.cc to src/inspector_agent.cc.

However, I am not so sure about moving the javascript part to lib/inspector.js. lib/inspector.js is not loaded by Node.js at startup time, therefore my async_hook is not enabled and the whole thing breaks. Also according to the docs, the inspector module provides an API for interacting with the V8 inspector. The code I am adding is not for interacting with the V8 inspector, but it's a necessary integration between Node.js/libuv and V8.

Thoughts?

@bajtos
Copy link
Contributor Author

bajtos commented Jun 22, 2017

Should I perhaps place the JS part into lib/internal/inspector.js?

String::Value taskNameValue(taskName);
StringView taskNameView(*taskNameValue, taskNameValue.length());

intptr_t taskId = args[1].As<Integer>()->Value();
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Style issues: snake_case, not camelCase, for locals.


intptr_t taskId = args[0].As<Integer>()->Value();
env->inspector_agent()->AsyncTaskFinished(reinterpret_cast<void*>(taskId));
}
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You could DRY these a little by using a template function. As well, this probably needs to be inside a #if HAVE_INSPECTOR guard. ./configure --without-inspector should build/work.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You could DRY these a little by using a template function

Good point. I am not sure if I understand your idea correctly, I was able to DRY these functions with a helper function that does not require any template:

static void invokeAsyncTaskFnWithId(void (Agent::*asyncTaskFn)(void*),
                                    const FunctionCallbackInfo<Value>& args);

Strangely enough, now that I moved this code from src/async-wrap.cc to src/inspector_agent.cc, ./configure --without-inspector seems to work fine even with not #if HAVE_INSPECTOR guard. Perhaps src/inspector_agent.cc is excluded from compilation? Having said that, I'll probably need to modify the javascript part.

@addaleax
Copy link
Member

Should I perhaps place the JS part into lib/internal/inspector.js?

That seems perfectly fine to me. 👍

if (!args[1]->IsNumber())
return env->ThrowTypeError("second argument must be a number");
if (!args[2]->IsBoolean())
return env->ThrowTypeError("third argument must be a boolean");
Copy link
Member

@jasnell jasnell Jun 22, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If these errors are intended to be seen by end users:

(a) it would be better if the type checking were done in js land if possible
(b) it would be better if they used named arguments rather than "first argument", "second argument", etc

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

These errors should be never seen by the user as long as async hooks work correctly. These methods are invoked by our own async hook listener from the methods invoked by async hooks (init, before, etc.).

(a) it would be better if the type checking were done in js land if possible

The values are coming from the async_hook module. I could add a type check to my async hook callbacks (init, before, etc), but that seems too defensive to me - do we really need to worry about async_hooks not honoring their API contract?

Even if we check the types in js land, I think it's still a good idea to check them in C++ land too, so that we don't crash the process (I assume that V8 will crash the process when we try to cast a JS value to an incompatible C++ type)..

(b) it would be better if they used named arguments rather than "first argument", "second argument", etc

Good point, I'll reword the messages 👍

String::Value taskNameValue(taskName);
StringView taskNameView(*taskNameValue, taskNameValue.length());

intptr_t taskId = args[1].As<Integer>()->Value();
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

args[1]->IntegerValue(env->context()).ToChecked()

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@jasnell Huh? Even if typechecking is moved to JS, this should be correct (as long as the typechecking does its job).

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Correct yes, I just prefer the other style.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am not very familiar with V8 API and the style preferred in Node.js codebase, I am happy to follow whatever direction you agree on.


intptr_t taskId = args[1].As<Integer>()->Value();
void* task = reinterpret_cast<void*>(taskId);
bool recurring = args[2].As<Boolean>()->Value();
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

args[2]->BooleanValue(env->context()).ToChecked()

Environment* env = Environment::GetCurrent(args);

if (!args[0]->IsNumber())
return env->ThrowTypeError("first argument must be a number");
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Same as above. It would be preferable if the type checking was done in js land if possible, and this should use a named argument.

@eugeneo
Copy link
Contributor

eugeneo commented Jun 22, 2017

@ak239 - please take a look.

@bajtos
Copy link
Contributor Author

bajtos commented Jun 23, 2017

Thank you all for your feedback! I cleaned up the code based on your suggestions:

  • improved assertion messages
  • added as shared C++ method for invoking AsyncTask* functions with a single taskId argument
  • moved the hook implementation to lib/internal/inspector_async_hook.js

Next step for me: enable/disable the hook from inspector agent, per @addaleax suggestion in #13870 (comment)

A possible next step for you, the reviewers: reach a consensus on what style I should use for converting arguments from JS to C++ (see #13870 (comment)), and where to check/assert the type of these arguments (see #13870 (comment)).

@addaleax
Copy link
Member

A possible next step for you, the reviewers: reach a consensus on what style I should use for converting arguments from JS to C++ (see #13870 (comment)), and where to check/assert the type of these arguments (see #13870 (comment)).

As for typechecking, I think the idea was to if (…) throw errors.TypeError(); in JS land in any case (and I’m okay with that).

After that, you can just use arg->IntegerValue(ctx).FromJust(), it’s fine by me (but for the record, if you don’t know that arg is a number that potentially does much more complex work than arg.As<Integer>()->Value()).

Copy link
Member

@alexkozy alexkozy left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks a lot!

const helper = require('./inspector-helper');
const assert = require('assert');

const script = 'Promise.resolve().then(() => { debugger; });';
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Inside of V8 we have own promise instrumentation, which is partially based on V8 async hooks, I'm not sure how these two instrumentations will live together, can we check msg.params.asyncStackTrace content in this test?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good point. I am aware of V8 own promise instrumentation, I think this is the relevant code:

// Async task events from Promises are given misaligned pointers to prevent
// from overlapping with other Blink task identifiers.
void* task = reinterpret_cast<void*>(id * 2 + 1);
void* parentTask =
parentId ? reinterpret_cast<void*>(parentId * 2 + 1) : nullptr;

  void* task = reinterpret_cast<void*>(id * 2 + 1);
  void* parentTask =
      parentId ? reinterpret_cast<void*>(parentId * 2 + 1) : nullptr;

IIUC, this is assigning odd numbers to async tasks related to promises. It makes me wonder whether I should assign even numbers to async tasks coming from Node.js async_hooks, to avoid the situation where the same async task id is used by built-in Promise instrumentation and by Node.js async_hooks based instrumentation?

void * task = reinterpret_cast<void*>(id * 2 + 0); // or (id << 1)

I'll double check what stack trace is reported by Promises now and beef up the assert in this test. I believe that right now, Promises call asyncTaskStarted/Finished twice - once from built-in V8 instrumentation, second time from the new async_hooks code.

We may be able to detect when async_hooks callback was invoked for a promise event and don't call asyncTask* API in that case, but I am not sure if it's needed and worth the effort?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think our current approach for promises are very similar with Node.js approach so in worst case we'll call v8inspector instrumentation twice. Instrumentation on our side is faster because it doesn't need to go through additional Node.js layer. So I think it's better to detect when async_hooks called for promise and filter it here then filter it on inspector side or call it twice.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If you don't mind, I'd rather avoid filtering out async_hook events triggered for promises, simply because I don't see a reliable way how to detect them. The only async_hook information I have is a string-based type.

I wrote a simple program to verify what happens when both Node.js and V8 report asyncTask for the same promise:

setInterval(() => {
  Promise.resolve().then(() => {
    debugger;
    console.log('tick')
  });
}, 300);

Things seems to work well with the current implementation, see the screenshot below (my test file is called x.js):

screen shot 2017-07-13 at 18 24 04


function runTests(harness) {
// Wait for the child to start running the script
setTimeout(() => run(), 1000);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is it common way in Node.js to wait 1 sec or we can get some notification when child process is ready?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Actually, the timeout should not be needed now. The code setting up the inspector session seems to handle this wait already. I'll remove the timeout shortly.

const helper = require('./inspector-helper');
const assert = require('assert');

const script = 'Promise.resolve().then(() => { debugger; });';
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

And can we add a test where we create one promise and then have two different chained callback:
function foo() { debugger; }
var p = Promise.resolve();
p.then(foo);
p.then(foo);
And check that we have correct stacks on both breaks.

if (!args[0]->IsNumber())
return env->ThrowTypeError("taskId must be a number");

intptr_t task_id = args[0].As<Integer>()->Value();
Copy link
Member

@alexkozy alexkozy Jun 23, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It's not declared anywhere but in inspector we assume that when other clients use our asyncTask* API they use real pointers, or at least something aligned like real pointer, in general it means that your task_id should always be even, you can just multiply it by 2 here.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Will do, I was already thinking about this in #13870 (comment).

if (!Number.isInteger(asyncId))
throw new errors.TypeError('ERR_INVALID_ARG_TYPE', 'asyncId', 'integer');
if (typeof type !== 'string')
throw new errors.TypeError('ERR_INVALID_ARG_TYPE', 'type', 'string');
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don’t think these necessary, you can just do thingslike CHECK(args[0]->IsString()); in C++; it’s a bit shorter, and I think that if type is ever not a string that’s an internal error in Node, so it should hard crash rather than throwing an exception.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I added these lines based on the feedback from you and @jasnell:

As for typechecking, I think the idea was to if (…) throw errors.TypeError(); in JS land in any case (and I’m okay with that).

Having said that, I agree that if type is not a string then it's an internal Node.js error, and I am fine with crashing the process. I'll make the changes you are proposing.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah, sorry – I didn’t realize the binding methods were only called from other internal code.


// Integration with V8 Inspector AsyncTask* API
// FIXME(bajtos) move this code to src/inspector_agent.cc
// Agent::Start() should enable the hook, Agent::Stop() should disable it
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I would consider this FIXME a blocker for this PR, let me know if you need any help with it.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Agreed.

I have been looking into this issue in the past days, the problem is more complex than I initially thought. Typically Agent::Start is called directly from node::Start, long time before bootstrap_node.js is loaded. When debugging via --inspect-brk, bootstrap_node.js is not started until a debugger is attached.

One option is to enable the hook at the time when a client connects (in Agent::Connect), plus defer hook enablement until bootstrap_node.js is called in case of --inspect-brk, because in case of --inspect-brk, the client connects before we can create the inspector async hook. However, I find the user experience of this solution rather poor. Because async stack trace tracing is enabled only at the time the debugger connects, any async transitions created at startup time (e.g. like setting up an HTTP server, creating timeouts, etc.) are lost.

Here is my current plan:

  • Somewhere in src/node.cc, set a flag that can be used by lib/internal/inspector_async_hook to decide whether the hook should be enabled at Node.js start/boot time. This should nicely handle both --inspect and --inspect-brk cases, as long as Node.js bootstrapping process stays synchronous.
  • At the same time, in order to support process._startDebug, I'll still need to pass the "enable" function into C++ land, so that we can enable the hook at runtime when the debugger was enabled via a signal (_startDebug).

I estimate I'll need few more days to finish this, and since I am on vacation next week, I may not be able to push the update until the week of July 10th.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@bajtos

Typically Agent::Start is called directly from node::Start, long time before bootstrap_node.js is loaded. When debugging via --inspect-brk, bootstrap_node.js is not started until a debugger is attached.

To rephrase the issue, you can't create a hook until after bootstrap_node.js has run, and this is an issue with --inspect-brk because the hook won't be in place in time.

I find the user experience of this solution rather poor. Because async stack trace tracing is enabled only at the time the debugger connects, any async transitions created at startup time (e.g. like setting up an HTTP server, creating timeouts, etc.) are lost.

If you were to add a setupInspectorHook() as the first call to startup() in lib/internal/bootstrap_node.js it would force the hook to be enabled before any possible asynchronous tasks are performed.

At the same time, in order to support process._startDebug, I'll still need to pass the "enable" function into C++ land, so that we can enable the hook at runtime when the debugger was enabled via a signal (_startDebug).

To double check, this wouldn't start capturing async stack traces until after the process has been signaled, but on the same note does Chrome always record all async stack traces so they are always available after the inspector connects?

throw new errors.TypeError('ERR_INVALID_ARG_TYPE', 'asyncId', 'integer');
if (typeof type !== 'string')
throw new errors.TypeError('ERR_INVALID_ARG_TYPE', 'type', 'string');
// TODO(bajtos): support recurring tasks like setInterval
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Am I correct to assume that https://v8docs.nodesource.com/node-8.0/df/d37/classv8__inspector_1_1_v8_inspector.html is the most “documentation” we get for the V8 inspector API? If yes, I am not sure how we would want to use it to report recurring tasks… it’s not just setInterval, it’s a lot of things that create multiple events (TCP/UDP servers, file streams, zlib, etc.).

Copy link
Member

@AndreasMadsen AndreasMadsen Jun 28, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What is the consequence if we just set it to true for all event types?

Using false does not make sense because of setInterval etc.. But even for setInterval it can't be guaranteed that it will be recurring, thus true should always work. I guess it will just be a bit inefficient.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am not aware of any better documentation than the source code. I don't have any strong opinion on what's the best value to use, I am ok with using true.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

As long as Node.js calls asyncTaskCanceled, using recurring = true is fine.

Copy link
Contributor

@trevnorris trevnorris left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Biggest blocker I see is the usage of intptr_t on 32bit builds. Hopefully I'm overlooking something that won't make that a problem.

},

destroy(asyncId) {
if (!Number.isInteger(asyncId))
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The only way this could fail is if the hook callbacks are being called manually. Otherwise it's guaranteed that
asyncId > 0 && Number.isInteger(asyncId). Same with type above that it guarantees
typeof type === 'string' && type.length > 0

String::Value taskNameValue(taskName);
StringView taskNameView(*taskNameValue, taskNameValue.length());

intptr_t task_id = args[1]->IntegerValue(env->context()).FromJust();
Copy link
Contributor

@trevnorris trevnorris Jun 29, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks like you're using intptr_t because of the conversion to an even void*, but I believe this will fail quickly on 32bit builds b/c INTPTR_MAX == 2147483647 while asyncId is internally stored as a double. You could test this out by the following:

'use strict';
const { async_uid_fields, constants: { kAsyncUidCntr }} = process.binding('async_wrap');
const { newUid } = require('async_hooks');

async_uid_fields[kAsyncUidCntr] = -1 >>> 1;
process._rawDebug(newUid() > -1 >>> 1);

Use this code along with calling AsyncTaskScheduleWrapper() on a 32bit build.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@trevnorris Do you have any alternative suggestions? The inspector API doesn’t seem to allow anything more flexible here. I would be okay with just accepting this as a limitation.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We should get help from @nodejs/v8-inspector to make this more flexible. Ideally, it would support an arbitrary 64bit id.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@addaleax

I would be okay with just accepting this as a limitation.

Creating a new id every μs would cause this to run out in under 20 mins. I'm at a loss to see how we can word around this limitation and have this remotely functional.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@trevnorris Not sure, my math seems to give us about 35 minutes ;) My thoughts are more in the line of: 32-bit systems are getting rarer, esp. for developers, and processes that actually create async IDs at that rate are probably not the ones that get debugged most frequently. Plus, no 32-bit system could actually handle that many async resources at a time; it’s likely that most stack traces would still be accurate.

I’ll try to figure out how to bring the inspector source code to support a larger range of values; it seems pretty doable, I may be able to get a PR up today.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Copy link
Member

@alexkozy alexkozy Jul 7, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm not sure that on inspector side we'd like to support arbitrary taskId:

On Inspector side we are trying to limit async stack traces memory usage, we dedup frames, stacks and limit maximum amount of async stacks which can be stored at particular moment of time (currently it's 128*1024). We cleanup old stacks first, so it means that at moment when Node.js reports 128*1024 + 1 stack we already collected stack trace with id 1. So it means that 2^31 different async task ids should be enough (actually 2^16 should be enough). Node.js can just use nodejs_id % 2^31 as id for inspector. We can land this CL later when we figure out how we can effectively avoid cleanup of old stacks but it probably would mean that async stack implementation is moved to V8 and enabled by default not only during debugging.

(edited by @TimothyGu to fix Markdown)

};

exports.startNodeAndDebuggerViaSignal = function(callback, scriptContents) {
const args = ['-e', `${scriptContents}\nconsole.error('started');`];
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Might want to use process._rawDebug instead of console.error because the latter will trigger an async event.

@bajtos
Copy link
Contributor Author

bajtos commented Jun 30, 2017

Thanks @trevnorris for joining the discussion! I'm leaving for vacation later today, I'll review and respond to your comments when I get back, after July 10th.

@addaleax addaleax added the semver-minor PRs that contain new features and should be released in the next minor version. label Jun 30, 2017
@bajtos
Copy link
Contributor Author

bajtos commented Jul 11, 2017

Hello 👋

I have reworked the initialisation of inspector async hook:

  1. Introduced a new property process._inspected that we use to detect whether the process was started with --inspect or --inspect-brk. I could expose this property on inspector binding instead, but it occurred to me that this flag may be useful outside of Node.js core too - see e.g. Debugging with async stack traces in Node.js petkaantonov/bluebird#1364 Having said that, I don't really mind to move the property somewhere else if you prefer. See 1f374ab

  2. Reworked the initialisation in bootstrap_node, I also had to fix C++ side to use Persistent instead of Local handle, see eab9884. TBH, I don't understand this nuance very much, Environment seems to be using a different technique to store persistent JS callbacks. I am also not sure whether this code supports multiple isolates correctly. @bnoordhuis would you mind taking a look?

  3. The remaining commits are addressing your review comments.

Could you PTAL at my changes again please?

});

exports.setup = function() {
inspector.registerAsyncHook(() => hook.enable(), () => hook.disable());
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Right now, we never use the disable callback, because AFAICT, the inspector mode is never disabled after it has been enabled. Am I missing something? Should I remove disable callback from the C++ layer to simplify things in the spirit of YAGNI?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If it is removed, possibly add a comment above this line explaining why disable() is never used.

@trevnorris
Copy link
Contributor

Introduced a new property process._inspected that we use to detect whether the process was started with --inspect or --inspect-brk.

Not to be done in this PR, but just a note for the future. We should really create an object or similar that has these. e.g.

if (process.flags['--inspect']) { }

// Or a call that automatically does `-_` replacement
process.hasExecFlag = function hasExecFlag(flag) {
  if (typeof flag !== 'string') throw new TypeError('must be a string');
  flag = flag.replace('_', '-');
  for (const str of process.execArgv)
    if (str === flag) return true;
  return false;
};

I could expose this property on inspector binding instead, but it occurred to me that this flag may be useful outside of Node.js core

Exposing it on inspector might be better for the moment to see if something like the above should land instead. That way we don't have to back peddle a property. If we want to then a PR that does this can be whipped up quickly.

FatalError(
"node::InspectorAgent::StartIoThread",
"Cannot enable Inspector's AsyncHook, please report this.");
}
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There's been discussion about standardizing how async_hooks/async_wrap throws (cc @AndreasMadsen @addaleax), but the behavior in Environment::AsyncHooks::pop_ids and fatalError() (lib/async_hooks.js) is that we only abort on --abort-on-uncaught-exception, and otherwise we forcibly exit (without chance of recovery).

I'm down for discussing how this is handled, but consistency would be good. Possibly for this PR follow the other examples, and we can fix how it's handled in another PR.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I will add this to my list of places where we have inconsistency.

StringView taskNameView(*taskNameValue, taskNameValue.length());

CHECK(args[1]->IsNumber());
intptr_t task_id = args[1]->IntegerValue(env->context()).FromJust();
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm worried that IntegerValue() returns a int64_t but intptr_t is a int32_t on ia32 builds. This will quickly run out of space to properly store the async ids.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@trevnorris Did you see #13870 (comment)?

On Inspector side we are trying to limit async stack traces memory usage, we dedup frames, stacks and limit maximum amount of async stacks which can be stored at particular moment of time (currently it's 128*1024). We cleanup old stacks first, so it means that at moment when Node.js reports 128*1024 + 1 stack we already collected stack trace with id 1. So it means that 2^31 different async task ids should be enough (actually 2^16 should be enough). Node.js can just use nodejs_id % 2^31 as id for inspector. We can land this CL later when we figure out how we can effectively avoid cleanup of old stacks but it probably would mean that async stack implementation is moved to V8 and enabled by default not only during debugging.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This goes back to your original comment in #13870 (comment).

I acknowledge the truncation can be a problem in theory. In practice, we should be fine because of #13870 (comment). Even if it was not true, I personally think it's better to have async stack traces in the first ~20 minutes of the debugging session than to not have any async stack traces at all.

However, to make this truncation issue more obvious, I'll use int64_t type here, and move the truncation into GetAsyncTask function, together with an explanatory comment.

Environment* env = Environment::GetCurrent(args);

v8::Local<v8::Function> enable_function = args[0].As<Function>();
v8::Local<v8::Function> disable_function = args[1].As<Function>();
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If either arg is not a v8::Function then on Release builds we'll be left with a cryptic segfault. Mind adding a CHECK(args[]->IsFunction()) for each argument here?

},

destroy(asyncId) {
inspector.asyncTaskCanceled(asyncId);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

does "canceled" mean that no other "started"/"finished" calls can be made? b/c when I read that it sounds like the async task was supposed to fire a "started", but was destroyed before that happened.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good point, it looks a bit suspicious to me as well. @ak239 could you perhaps help us to understand this better?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Your understanding is right. asyncTaskCanceled means that asynchronous task would never be executed again (no other started/finished calls) so on inspector side we can cleanup all related to this task data.

}

const hook = createHook({
init(asyncId, type, triggerId, resource) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Just to confirm that it's alright with you, while we make sure calls to init() in core actually mean the event loop has progressed in some way since the call to init(), the user API allows users to call before() synchronously. There isn't much that can be done about that, and it's on the user to implement it properly.

Basically, there's nothing actionable. Just want to bring this point up.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am afraid I am not able to judge how this fact affects V8 Inspector asyncTask* APIs. My knowledge of these two parts (Node.js async hooks, V8 asyncTask*) is pretty limited. I am just glueing them together, so to speak.

@TimothyGu
Copy link
Member

Rerun is green. Landed in be63c26...a0895ed 🎊

@TimothyGu TimothyGu closed this Aug 17, 2017
TimothyGu added a commit that referenced this pull request Aug 17, 2017
PR-URL: #13870
Reviewed-By: Miroslav Bajtoš <mbajtoss@gmail.com>
TimothyGu pushed a commit that referenced this pull request Aug 17, 2017
Implement a special async_hooks listener that forwards information
about async tasks to V8Inspector asyncTask* API, thus enabling
DevTools feature "async stack traces".

The feature is enabled only on 64bit platforms due to a technical
limitation of V8 Inspector: inspector uses a pointer as a task id,
while async_hooks use 64bit numbers as ids.

To avoid performance penalty of async_hooks when not debugging,
the new listener is enabled only when the process enters a debug mode:

 - When the process is started with `--inspect` or `--inspect-brk`,
   the listener is enabled immediately and async stack traces
   lead all the way to the first tick of the event loop.

 - When the debug mode is enabled via SIGUSR1 or `_debugProcess()`,
   the listener is enabled together with the debugger. As a result,
   only async operations started after the signal was received
   will be correctly observed and reported to V8 Inspector. For example,
   a `setInterval()` called in the first tick of the event will not be
   shown in the async stack trace when the callback is invoked. This
   behaviour is consistent with Chrome DevTools.

Last but not least, this commit fixes handling of InspectorAgent's
internal property `enabled_` to ensure it's set back to `false`
after the debugger is deactivated (typically via `process._debugEnd()`).

Fixes: #11370
PR-URL: #13870
Reviewed-by: Timothy Gu <timothygu99@gmail.com>
Reviewed-by: Anna Henningsen <anna@addaleax.net>
@bajtos
Copy link
Contributor Author

bajtos commented Aug 17, 2017

Awesome! I'd like to thank everybody who was involved in this long-lived pull request and helped me to make this happen. I really appreciated your help!

@sam-github
Copy link
Contributor

Belated LGTM, sorry @bajtos, I was vacationing when you asked me to relook.

@Trott
Copy link
Member

Trott commented Aug 22, 2017

Should this get a notable change label?

@addaleax addaleax added the notable-change PRs with changes that should be highlighted in changelogs. label Aug 22, 2017
@addaleax
Copy link
Member

@Trott yes! added it :)

MylesBorins pushed a commit that referenced this pull request Sep 10, 2017
PR-URL: #13870
Reviewed-By: Miroslav Bajtoš <mbajtoss@gmail.com>
MylesBorins pushed a commit that referenced this pull request Sep 10, 2017
Implement a special async_hooks listener that forwards information
about async tasks to V8Inspector asyncTask* API, thus enabling
DevTools feature "async stack traces".

The feature is enabled only on 64bit platforms due to a technical
limitation of V8 Inspector: inspector uses a pointer as a task id,
while async_hooks use 64bit numbers as ids.

To avoid performance penalty of async_hooks when not debugging,
the new listener is enabled only when the process enters a debug mode:

 - When the process is started with `--inspect` or `--inspect-brk`,
   the listener is enabled immediately and async stack traces
   lead all the way to the first tick of the event loop.

 - When the debug mode is enabled via SIGUSR1 or `_debugProcess()`,
   the listener is enabled together with the debugger. As a result,
   only async operations started after the signal was received
   will be correctly observed and reported to V8 Inspector. For example,
   a `setInterval()` called in the first tick of the event will not be
   shown in the async stack trace when the callback is invoked. This
   behaviour is consistent with Chrome DevTools.

Last but not least, this commit fixes handling of InspectorAgent's
internal property `enabled_` to ensure it's set back to `false`
after the debugger is deactivated (typically via `process._debugEnd()`).

Fixes: #11370
PR-URL: #13870
Reviewed-by: Timothy Gu <timothygu99@gmail.com>
Reviewed-by: Anna Henningsen <anna@addaleax.net>
@MylesBorins MylesBorins mentioned this pull request Sep 10, 2017
MylesBorins pushed a commit that referenced this pull request Sep 11, 2017
PR-URL: #13870
Reviewed-By: Miroslav Bajtoš <mbajtoss@gmail.com>
MylesBorins pushed a commit that referenced this pull request Sep 11, 2017
Implement a special async_hooks listener that forwards information
about async tasks to V8Inspector asyncTask* API, thus enabling
DevTools feature "async stack traces".

The feature is enabled only on 64bit platforms due to a technical
limitation of V8 Inspector: inspector uses a pointer as a task id,
while async_hooks use 64bit numbers as ids.

To avoid performance penalty of async_hooks when not debugging,
the new listener is enabled only when the process enters a debug mode:

 - When the process is started with `--inspect` or `--inspect-brk`,
   the listener is enabled immediately and async stack traces
   lead all the way to the first tick of the event loop.

 - When the debug mode is enabled via SIGUSR1 or `_debugProcess()`,
   the listener is enabled together with the debugger. As a result,
   only async operations started after the signal was received
   will be correctly observed and reported to V8 Inspector. For example,
   a `setInterval()` called in the first tick of the event will not be
   shown in the async stack trace when the callback is invoked. This
   behaviour is consistent with Chrome DevTools.

Last but not least, this commit fixes handling of InspectorAgent's
internal property `enabled_` to ensure it's set back to `false`
after the debugger is deactivated (typically via `process._debugEnd()`).

Fixes: #11370
PR-URL: #13870
Reviewed-by: Timothy Gu <timothygu99@gmail.com>
Reviewed-by: Anna Henningsen <anna@addaleax.net>
MylesBorins pushed a commit that referenced this pull request Sep 12, 2017
PR-URL: #13870
Reviewed-By: Miroslav Bajtoš <mbajtoss@gmail.com>
MylesBorins pushed a commit that referenced this pull request Sep 12, 2017
Implement a special async_hooks listener that forwards information
about async tasks to V8Inspector asyncTask* API, thus enabling
DevTools feature "async stack traces".

The feature is enabled only on 64bit platforms due to a technical
limitation of V8 Inspector: inspector uses a pointer as a task id,
while async_hooks use 64bit numbers as ids.

To avoid performance penalty of async_hooks when not debugging,
the new listener is enabled only when the process enters a debug mode:

 - When the process is started with `--inspect` or `--inspect-brk`,
   the listener is enabled immediately and async stack traces
   lead all the way to the first tick of the event loop.

 - When the debug mode is enabled via SIGUSR1 or `_debugProcess()`,
   the listener is enabled together with the debugger. As a result,
   only async operations started after the signal was received
   will be correctly observed and reported to V8 Inspector. For example,
   a `setInterval()` called in the first tick of the event will not be
   shown in the async stack trace when the callback is invoked. This
   behaviour is consistent with Chrome DevTools.

Last but not least, this commit fixes handling of InspectorAgent's
internal property `enabled_` to ensure it's set back to `false`
after the debugger is deactivated (typically via `process._debugEnd()`).

Fixes: #11370
PR-URL: #13870
Reviewed-by: Timothy Gu <timothygu99@gmail.com>
Reviewed-by: Anna Henningsen <anna@addaleax.net>
MylesBorins added a commit that referenced this pull request Sep 12, 2017
Notable Changes

* build:
  * Snapshots are now re-enabled in V8
  #14875

* console:
  * Implement minimal `console.group()`.
  #14910

* deps:
  * upgrade libuv to 1.14.1
    #14866
  * update nghttp2 to v1.25.0
    #14955

* dns:
  * Add `verbatim` option to dns.lookup(). When true, results from the
    DNS resolver are passed on as-is, without the reshuffling that
    Node.js otherwise does that puts IPv4 addresses before IPv6
    addresses.
    #14731

* fs:
  * add fs.copyFile and fs.copyFileSync which allows for more efficient
    copying of files.
    #15034

* inspector:
  * Enable async stack traces
    #13870

* module:
  * Add support for ESM. This is currently behind the
    `--experimental-modules` flag and requires the .mjs extension.
    `node --experimental-modules index.mjs`
    #14369

* napi:
  * implement promise
    #14365

* os:
  * Add support for CIDR notation to the output of the
    networkInterfaces() method.
    #14307

* perf_hooks:
  * An initial implementation of the Performance Timing API for
    Node.js. This is the same Performance Timing API implemented by
    modern browsers with a number of Node.js specific properties. The
    User Timing mark() and measure() APIs are implemented, as is a
    Node.js specific flavor of the Frame Timing for measuring event
    loop duration.
    #14680

* tls:
  * multiple PFX in createSecureContext
    [#14793](#14793)

* Added new collaborators:
  * BridgeAR – Ruben Bridgewater

PR-URL: #15308
MylesBorins added a commit that referenced this pull request Sep 12, 2017
Notable Changes

* build:
  * Snapshots are now re-enabled in V8
  #14875

* console:
  * Implement minimal `console.group()`.
  #14910

* deps:
  * upgrade libuv to 1.14.1
    #14866
  * update nghttp2 to v1.25.0
    #14955

* dns:
  * Add `verbatim` option to dns.lookup(). When true, results from the
    DNS resolver are passed on as-is, without the reshuffling that
    Node.js otherwise does that puts IPv4 addresses before IPv6
    addresses.
    #14731

* fs:
  * add fs.copyFile and fs.copyFileSync which allows for more efficient
    copying of files.
    #15034

* inspector:
  * Enable async stack traces
    #13870

* module:
  * Add support for ESM. This is currently behind the
    `--experimental-modules` flag and requires the .mjs extension.
    `node --experimental-modules index.mjs`
    #14369

* napi:
  * implement promise
    #14365

* os:
  * Add support for CIDR notation to the output of the
    networkInterfaces() method.
    #14307

* perf_hooks:
  * An initial implementation of the Performance Timing API for
    Node.js. This is the same Performance Timing API implemented by
    modern browsers with a number of Node.js specific properties. The
    User Timing mark() and measure() APIs are implemented, as is a
    Node.js specific flavor of the Frame Timing for measuring event
    loop duration.
    #14680

* tls:
  * multiple PFX in createSecureContext
    [#14793](#14793)

* Added new collaborators:
  * BridgeAR – Ruben Bridgewater

PR-URL: #15308
addaleax pushed a commit to addaleax/node that referenced this pull request Sep 13, 2017
Notable Changes

* build:
  * Snapshots are now re-enabled in V8
  nodejs#14875

* console:
  * Implement minimal `console.group()`.
  nodejs#14910

* deps:
  * upgrade libuv to 1.14.1
    nodejs#14866
  * update nghttp2 to v1.25.0
    nodejs#14955

* dns:
  * Add `verbatim` option to dns.lookup(). When true, results from the
    DNS resolver are passed on as-is, without the reshuffling that
    Node.js otherwise does that puts IPv4 addresses before IPv6
    addresses.
    nodejs#14731

* fs:
  * add fs.copyFile and fs.copyFileSync which allows for more efficient
    copying of files.
    nodejs#15034

* inspector:
  * Enable async stack traces
    nodejs#13870

* module:
  * Add support for ESM. This is currently behind the
    `--experimental-modules` flag and requires the .mjs extension.
    `node --experimental-modules index.mjs`
    nodejs#14369

* napi:
  * implement promise
    nodejs#14365

* os:
  * Add support for CIDR notation to the output of the
    networkInterfaces() method.
    nodejs#14307

* perf_hooks:
  * An initial implementation of the Performance Timing API for
    Node.js. This is the same Performance Timing API implemented by
    modern browsers with a number of Node.js specific properties. The
    User Timing mark() and measure() APIs are implemented, as is a
    Node.js specific flavor of the Frame Timing for measuring event
    loop duration.
    nodejs#14680

* tls:
  * multiple PFX in createSecureContext
    [nodejs#14793](nodejs#14793)

* Added new collaborators:
  * BridgeAR – Ruben Bridgewater

PR-URL: nodejs#15308
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
async_hooks Issues and PRs related to the async hooks subsystem. c++ Issues and PRs that require attention from people who are familiar with C++. inspector Issues and PRs related to the V8 inspector protocol notable-change PRs with changes that should be highlighted in changelogs. semver-minor PRs that contain new features and should be released in the next minor version.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Missing async callstacks on setTimeout