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

trace_events: adds a new trace_events api #19803

Closed
wants to merge 3 commits into from

Conversation

jasnell
Copy link
Member

@jasnell jasnell commented Apr 4, 2018

Removes the requirement to use --trace-events-enabled to enable trace events. Tracing is enabled automatically if there are any enabled categories.

Adds a new trace_events module with an API for enabling/disabling trace events at runtime without a command line flag.

const trace_events = require('trace_events');
const categories = [ 'node.perf', 'node.async_hooks' ];
const tracing = trace_events.createTracing({ categories });
tracing.enable();
// do stuff
tracing.disable();

Multiple Tracing objects may exist and be enabled at any point in time. The enabled trace event categories is the union of all enabled Tracing objects and the --trace-event-categories flag.

Alternative to: #19233

ping @ofrobots @AndreasMadsen @mcollina @nodejs/diagnostics

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

@jasnell jasnell added semver-major PRs that contain breaking changes and should be released in the next major version. trace_events Issues and PRs related to V8, Node.js core, and userspace code trace events. labels Apr 4, 2018
@nodejs-github-bot nodejs-github-bot added the lib / src Issues and PRs related to general changes in the lib or src directory. label Apr 4, 2018
@jasnell
Copy link
Member Author

jasnell commented Apr 4, 2018


[customInspectSymbol](depth, opts) {
const obj = {
enabled: Boolean(this[kEnabled]),
Copy link
Member

@AndreasMadsen AndreasMadsen Apr 4, 2018

Choose a reason for hiding this comment

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

this.enabled should be enough

}

get enabled() {
return Boolean(this[kEnabled]);
Copy link
Member

Choose a reason for hiding this comment

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

Why Boolean(this[kEnabled]),couldn't you just initialize this[kEnabled] = false; in the constructor?

Copy link
Member Author

Choose a reason for hiding this comment

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

No particular reason, either works

Copy link
Member

Choose a reason for hiding this comment

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

No particular reason, either works

I would prefer the one that doesn't involve type conversion. I think V8 will also prefer the monomorphism.

}
}

function createTracing(options = { categories: ['v8', 'node'] }) {
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 categories should be mandatory. Logging all this data is never a good idea.

@devsnek
Copy link
Member

devsnek commented Apr 4, 2018

once again a small reminder about whether we want to namespace builtins, not blocking this or anything, it looks pretty good 👍

@Qard
Copy link
Member

Qard commented Apr 4, 2018

Any particular reason for trace_events.createTracing({ categories: [ 'node.perf', 'node.async_hooks' ] }) versus just trace_events.createTracing([ 'node.perf', 'node.async_hooks' ])?

@jasnell
Copy link
Member Author

jasnell commented Apr 4, 2018

@Qard ... to account for the possibility of new options in the future.

@jasnell
Copy link
Member Author

jasnell commented Apr 4, 2018

Failures in CI are unrelated.

@Qard
Copy link
Member

Qard commented Apr 4, 2018

Could you not just do trace_events.createTracing(categories, options) if that need comes up in the future?

@jasnell
Copy link
Member Author

jasnell commented Apr 4, 2018

Yes, but this API is also consistent with the styling of the async_hooks API (e.g. async_hooks.createHook({ ... }). Consistency of similarly purposed APIs is a good thing :-)


An attempt to load the `trace_events` module was made but the Node.js binary
was compiled with the `NODE_USE_V8_PLATFORM=0` configuration option causing
Trace Events to be unavailable.
Copy link
Member

Choose a reason for hiding this comment

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

Optional suggestion:

Simplify this to something like:

The trace_events module cannot be loaded because Node.js was compiled without Trace Events.

...or:

The trace_events module could not be loaded because Node.js was compiled with V8 platform disabled.

This will allow for the possibility now or in the future that there are other reasons Node.js might be compiled without Trace Events.

(Totally non-blocking. Just a suggestion.)

Tracing can be enabled by passing the `--trace-events-enabled` flag when
starting a Node.js application.
Tracing can be enabled by using the `--trace-event-categories` flag when
starting a Node.js application, or by using the `trace_events` module.
Copy link
Member

Choose a reason for hiding this comment

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

Alternate suggestion:

Tracing can be enabled with the --trace-event-categories command-line flag
or by using the trace_events module.


Disables this `Tracing` object.

Only trace event categories *not* covered by other enableed `Tracing` objects
Copy link
Member

Choose a reason for hiding this comment

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

Typo: enableed -> enabled


* Returns: {string}

Returns a comma-separated listing of all currently enabled trace event
Copy link
Member

Choose a reason for hiding this comment

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

Nit: listing -> list

Copy link
Member

Choose a reason for hiding this comment

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

Nit: currently enabled -> currently-enabled


Returns a comma-separated listing of all currently enabled trace event
categories. The current set of enabled trace event categories is determined
by the *union* of all currently enabled `Tracing` objects and any categories
Copy link
Member

Choose a reason for hiding this comment

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

Same: currently enabled -> currently-enabled

```

Where test.js is

Copy link
Member

Choose a reason for hiding this comment

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

Nit: Get rid of everything from For example to this line, as well as the Will emit line below and use this instead:

Given the file `test.js` below, the command `node --trace-event-categories node.perf test.js` will
print `'node.async_hooks,node.perf'` to the console.

@AndreasMadsen
Copy link
Member

Yes, but this API is also consistent with the styling of the async_hooks API (e.g. async_hooks.createHook({ ... }). Consistency of similarly purposed APIs is a good thing :-)

I don't really hold any strong opinion. But the reason why it is an object in async_hooks is that all parameters are optional. That is not the case here.

@jasnell
Copy link
Member Author

jasnell commented Apr 4, 2018

I don't really hold any strong opinion. But the reason why it is an object in async_hooks is that all parameters are optional. That is not the case here.

Yep, I get that, but I still have a strong preference towards keeping the arguments as consistent as possible.

@Qard
Copy link
Member

Qard commented Apr 4, 2018

I don't really agree with the "consistency" argument here--the purpose of async_hooks is not that similar, and the purpose of the arguments are entirely different. I don't really have a strong opinion about it though. 🤷‍♂️

@mcollina
Copy link
Member

mcollina commented Apr 4, 2018

I think there is a package-lock file committed by accident.

Side note, as this is an experimental module, I don't think this is semver-major. The major reason this is semver-major is that adding this will shadow my trace_events placeholder on npm.

Can you add setting the destination file via the JS API?

@jasnell
Copy link
Member Author

jasnell commented Apr 4, 2018

I think there is a package-lock file committed by accident.

Ugh.

Side note, as this is an experimental module, I don't think this is semver-major. The major reason this is semver-major is that adding this will shadow my trace_events placeholder on npm.

Well, adding a new top level module is always semver-major by default. The @nodejs/tsc can decide otherwise, however.

Can you add setting the destination file via the JS API?

In a separate PR, yes. Once this lands.

@jasnell
Copy link
Member Author

jasnell commented Apr 4, 2018

Errant package-lock change removed.

added: REPLACEME
-->

* Value: {string}
Copy link
Contributor

Choose a reason for hiding this comment

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

It seems Value: part is unconventional: other properties in the docs mostly have just a type.

added: REPLACEME
-->

* Value: {boolean} `true` only if the `Tracing` object has been enabled.
Copy link
Contributor

Choose a reason for hiding this comment

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

Ditto)


```js
const trace_events = require('trace_events');
const categories = [ 'node.perf', 'node.async_hooks' ];
Copy link
Contributor

@vsemozhetbyt vsemozhetbyt Apr 4, 2018

Choose a reason for hiding this comment

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

Nit: maybe it is worth to unify padding spaces in array literals inside this doc: some have them, some have not.


* `options` {Object}
* `categories` {string[]} An array of trace category names
* Returns: `Tracing` object.
Copy link
Contributor

@vsemozhetbyt vsemozhetbyt Apr 4, 2018

Choose a reason for hiding this comment

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

Maybe it is worth to add this type in customTypesMap and format it here, like this:

  • in type-parser.js:
-  'tls.TLSSocket': 'tls.html#tls_class_tls_tlssocket',
-
+  'tls.TLSSocket': 'tls.html#tls_class_tls_tlssocket',
+
+  'Tracing': 'tracing.html#tracing_tracing_object',
+
  • in tracing.md:
-* Returns: `Tracing` object.
+* Returns: {Tracing}

@jasnell
Copy link
Member Author

jasnell commented Apr 5, 2018

@vsemozhetbyt ... updated! :-)

Copy link
Member

@mcollina mcollina left a comment

Choose a reason for hiding this comment

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

LGTM

@jasnell jasnell force-pushed the trace-events-api branch 2 times, most recently from c6e111f to 2ade138 Compare April 10, 2018 20:32
@jasnell
Copy link
Member Author

jasnell commented Apr 10, 2018

I've updated the PR to emit a process warning if the Tracing object is gc'd while still enabled. This is specifically to discourage users from allowing references to get lost and to help identify buggy code. The Tracing object is still disabled on gc but the best practice would be to hold a reference to prevent gc and to explicitly call disable() before allowing the object to gc. There is existing precedence for this with the new FileHandle object that is used in the fs.promises API.

@jasnell
Copy link
Member Author

jasnell commented Apr 11, 2018

@nodejs/diagnostics @nodejs/tsc ... I'd appreciate a few more looks at this and some additional points of view on the one item that is holding this up... namely whether gc of an enabled Tracing object should automatically disable it.

### ERR_TRACE_EVENTS_UNAVAILABLE

The `trace_events` module could not be loaded because Node.js was compiled with
V8 platform disabled.
Copy link
Member

Choose a reason for hiding this comment

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

"with V8 platform disabled" is cryptic. I'd say something like "with ./configure --without-v8-platform".

Copy link
Member

Choose a reason for hiding this comment

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

Maybe "with the --without-v8-platform flag"?

categories. Instances are created using the `trace_events.createTracing()`
method.

When created, the `Tracing` object is not-enabled. Calling the
Copy link
Member

Choose a reason for hiding this comment

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

'not enabled', no dash, or just 'disabled.'

Copy link
Member

Choose a reason for hiding this comment

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

disabled is the better of those two options IMO

src/node.cc Outdated
}

void StopTracingAgent() {
tracing_agent_->Stop();
}

tracing::Agent* GetTracingAgent() {
Copy link
Member

Choose a reason for hiding this comment

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

Method could be const, ditto on line 353.

Local<Array> cats = args[0].As<Array>();
for (size_t n = 0; n < cats->Length(); n++) {
Local<Value> category = cats->Get(env->context(), n).ToLocalChecked();
Utf8Value val(env->isolate(), category.As<String>());
Copy link
Member

Choose a reason for hiding this comment

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

Don't .As<String>() here:

  1. The constructor takes a Local<Value>
  2. It looks wrong because there's nothing that guarantees it's really a string.

CHECK_EQ(err, 0);

tracing_controller_->StartTracing(trace_config);
CHECK_EQ(uv_thread_create(&thread_, ThreadCb, this), 0);
Copy link
Member

Choose a reason for hiding this comment

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

CHECK_EQ(0, uv_thread_create(...)); - that's the most common form in src/ for such checks.

agent_->Disable(this);
enabled_ = false;
}
}
Copy link
Member

Choose a reason for hiding this comment

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

These methods look unnecessary. I can't really tell why CategorySet is exposed to JS because the core of its logic is just this and that could be done by a single binding method:

Utf8Value categories(args.GetIsolate(), args[0]);
v8_platform.GetTracingAgent()->Enable(categories);

And Enable() can be condensed to just this, it looks like:

// split categories by comma, then:
TraceConfig* trace_config = new TraceConfig();
for (auto category : categories) trace_config->AddIncludedCategory(category.c_str());
tracing_controller_->StartTracing(config);

If CategorySet exists to have some weak GC object, eh, there's probably better ways to achieve that. I see it's been discussed at some length already. :-)

Copy link
Member Author

Choose a reason for hiding this comment

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

The reason CategorySet exists is specifically to have some weak GC object that can be used with the theoretical goal of being able to manage multiple trace event targets and possibly other hypothetical use cases later. I'm personally not convinced it's needed and would prefer the trace_events.enable()/ trace_events.disable() approach with the internal ref counting. It would make this much simpler as you suggest.

Copy link
Member Author

@jasnell jasnell Apr 11, 2018

Choose a reason for hiding this comment

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

To explain a bit more... the simplified versions you suggest are definitely possible. However,

1) there is a general concern over multiple modules stepping on each other if they are enabling/disabling categories which is why the code uses a crude form of reference counting using an std::multiset as opposed to using AddIncludedCategory directly. We should likely keep that in place.

2) CategorySet exists specifically to have a JS that can be used. Right now enabling and disabling the categories is the only use for it. There has been some discussion, however, about allowing JS code to specify multiple trace event destinations (e.g. one Tracing object could direct the trace events it cares about to one file, while another directs trace events it wants to another file). This is a purely hypothetical use case at this point but it's been discussed.

I've got zero problems with simplifying this by eliminating CategorySet but we need to resolve the API question... do we, or we do not, want the JS-accessible Tracing object?

Copy link
Member Author

Choose a reason for hiding this comment

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

Reading the comment again I realize I misread your original point. The internal CategorySet is there largely to eventually allow for more Tracing object specific configuration stuff such as multiple outputs. You're absolutely right that it can be eliminated if all we're going to do is enable/disable categories.

@jasnell
Copy link
Member Author

jasnell commented Apr 13, 2018

Thanks for the comments @bnoordhuis ... I think I got everything...

@nodejs/tsc ... still looking for additional review on this. There is a conflict of opinion about whether the Tracing object should disable itself on gc. We should try to resolve that before landing this.

### ERR_TRACE_EVENTS_CATEGORY_REQUIRED

An attempt was made to call `trace_events.createTracing()` with an empty set
of trace event categories. At least one category is required.
Copy link
Member

@Trott Trott Apr 13, 2018

Choose a reason for hiding this comment

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

These two sentences should (IMO) be replaced with a single short sentence:

`trace_events.createTracing()` requires at least one trace event category.
...or if you must use passive voice, something more like:
`trace_events.createTracing()` must be called with at least one trace event category.

@jasnell
Copy link
Member Author

jasnell commented Apr 14, 2018

After talking with @mcollina about it, in order to get this unblocked, I'm removing the disable on gc and will maintain an internal Set of enabled Tracing object references to ensure that they cannot be gc'd while they are enabled. A new getEnabledTracingObjects() method will allow inspection of what Tracing objects are in the Set (and will allow recovery of any lost references).

Removes the requirement to use `--trace-events-enabled` to enable
trace events. Tracing is enabled automatically if there are any
enabled categories.

Adds a new `trace_events` module with an API for enabling/disabling
trace events at runtime without a command line flag.

```js
const trace_events = require('trace_events');
const categories = [ 'node.perf', 'node.async_hooks' ];
const tracing = trace_events.createTracing({ categories });
tracing.enable();
// do stuff
tracing.disable();
```

Multiple `Tracing` objects may exist and be enabled at any point
in time. The enabled trace event categories is the union of all
enabled `Tracing` objects and the `--trace-event-categories`
flag.
@jasnell
Copy link
Member Author

jasnell commented Apr 14, 2018

Copy link
Contributor

@ofrobots ofrobots left a comment

Choose a reason for hiding this comment

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

LGTM if getEnabledTracingObjects is omitted for now, but I am open to counter arguments.

Tracing can be enabled by passing the `--trace-events-enabled` flag when
starting a Node.js application.
Tracing can be enabled with the `--trace-event-categories` command-line flag
or by using the `trace_events` module.

The set of categories for which traces are recorded can be specified using the
Copy link
Contributor

Choose a reason for hiding this comment

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

minor nit: elide these two paragraphs:

Tracing can be enabled with the --trace-event-categories command-line flag
or by using the trace_events module. The --trace-event-categories flag accepts
accepts a list of comma separated category..

Copy link
Member Author

Choose a reason for hiding this comment

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

How come? They seem useful.

Copy link
Member

Choose a reason for hiding this comment

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

I agree with @ofrobots and think the current formulation as separate paragraphs is confusing. They are written as if they are about two different flags but they're about the same flag. Put the information in one place.

Copy link
Member

Choose a reason for hiding this comment

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

Also, the way @ofrobots re-wrote the second sentence (to be less wordy and to eliminate the passive voice) is much more readable IMO.

Copy link
Member

Choose a reason for hiding this comment

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

(Although get rid of the accepts accepts in the second sentence. One accepts is enough. 😄)

Copy link
Member

Choose a reason for hiding this comment

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

(Also: comma separated -> comma-separated.)

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 want to keep them as separate paragraphs on the grounds that one is about enabling the feature and the other is about specifying categories, rewrite the second one so that it doesn't sound like it's introducing a new flag when it's not. Maybe this?

Categories for which traces are recorded are specified as one or more names after the --trace-event-categories flag.

}

bool enabled_ = false;
std::set<std::string> categories_;
Copy link
Contributor

Choose a reason for hiding this comment

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

nit: make this a const as well.

return new Tracing(options.categories);
}

function getEnabledTracingObjects() {
Copy link
Contributor

Choose a reason for hiding this comment

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

The danger with this API is that others can get a handle to my tracing object and mutate. I think the danger you are guarding against here is that people might lose a handle to their Tracing object, and this provides a way to recover. I am not convinced that this will be a real problem that users of trace_events are likely to run into. And even if they do, it is going to be really easy to fix their code.

IMO, we don't need this API. If there is real need for this API that cannot be addressed by a fix in user code, then lets hear that reason from users and then add this

Copy link
Member Author

@jasnell jasnell Apr 16, 2018

Choose a reason for hiding this comment

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

The concern here is that we're building a potential memory leak... giving users the ability to allocate objects that cannot be recovered and gc'd. If we don't have deactivation on cleanup, then I think we at least need to have a mechanism like this because the failure might be entirely silent and go unnoticed by the users.

One thing we could do to make it nosier is a warning if the set of enabled Tracing objects becomes too large but that's only a partial mitigation.

Copy link
Contributor

Choose a reason for hiding this comment

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

The concern here is that we're building a potential memory leak.

I think it would be unlikely for people to enable the same category multiple times – without disabling the previously enabled tracing object. So, the only case where the leak is possible is when users are trying out various different permutations of the categories – but never disabling them. I think this is unlikely, and a warning for (say >10) tracing objects would probably be enough to guard against this danger.

The proposed API here is more dangerous than the theoretical memory leak IMO.

Copy link
Member Author

Choose a reason for hiding this comment

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

I'll remove the function and add the error. I'm not entirely happy with it but I'd like to get this unblocked.

const enabledCategories = isChild ? 'foo' : undefined;

assert.strictEqual(getEnabledCategories(), enabledCategories);
[1, 'foo', true, false, null, undefined].forEach((i) => {
Copy link
Contributor

Choose a reason for hiding this comment

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

nit: might be good to deal with this (i.e. better error message). It might be worth noting that non-string values get coerced to a string in the docs. Okay, if it gets done in a follow-on PR.

> t.createTracing({categories: [Symbol("foo")]})
TypeError: Cannot convert a Symbol value to a string
    at new Tracing (trace_events.js:25:21)
    at Object.createTracing (trace_events.js:75:10

@jasnell
Copy link
Member Author

jasnell commented Apr 16, 2018

This is ready to go, just waiting on additional @nodejs/tsc review since it is semver-major due to the addition of the new top level module. hah, just saw that @ofrobots' reviewed :-) thank you!

@jasnell
Copy link
Member Author

jasnell commented Apr 16, 2018

@jasnell
Copy link
Member Author

jasnell commented Apr 16, 2018

CI is green. There are three TSC approvals. If there are no objections I will get this landed tomorrow.

@nodejs/tsc ... let me know if there are any objections to going ahead and pulling this in to 10.0.0

jasnell added a commit that referenced this pull request Apr 17, 2018
Removes the requirement to use `--trace-events-enabled` to enable
trace events. Tracing is enabled automatically if there are any
enabled categories.

Adds a new `trace_events` module with an API for enabling/disabling
trace events at runtime without a command line flag.

```js
const trace_events = require('trace_events');
const categories = [ 'node.perf', 'node.async_hooks' ];
const tracing = trace_events.createTracing({ categories });
tracing.enable();
// do stuff
tracing.disable();
```

Multiple `Tracing` objects may exist and be enabled at any point
in time. The enabled trace event categories is the union of all
enabled `Tracing` objects and the `--trace-event-categories`
flag.

PR-URL: #19803
Reviewed-By: Matteo Collina <matteo.collina@gmail.com>
Reviewed-By: Ali Ijaz Sheikh <ofrobots@google.com>
Reviewed-By: Franziska Hinkelmann <franziska.hinkelmann@gmail.com>
@jasnell
Copy link
Member Author

jasnell commented Apr 17, 2018

Landed in 5c27e44

@jasnell jasnell closed this Apr 17, 2018
jasnell added a commit that referenced this pull request Apr 17, 2018
Removes the requirement to use `--trace-events-enabled` to enable
trace events. Tracing is enabled automatically if there are any
enabled categories.

Adds a new `trace_events` module with an API for enabling/disabling
trace events at runtime without a command line flag.

```js
const trace_events = require('trace_events');
const categories = [ 'node.perf', 'node.async_hooks' ];
const tracing = trace_events.createTracing({ categories });
tracing.enable();
// do stuff
tracing.disable();
```

Multiple `Tracing` objects may exist and be enabled at any point
in time. The enabled trace event categories is the union of all
enabled `Tracing` objects and the `--trace-event-categories`
flag.

PR-URL: #19803
Reviewed-By: Matteo Collina <matteo.collina@gmail.com>
Reviewed-By: Ali Ijaz Sheikh <ofrobots@google.com>
Reviewed-By: Franziska Hinkelmann <franziska.hinkelmann@gmail.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
lib / src Issues and PRs related to general changes in the lib or src directory. semver-major PRs that contain breaking changes and should be released in the next major version. trace_events Issues and PRs related to V8, Node.js core, and userspace code trace events.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet