Repository navigation
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
Changes from 1 commit
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| 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 | ||
| `--trace-event-categories` flag followed by a list of comma separated category | ||
|
|
@@ -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. | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Not a feedback on this PR, but I don't think
Member
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. I think it is for backward compatibility, ultimately I think
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe 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
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe 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 | ||
|
|
@@ -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` | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe 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
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe 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.
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. re: 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
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe 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: 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.
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe 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 |
||
| <!-- YAML | ||
| added: REPLACEME | ||
| --> | ||
|
|
||
| * {string} | ||
|
|
||
| A comma-separated list of the trace event categories covered by this | ||
| `Tracing` object. | ||
|
Member
There was a problem hiding this comment. Choose a reason for hiding this commentThe 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?
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe 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 |
||
|
|
||
| #### `tracing.disable()` | ||
| <!-- YAML | ||
| added: REPLACEME | ||
| --> | ||
|
|
||
| Disables this `Tracing` object. | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe 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
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Likely a good idea.
Member
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. I don't really like that the categories are disabled if the trace_events.createTracing({ categories: ['node.http'] }).enable();without ever disabling it again.
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe 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.
Member
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more.
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?
Member
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. I do think letting users lose a reference to I agree that this matches the behavior of async_hooks.
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.
I find it as bad as allocating resources that could not be collected in the future.
Member
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more.
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more.
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
Member
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more.
What do we mean by Other examples:
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. For For the other examples: |
||
|
|
||
| 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. | ||
|
|
||
|
Member
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Nit: Get rid of everything from 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 | ||
| 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() { | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe 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 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
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe 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
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more.
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.
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe 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 | ||
| }; | ||

There was a problem hiding this comment.
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:
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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 acceptsin the second sentence. Oneacceptsis enough. 😄)There was a problem hiding this comment.
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.)There was a problem hiding this comment.
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?