Skip to content

Commit

Permalink
trace_events: adds a new trace_events api
Browse files Browse the repository at this point in the history
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>
  • Loading branch information
jasnell committed Apr 17, 2018
1 parent 95fafc0 commit 5c27e44
Show file tree
Hide file tree
Showing 25 changed files with 677 additions and 87 deletions.
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 @@ -1550,6 +1550,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.

```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.

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

Disables this `Tracing` object.

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 @@ -984,6 +984,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

3 comments on commit 5c27e44

@chinhuang007
Copy link
Contributor

Choose a reason for hiding this comment

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

@jasnell Is there any particular reason emit is not exposed as part of the trace_events API? With emit, the JS developers can generate custom trace data using their own categories. They can currently do it anyway via binding. So I think we might as well make emit available in trace_events module.

@jasnell
Copy link
Member Author

@jasnell jasnell commented on 5c27e44 May 9, 2018

Choose a reason for hiding this comment

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

Yes, the emit function that is there is not intended for public use and is not safe but public use.... specifically, it will abort if the inputs are not correct. It's also extremely slow at this point. I am currently working on an implementation of an V8 builtin function that would offer the same functionality in a manner that is much faster. Even still, however, that will not be exposed to user code immediately, as the priority is getting Node.js' own code instrumented with trace events before we open that mechanism up to user code.

@chinhuang007
Copy link
Contributor

Choose a reason for hiding this comment

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

These two issues associated with emit can be mitigated. 1. process will abort with incorrect inputs ==> we clearly document the expected inputs and maybe even allow the process to continue rather than abort? 2. performs slowly ==> it is the same performance impact for node own code instrumentation and custom code trace, so again we can document it. Your fix at the V8 level is an excellent performance boost. However, it does not preclude the use of custom tracing, especially when the trace_events API allows custom trace categories in createTracing. I understand node own tracing has priority. I also believe user code tracing is flexible and useful. So I will write a short doc on the side if nothing is going to change in the trace_events module in the near future.

Please sign in to comment.