inspector: track async stacks when necessary #16260

ofrobots · 2017-10-17T16:21:17Z

With this change, we do async stack tracking only when explicitly
requested by the inspector client. This avoids unnecessary overhead
for clients that might not be interested in async stack traces.

Fixes: #16180

In practical terms, this means that we still get async stack tracking right from startup when --inspect-brk is used for debuggers that enable async stacks (DevTools does this by default, and I think WebStorm and others as well).

When using --inspect, we no longer enable async stack tracking by default. The inspector client can request async stack tracking at the time of the connection. Any async resources already created will not have stack tracking. I believe this is the right behavior (see #16180). Users needing async stack tracking right from startup can use --inspect-brk.

Checklist

make -j4 test (UNIX), or vcbuild test (Windows) passes
commit message follows commit guidelines

Affected core subsystem(s)

inspector

CI: https://ci.nodejs.org/job/node-test-pull-request/10785/

ofrobots · 2017-10-17T17:12:36Z

~~CI: https://ci.nodejs.org/job/node-test-pull-request/10783/~~ See OP for CI link.

R= @nodejs/v8-inspector
/cc @nodejs/diagnostics

addaleax · 2017-10-17T17:30:28Z

src/inspector_agent.cc

+    return;
+  }
+
+  Local<Value> method = maybe_method.ToLocalChecked();


I’d guess you can judge this better than I can, but it seems like quite a bit of this function could be simplified by using a if (!object->Get(…).ToLocal(&var_name)) return; pattern?

Thanks. Fixed.

With this change, we do async stack tracking only when explicitly requested by the inspector client. This avoids unnecessary overhead for clients that might not be interested in async stack traces. Fixes: nodejs#16180

addaleax · 2017-10-17T19:12:32Z

src/inspector_agent.cc

+
+  Maybe<double> maybe_depth = depth_value->NumberValue(context);
+  if (maybe_depth.IsNothing()) {
+    return;


I think this can’t actually be the case since you checked depths_value->IsNumber()

addaleax · 2017-10-17T19:13:43Z

src/inspector_agent.cc

+  // Basically, the logic we want to implement is:
+  // let parsed; try {
+  //   parsed = JSON.parse(string);
+  // } catch (e) { return; }


Is there a TryCatch that corresponds to this conceptual try/catch? If so, it’s not obvious where… or, rather: If there is none, what happens with the exception if JSON.parse throws?

I don't believe that the v8::JSON::Parse API throws on a parse error (unlike the JavaScript JSON.parse). This is the comment I am basing this on: https://cs.chromium.org/chromium/src/v8/include/v8.h?type=cs&l=1815.

/cc @nodejs/v8 if my understanding here is incorrect.

Okay, tried it out myself. v8::JSON::Parse does indeed throw. I will add a TryCatch.

@ofrobots Fwiw, as I understand it it’s a general principle of the V8 API that if a Maybe method returns an empty value, there is a corresponding pending exception

addaleax · 2017-10-17T19:18:06Z

src/inspector_agent.cc

+  MaybeLocal<String> string =
+    String::NewFromTwoByte(isolate, message.characters16(),
+                           v8::NewStringType::kNormal, message.length());
+  if (string.IsEmpty()) {


I can’t really tell how relevant performance is here, but if it makes sense to you, maybe add an early return if message doesn’t contain the substring Debugger.setAsync?

I think it would be good to improve performance here, but that's a non-critical optimization and can be addressed once this lands. I have left a TODO.

refack · 2017-10-17T21:09:20Z

src/inspector_agent.cc

@@ -449,7 +452,9 @@ Agent::Agent(Environment* env) : parent_env_(env),
                                 client_(nullptr),
                                 platform_(nullptr),
                                 enabled_(false),
-                                 next_context_number_(1) {}
+                                 next_context_number_(1),


Question: any reason do keep using initialization lists when we support C++11 (i.e. "Class Member Initialization")?

TimothyGu

Generally LGTM.

TimothyGu · 2017-10-17T21:24:45Z

src/inspector_agent.cc

+  MaybeLocal<Value> maybe_parsed =
+    v8::JSON::Parse(context, string.ToLocalChecked());
+  if (maybe_parsed.IsEmpty()) {
+    return;


Hint: what @addaleax is saying is that the return here won't make the exception magically go away. To replicate the return in JS a v8::TryCatch is needed.

bnoordhuis · 2017-10-18T09:48:34Z

src/inspector_agent.cc

+  }
+}
+
+void Agent::EnableAsyncHook(Isolate* isolate) {


It would be good to add a HandleScope here and in the method below because currently they leak handles into the caller's HandleScope. It's harmless right now but could become an issue in future refactorings.

bnoordhuis · 2017-10-18T09:51:15Z

src/inspector_agent.cc

+    FatalError(
+      "node::inspector::Agent::DisableAsyncHook",
+      "Cannot disable Inspector's AsyncHook, please report this.");
+  }


These two methods could be dedup'd, e.g., by passing the Persistent<Function> to use as a parameter (and the name in the error message as a string.)

bnoordhuis · 2017-10-18T09:51:59Z

src/inspector_agent.cc

+  // can execute. The Debugger.setAsyncCallStackDepth message arrives too early
+  // and we must intercept this in C++.
+
+  v8::Isolate* isolate = parent_env_->isolate();


This method looks like it needs a HandleScope.

bnoordhuis · 2017-10-18T09:56:25Z

src/inspector_agent.cc

+  Local<Value> parsed = maybe_parsed.ToLocalChecked();
+  if (!parsed->IsObject()) {
+    return;
+  }


You could shorten this to:

Local<Value> scratch; Local<Object> parsed; if (!v8::JSON::Parse(context, string).ToLocal(&scratch) || !scratch->IsObject() || !scratch->ToObject(context).ToLocal(&parsed)) { return; }

(General observation, applies to not just this block of code.)

Thanks. Done.

It might be possible to condense the code a bit further along these lines, but I left it at a point which seemed to be a good balance between terseness and readability.

bnoordhuis · 2017-10-18T09:59:36Z

src/inspector_agent.cc

+      } else {
+        pending_disable_async_hook_ = true;
+      }
+    }


Could this be flattened like this?

if (pending_enable_async_hook_) { // ... } else if (!disable_async_hook_function_.IsEmpty()) { // ... } else { // ... }

If not, a code comment explaining why is probably in order.

bajtos

Thank you @ofrobots for taking care of this and making my initial implementation of async stack traces more useful!

bajtos · 2017-10-18T12:24:24Z

test/inspector/test-async-hook-inspector.js

+  verifyAsyncHookDisabled('invalid message should not enable async hooks');
+
+  session.post('Debugger.setAsyncCallStackDepth', { maxDepth: 'five' }, () => {
+    verifyAsyncHookDisabled('invalid maxDepth (sting) should not enable async' +


typo: sting - should be string?

bajtos · 2017-10-18T12:27:01Z

test/inspector/test-async-hook-teardown-at-debug-end.js

-
-// Verify that inspector-async-hook is no longer registered,
-// thus emitInit() ignores invalid arguments
-// See test/async-hooks/test-emit-init.js


It makes me wonder - are DevTools clients disabling stack trace inspection before they disconnect? What happens when a 3rd-party DevTools client is implemented "incorrectly" and does not call setAsyncCallStackDepth before closing the session - will we keep async stack traces enabled in such case, possibly forever if no other DevTool clients ever connects? Are we ok with that?

This is a good point. I think the alternative PR #16308 addresses this.

jasnell · 2017-10-18T15:33:51Z

First glance through looks fine other than the suggestions @bnoordhuis has already made. It's good to see this change.

One question: would it make any sense at all to have a command line flag to enable this by default at startup?

eugeneo · 2017-10-18T16:00:06Z

src/inspector_agent.cc

+  Local<Context> context = parent_env_->context();
+
+  MaybeLocal<String> string =
+    String::NewFromTwoByte(isolate, message.characters16(),


StringView does not convert between encodings. I believe, right now all messages are 16 bit. Can you add CHECK (!message.is8Bit()) just to be sure?

alexkozy

Let me raise some points: it's easy to get out-of-sync state with interception, since Debugger.disable and session disconnect disable async stacks as well. If at any time in future DevTools will support reload button for Node.js, we'll store session state as JSON and then use domain's restore method to restore state - setAsync.. won't be called in this case as well.

Alternative approaches:

we can provide callback on V8InspectorClient and call it any time when async call stack depth is changed,
we can expose JavaScript asyncTask* bindings which will contain fast return without entering C++ if async stacks are disabled.

I prefer second approach since it allows us not to grow inspector client API.

bnoordhuis

LGTM modulo style nits.

bnoordhuis · 2017-10-18T16:57:18Z

src/inspector_agent.cc

+  HandleScope handle_scope(isolate);
+  Local<Context> context = parent_env_->context();
+
+  v8::TryCatch try_catch(isolate); // catch and ignore exceptions.


s/catch/Catch/ and two spaces before the //. (Although I don't think the comment adds much.)

bnoordhuis · 2017-10-18T16:58:37Z

test/inspector/test-async-hook-inspector.js

+
+    session.post('Debugger.setAsyncCallStackDepth', { maxDepth: NaN }, () => {
+      verifyAsyncHookDisabled('invalid maxDepth (NaN) should not enable async' +
+        ' hooks');


Tiny nit: can you line this up here and below?

ofrobots · 2017-10-18T23:49:34Z

@ak239 raised some good points. I've implemented an alternative fix to the problem that depends on an upstream back port: #16308. Abandoning in favor of that PR.

ofrobots · 2017-10-18T23:56:52Z

@jasnell

One question: would it make any sense at all to have a command line flag to enable this by default at startup?

I am not opposed to that, however, I am not entirely clear on the exact use-case that addresses that isn't already addressed by --inspect-brk or through the inspector module. If there are valid uses-cases, I think the flag can be added at any point in a semver-minor. Right now I want to make sure we fix the problematic behavior from #16180 before we head into LTS.

nodejs-github-bot added c++ Issues and PRs that require attention from people who are familiar with C++. lib / src Issues and PRs related to general changes in the lib or src directory. labels Oct 17, 2017

ofrobots force-pushed the stack-tracking branch from 10d15a4 to ae2da88 Compare October 17, 2017 17:09

ofrobots mentioned this pull request Oct 17, 2017

async stack tracking should not be enabled by default #16180

Closed

addaleax reviewed Oct 17, 2017

View reviewed changes

inspector: track async stacks when necessary

50c0bc1

With this change, we do async stack tracking only when explicitly requested by the inspector client. This avoids unnecessary overhead for clients that might not be interested in async stack traces. Fixes: nodejs#16180

ofrobots force-pushed the stack-tracking branch from ae2da88 to 50c0bc1 Compare October 17, 2017 19:01

addaleax approved these changes Oct 17, 2017

View reviewed changes

addaleax added async_hooks Issues and PRs related to the async hooks subsystem. inspector Issues and PRs related to the V8 inspector protocol labels Oct 17, 2017

refack approved these changes Oct 17, 2017

View reviewed changes

TimothyGu approved these changes Oct 17, 2017

View reviewed changes

bnoordhuis reviewed Oct 18, 2017

View reviewed changes

bajtos reviewed Oct 18, 2017

View reviewed changes

[SQUASH] address comments

df628ce

eugeneo reviewed Oct 18, 2017

View reviewed changes

alexkozy reviewed Oct 18, 2017

View reviewed changes

bnoordhuis approved these changes Oct 18, 2017

View reviewed changes

[SQUASH] fix typos in test

0a48cf7

ofrobots mentioned this pull request Oct 18, 2017

Inspector: Track async stacks only when necessary #16308

Merged

2 tasks

ofrobots closed this Oct 18, 2017

aoberoi mentioned this pull request May 19, 2018

Preserve stack track of original errors slackapi/node-slack-sdk#561

Closed

9 tasks

inspector: track async stacks when necessary #16260

inspector: track async stacks when necessary #16260

Conversation

ofrobots commented Oct 17, 2017 • edited Loading

Checklist

Affected core subsystem(s)

ofrobots commented Oct 17, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

TimothyGu left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bajtos left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jasnell commented Oct 18, 2017

Choose a reason for hiding this comment

alexkozy left a comment • edited Loading

Choose a reason for hiding this comment

bnoordhuis left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ofrobots commented Oct 18, 2017

ofrobots commented Oct 18, 2017 • edited Loading

ofrobots commented Oct 17, 2017 •

edited

Loading

ofrobots commented Oct 17, 2017 •

edited

Loading

alexkozy left a comment •

edited

Loading

ofrobots commented Oct 18, 2017 •

edited

Loading