Skip to content

trace_events: adds a new trace_events api #19803

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

Closed
wants to merge 3 commits into from
Closed
Show file tree
Hide file tree
Changes from all commits
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
162 changes: 153 additions & 9 deletions doc/api/tracing.md
Original file line number Diff line number Diff line change
@@ -1,16 +1,15 @@
# 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.

The set of categories for which traces are recorded can be specified using the
`--trace-event-categories` flag followed by a list of comma separated category
names.
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
a list of comma-separated category names.

The available categories are:

Expand All @@ -27,7 +26,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.
Copy link
Contributor

@ofrobots ofrobots Apr 5, 2018

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
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
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
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 +64,132 @@ 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`
<!-- YAML
added: REPLACEME
-->

* {string}

A comma-separated list of the trace event categories covered by this
`Tracing` object.
Copy link
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
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
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
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.

Copy link
Member

@AndreasMadsen AndreasMadsen Apr 5, 2018

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
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
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
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
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
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
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
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. Values included
in the array are coerced to a string when possible. An error will be
thrown if the value cannot be coerced.
* 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.

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

[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
89 changes: 89 additions & 0 deletions lib/trace_events.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,89 @@
'use strict';

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

const kMaxTracingCount = 10;

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);
if (enabledTracingObjects.size > kMaxTracingCount) {
process.emitWarning(
'Possible trace_events memory leak detected. There are more than ' +
`${kMaxTracingCount} enabled Tracing objects.`
);
}
}
}

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);
}

module.exports = {
createTracing,
getEnabledCategories
};
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