Skip to content
Closed
Show file tree
Hide file tree
Changes from 1 commit
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion doc/api/_toc.md
Original file line number Diff line number Diff line change
Expand Up @@ -46,7 +46,7 @@
* [String Decoder](string_decoder.html)
* [Timers](timers.html)
* [TLS/SSL](tls.html)
* [Tracing](tracing.html)
* [Trace Events](tracing.html)
* [TTY](tty.html)
* [UDP/Datagram](dgram.html)
* [URL](url.html)
Expand Down
12 changes: 12 additions & 0 deletions doc/api/errors.md
Original file line number Diff line number Diff line change
Expand Up @@ -1531,6 +1531,18 @@ socket, which is only valid from a client.

An attempt was made to renegotiate TLS on a socket instance with TLS disabled.

<a id="ERR_TRACE_EVENTS_CATEGORY_REQUIRED"></a>
### ERR_TRACE_EVENTS_CATEGORY_REQUIRED

The `trace_events.createTracing()` method requires at least one trace event
category.

<a id="ERR_TRACE_EVENTS_UNAVAILABLE"></a>
### ERR_TRACE_EVENTS_UNAVAILABLE

The `trace_events` module could not be loaded because Node.js was compiled with
the `--without-v8-platform` flag.

<a id="ERR_TRANSFORM_ALREADY_TRANSFORMING"></a>
### ERR_TRANSFORM_ALREADY_TRANSFORMING

Expand Down
164 changes: 159 additions & 5 deletions doc/api/tracing.md
Original file line number Diff line number Diff line change
@@ -1,12 +1,14 @@
# Tracing
# Trace Events

<!--introduced_in=v7.7.0-->

> Stability: 1 - Experimental

Trace Event provides a mechanism to centralize tracing information generated by
V8, Node.js core, and userspace code.

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
Copy Markdown
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
Copy Markdown
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
Copy Markdown
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
Copy Markdown
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
Copy Markdown
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
Copy Markdown
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
Copy Markdown
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.

`--trace-event-categories` flag followed by a list of comma separated category
Expand All @@ -27,7 +29,32 @@ The available categories are:
By default the `node`, `node.async_hooks`, and `v8` categories are enabled.

```txt
node --trace-events-enabled --trace-event-categories v8,node,node.async_hooks server.js
node --trace-event-categories v8,node,node.async_hooks server.js
```

Prior versions of Node.js required the use of the `--trace-events-enabled`
flag to enable trace events. This requirement has been removed. However, the
`--trace-events-enabled` flag *may* still be used and will enable the
`node`, `node.async_hooks`, and `v8` trace event categories by default.

@ofrobots ofrobots Apr 5, 2018 •

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Not a feedback on this PR, but I don't think node.async_hooks are good candidates for the default set of events to enable. They are a bit too low level. Higher level tracing of at the APIs level would be a lot more useful to most users. Since trace_events is experimental, I expect we should be able to change this in the future.

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

I think it is for backward compatibility, ultimately I think --trace-events-enabled should be removed. A default set of trace_events doesn't really make sense to me.

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

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

Yes, it's for backwards compatibility only. Once this lands I plan to open a PR deprecating --trace-events-enabled and removing it from the node --help output. It will still be there for legacy support and can eventually be removed.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

sgtm


```txt
node --trace-events-enabled

// is equivalent to

node --trace-event-categories v8,node,node.async_hooks
```

Alternatively, trace events may be enabled using the `trace_events` module:

```js
const trace_events = require('trace_events');
const tracing = trace_events.createTracing({ categories: ['node.perf'] });
tracing.enable(); // Enable trace event capture for the 'node.perf' category

// do work

tracing.disable(); // Disable trace event capture for the 'node.perf' category
```

Running Node.js with tracing enabled will produce log files that can be opened
Expand All @@ -40,12 +67,139 @@ be specified with `--trace-event-file-pattern` that accepts a template
string that supports `${rotation}` and `${pid}`. For example:

```txt
node --trace-events-enabled --trace-event-file-pattern '${pid}-${rotation}.log' server.js
node --trace-event-categories v8 --trace-event-file-pattern '${pid}-${rotation}.log' server.js
```

Starting with Node.js 10.0.0, the tracing system uses the same time source
as the one used by `process.hrtime()`
however the trace-event timestamps are expressed in microseconds,
unlike `process.hrtime()` which returns nanoseconds.

## The `trace_events` module
<!-- YAML
added: REPLACEME
-->

### `Tracing` object
<!-- YAML
added: REPLACEME
-->

The `Tracing` object is used to enable or disable tracing for sets of
categories. Instances are created using the `trace_events.createTracing()`
method.

When created, the `Tracing` object is disabled. Calling the
`tracing.enable()` method adds the categories to the set of enabled trace event
categories. Calling `tracing.disable()` will remove the categories from the
set of enabled trace event categories.

#### `tracing.categories`

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

At some point we may also want to expose the list of static categories that can be enabled by the user to facilitate interactive tool writers to expose them in the UI. With that in mind, do we want name this Tracing.prototype.enabled_categories so that it is more easily distinguishable from trace_events.categories?

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

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

well... we can expose the list of categories that we explicitly support, but the list is not entirely static.

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

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

re: categories... there is no trace_events.categories.

const trace_events = require('trace_events');
trace_events.getEnabledCategories(); // returns the string listing of enabled categories

const tracing = trace_events.createTracing({ categories: ['foo', 'bar'] });
tracing.categories  // the string listing of categories for this tracing object

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Yes, there is no API for that today, but we would want one the future.

To give some more context, this is what one can do in Chrome today:
image

I would imagine that people would want to build tracing tools that let users select from a list of categories of events they can trace. It would be good if such tools can obtain the predefined list of categories programmatically.

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

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

It should be relatively trivial to add this with a separate PR once the trace_events module lands.

<!-- YAML
added: REPLACEME
-->

* {string}

A comma-separated list of the trace event categories covered by this
`Tracing` object.

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

I'm not truly fond of returning a comma-separated list of things. Can we return an Array? Do we expect this API to be sitting in hot paths where doing that would be too expensive?

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

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

The main reason I went with the comma separated list is that it uses the same format at that accepted by the --trace-event-categories flag. A user can easily console.log() this then copy-and-paste it in to a script using that flag. The values are purely informational otherwise and it is exceedingly unlikely to end up in a hot path. At most, a user will log the data out and, in so doing, would have to convert it to a string anyway. I could provide an second property that gives an Array.


#### `tracing.disable()`
<!-- YAML
added: REPLACEME
-->

Disables this `Tracing` object.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Do we also want to mention somewhere that the traced categories will get disabled if the Tracing object gets garbage collected. I wonder if this is going to be a gotcha for people – they might enable tracing then forget to keep a reference to the object long term?

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

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

Likely a good idea.

@AndreasMadsen AndreasMadsen Apr 5, 2018 •

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

I don't really like that the categories are disabled if the Tracing object is garbage collected. We don't remove hooks in async_hooks just because the hooks object is removed. We don't stop a setTimeout just because the timer object is removed. I think it is perfectly natural to do:

trace_events.createTracing({ categories: ['node.http'] }).enable();

without ever disabling it again.

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

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

In that case, however, it would be trivial to put this call into a context where it is never garbage collected, then you'd accomplish the same goal.

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

In that case, however, it would be trivial to put this call into a context where it is never garbage collected, then you'd accomplish the same goal.

I'm not really buying that as a good argument. You could say that about a lot of APIs we have. As a general rule, I don't think garbage collection should have side-effects.

Could we turn this discussion around, where you argue why it should have this side effect?

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

I do think letting users lose a reference to hooks is less bad as this is. I would note that the hooks objects has no chance of being collected anyway, as it's typically referenced by the closures that are passed to the hook.

I agree that this matches the behavior of async_hooks.

setTimeout  is something that resolve itself. It does not leave any resource occupied after it's done, so it's not related.
I do agree that unused fd should be automatically closed.

I keep disagreeing with this approach, however let's land this and iterate separately, as it would need to be changed in async_hooks as well.

This central question: "is cleanup directly observable by the users?", is why I find calling tracer.disable() on GC a really bad idea.

I find it as bad as allocating resources that could not be collected in the future.

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

setTimeout is something that resolve itself. It does not leave any resource occupied after it's done, so it's not related.

setInterval then.

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

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

setInterval() is also a bit of a special case here because it's not going to be gc'd at all while the timer is running and the behavior with it is well established and expected with it by this point. If setInterval() were introduced today I'd be much more likely to advocate for more closely following the browser implementation that returns a number identifying the timer rather than an object, allowing clearInterval() to be called from any context. I'd also prefer to have an API that lets me discover which intervals are active. That ship has sailed for that particular API, however.

Another possible approach on this is to encourage folks to proactively disable the handles rather than wait for gc the same way we do with the new FileHandle class in fs.promises. Essentially, emit a warning if the categories are disabled implicitly on gc rather than explicitly by calling the disable() method. It would be much more likely to encourage better API use while still cleaning up after ourselves.

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

If setInterval() were introduced today I'd be much more likely to advocate for more closely following the browser implementation that returns a number identifying the timer rather than an object, allowing clearInterval() to be called from any context.

What do we mean by context, maybe that is what I don't understand? How do you know what number to use?

Other examples:

  • child = child_process.spawn() could call child.kill().
  • server = http.createServer() could call server.close().
  • request = http.request() could call request.end().
  • stream = new zlib.Deflate() could call stream.close().
  • stream = new crypto.createHash() could call stream.end().

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

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

For child_process.spawn(), yes it could, but again, the ship has long sailed for that particular API and the current behavior is what is expected. I actually wouldn't mind an optional setting that would allow the spawned process to be torn down if the child handle was gc'd.

For the other examples: server won't gc if it's an active handle. By the time it gc's, there should not be anything left to clean up and calling close() certainly would not be the correct choice. Generally likewise for request, and the two stream examples so I don't see those as being comparable.


Only trace event categories *not* covered by other enabled `Tracing` objects
and *not* specified by the `--trace-event-categories` flag will be disabled.

```js
const trace_events = require('trace_events');
const t1 = trace_events.createTracing({ categories: ['node', 'v8'] });
const t2 = trace_events.createTracing({ categories: ['node.perf', 'node'] });
t1.enable();
t2.enable();

// Prints 'node,node.perf,v8'
console.log(trace_events.getEnabledCategories());

t2.disable(); // will only disable emission of the 'node.perf' category

// Prints 'node,v8'
console.log(trace_events.getEnabledCategories());
```

#### `tracing.enable()`
<!-- YAML
added: REPLACEME
-->

Enables this `Tracing` object for the set of categories covered by the
`Tracing` object.

#### `tracing.enabled`
<!-- YAML
added: REPLACEME
-->

* {boolean} `true` only if the `Tracing` object has been enabled.

### `trace_events.createTracing(options)`
<!-- YAML
added: REPLACEME
-->

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

Creates and returns a `Tracing` object for the given set of `categories`.

```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();
```

### `trace_events.getEnabledCategories()`
<!-- YAML
added: REPLACEME
-->

* Returns: {string}

Returns a comma-separated list 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
enabled using the `--trace-event-categories` flag.

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.

Copy link
Copy Markdown
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.

```js
const trace_events = require('trace_events');
const t1 = trace_events.createTracing({ categories: ['node.async_hooks'] });
const t2 = trace_events.createTracing({ categories: ['node.perf'] });
const t3 = trace_events.createTracing({ categories: ['v8'] });

t1.enable();
t2.enable();

console.log(trace_events.getEnabledCategories());
```

### `trace_events.getEnabledTracingObjects()`
<!-- YAML
added: REPLACEME
-->

* Returns: {Tracing[]}

Returns an array of currently enabled `Tracing` objects.

[Performance API]: perf_hooks.html
3 changes: 3 additions & 0 deletions lib/internal/errors.js
Original file line number Diff line number Diff line change
Expand Up @@ -982,6 +982,9 @@ E('ERR_TLS_REQUIRED_SERVER_NAME',
E('ERR_TLS_SESSION_ATTACK', 'TLS session renegotiation attack detected', Error);
E('ERR_TLS_SNI_FROM_SERVER',
'Cannot issue SNI from a TLS server-side socket', Error);
E('ERR_TRACE_EVENTS_CATEGORY_REQUIRED',
'At least one category is required', TypeError);
E('ERR_TRACE_EVENTS_UNAVAILABLE', 'Trace events are unavailable', Error);
E('ERR_TRANSFORM_ALREADY_TRANSFORMING',
'Calling transform done when still transforming', Error);

Expand Down
3 changes: 2 additions & 1 deletion lib/internal/modules/cjs/helpers.js
Original file line number Diff line number Diff line change
Expand Up @@ -101,7 +101,8 @@ const builtinLibs = [
'assert', 'async_hooks', 'buffer', 'child_process', 'cluster', 'crypto',
'dgram', 'dns', 'domain', 'events', 'fs', 'http', 'http2', 'https', 'net',
'os', 'path', 'perf_hooks', 'punycode', 'querystring', 'readline', 'repl',
'stream', 'string_decoder', 'tls', 'tty', 'url', 'util', 'v8', 'vm', 'zlib'
'stream', 'string_decoder', 'tls', 'trace_events', 'tty', 'url', 'util',
'v8', 'vm', 'zlib'
];

if (typeof process.binding('inspector').open === 'function') {
Expand Down
86 changes: 86 additions & 0 deletions lib/trace_events.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,86 @@
'use strict';

const { hasTracing } = process.binding('config');
const kHandle = Symbol('handle');
const kEnabled = Symbol('enabled');
const kCategories = Symbol('categories');

const {
ERR_TRACE_EVENTS_CATEGORY_REQUIRED,
ERR_TRACE_EVENTS_UNAVAILABLE,
ERR_INVALID_ARG_TYPE
} = require('internal/errors').codes;

if (!hasTracing)
throw new ERR_TRACE_EVENTS_UNAVAILABLE();

const { CategorySet, getEnabledCategories } = process.binding('trace_events');
const { customInspectSymbol } = require('internal/util');
const { format } = require('util');

const enabledTracingObjects = new Set();

class Tracing {
constructor(categories) {
this[kHandle] = new CategorySet(categories);
this[kCategories] = categories;
this[kEnabled] = false;
}

enable() {
if (!this[kEnabled]) {
this[kEnabled] = true;
this[kHandle].enable();
enabledTracingObjects.add(this);
}
}

disable() {
if (this[kEnabled]) {
this[kEnabled] = false;
this[kHandle].disable();
enabledTracingObjects.delete(this);
}
}

get enabled() {
return this[kEnabled];
}

get categories() {
return this[kCategories].join(',');
}

[customInspectSymbol](depth, opts) {
const obj = {
enabled: this.enabled,
categories: this.categories
};
return `Tracing ${format(obj)}`;
}
}

function createTracing(options) {
if (typeof options !== 'object' || options == null)
throw new ERR_INVALID_ARG_TYPE('options', 'object', options);

if (!Array.isArray(options.categories)) {
throw new ERR_INVALID_ARG_TYPE('options.categories', 'string[]',
options.categories);
}

if (options.categories.length <= 0)
throw new ERR_TRACE_EVENTS_CATEGORY_REQUIRED();

return new Tracing(options.categories);
}

function getEnabledTracingObjects() {

Copy link
Copy Markdown
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

@jasnell jasnell Apr 16, 2018 •

Copy link
Copy Markdown
Member Author

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
Copy Markdown
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
Copy Markdown
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.

return Array.from(enabledTracingObjects);
}

module.exports = {
createTracing,
getEnabledCategories,
getEnabledTracingObjects
};
1 change: 1 addition & 0 deletions node.gyp
Original file line number Diff line number Diff line change
Expand Up @@ -73,6 +73,7 @@
'lib/tls.js',
'lib/_tls_common.js',
'lib/_tls_wrap.js',
'lib/trace_events.js',
'lib/tty.js',
'lib/url.js',
'lib/util.js',
Expand Down
5 changes: 5 additions & 0 deletions src/env-inl.h
Original file line number Diff line number Diff line change
Expand Up @@ -32,6 +32,7 @@
#include "v8.h"
#include "node_perf_common.h"
#include "node_context_data.h"
#include "tracing/agent.h"

#include <stddef.h>
#include <stdint.h>
Expand Down Expand Up @@ -325,6 +326,10 @@ inline v8::Isolate* Environment::isolate() const {
return isolate_;
}

inline tracing::Agent* Environment::tracing_agent() const {
return tracing_agent_;
}

inline Environment* Environment::from_immediate_check_handle(
uv_check_t* handle) {
return ContainerOf(&Environment::immediate_check_handle_, handle);
Expand Down
5 changes: 4 additions & 1 deletion src/env.cc
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,7 @@
#include "node_buffer.h"
#include "node_platform.h"
#include "node_file.h"
#include "tracing/agent.h"

#include <stdio.h>
#include <algorithm>
Expand Down Expand Up @@ -87,9 +88,11 @@ void InitThreadLocalOnce() {
}

Environment::Environment(IsolateData* isolate_data,
Local<Context> context)
Local<Context> context,
tracing::Agent* tracing_agent)
: isolate_(context->GetIsolate()),
isolate_data_(isolate_data),
tracing_agent_(tracing_agent),
immediate_info_(context->GetIsolate()),
tick_info_(context->GetIsolate()),
timer_base_(uv_now(isolate_data->event_loop())),
Expand Down
Loading