Trace event support for Node.js #9304

matthewloring · 2016-10-26T23:53:35Z

Checklist

make -j8 test (UNIX), or vcbuild test nosign (Windows) passes
documentation is changed or added
commit message follows commit guidelines

Affected core subsystem(s)

src

Description of change

Background: nodejs/diagnostics#30, nodejs/diagnostics#53

This PR adds support for trace-event tracing to Node.js. It provides a mechanism to centralize tracing information generated by V8, Node core, and userspace code. The PR contains a few components:

A trace writer responsible for serializing traces and cycling the output files so that no individual file becomes to large.
A buffer for aggregating traces to allow for batched flushes.
An agent which initializes the tracing controller and ensures that trace serialization is done on a separate thread.
A set of macros for generating trace events.

Generating Trace Events

This PR introduces macros for recording trace events. Synchronous operations can be traced by wrapping them with the appropriate macros:

TRACE_EVENT_BEGIN0("MY_CATEGORY", "SomethingCostly")
doSomethingCostly()
TRACE_EVENT_END0("MY_CATEGORY", "SomethingCostly")

Asynchronous operations can be traced using:

void StartAsyncOperation(int operation_id, ...) {
  TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("category", "operation", operation_id);
  ...
}
void EndAsyncOperation(int operation_id, ...) {
  TRACE_EVENT_NESTABLE_ASYNC_END0("category", "operation", operation_id);
  ...
}

An example of async traces can be seen below. The example was generated by integrating the above macros into Async-Wrap.

Additional examples as well as a complete list of trace macros can be found in src/tracing/trace_event.h. This PR does not introduce any JS interface for generating events or tracing of Node core with the hope that the community can determine how the instrumentation of core should be approached and how this functionality can be exposed to end users.

Viewing Trace Events

The current trace serialization outputs traces in a format that can be visualized by navigating to chrome://tracing in Chrome and loading a trace output file.

We can zoom in on this visualization to view VM events alongside the opening and closing of TCP connections:

Usage

Tracing can be enabled by running:

node --trace-events-enabled server.js

By default, this will record all events in the "v8" and "node" categories. To trace other categories or ignore either of these categories, use the --trace-event-categories flag:

node --trace-events-enabled --trace-event-categories v8,custom-category server.js

This PR is the result of a lot of hard work by @misterpoe, @kjin, @lpy, @fmeawad, and @ofrobots.

Thanks for the review!

/cc @nodejs/diagnostics

AndreasMadsen · 2016-10-27T06:09:05Z

Awesome

An example of async traces can be seen below. The example was generated by integrating the above macros into Async-Wrap.

Should we consider doing this by default?

matthewloring · 2016-10-27T06:14:25Z

@AndreasMadsen I think that could be a good idea and it did generate useful information but I want to keep this PR focused on the core tracing system. I am hoping that instrumentation to generate trace events can be left to a follow on.

cjihrig · 2016-10-27T14:31:14Z

Is it possible to add docs and tests?

matthewloring · 2016-10-27T18:02:35Z

@cjihrig Working on tests now. Are the debugger docs the best place to put doc changes or should they go somewhere else?

cjihrig · 2016-10-27T18:08:52Z

Good question. Do you think there will be enough content to warrant a separate Tracing documentation page? If not, then the Debugger docs or even guides might be an appropriate place.

Others can weigh in here too.

sam-github · 2016-10-27T18:20:46Z

In the example above, trace config doesn't look complex enough to warrant a JSON config file. It can be difficult to arrange for files on disk to appear when wanting to configure node behaviour.

I suggest the example JSON config file would be better expressed as

node --trace-include=v8,custom_category --trace-exclude=node ...

matthewloring · 2016-10-27T21:48:47Z

@cjihrig I've added an end to end test and put some documentation in the debugger docs. Happy to move it if there is a better place.

@sam-github I've updated the description to list the full set of supported configuration options. Though I would anticipate included and excluded categories to be the options relevant to node, V8 does provide additional configuration.

cjihrig · 2016-10-27T22:07:34Z

test/parallel/test-trace-event.js

@@ -0,0 +1,29 @@
+'use strict';
+


Can you include ../common

cjihrig · 2016-10-27T22:09:04Z

test/parallel/test-trace-event.js

+const cp = require('child_process');
+
+const CODE = 'for (var i = 0; i < 100000; i++) { \"test\" + i }';
+const FILE_NAME = 'node_trace.1.log';


The file should probably be written to common.tmpDir.

cjihrig · 2016-10-27T22:09:57Z

test/parallel/test-trace-event.js

+const CODE = 'for (var i = 0; i < 100000; i++) { \"test\" + i }';
+const FILE_NAME = 'node_trace.1.log';
+
+fs.access(FILE_NAME, (err) => {


You can use common.fileExists() to avoid a level of indentation.

cjihrig · 2016-10-27T22:11:17Z

test/parallel/test-trace-event.js

+  const proc = cp.spawn(process.execPath,
+    [ '--enable-tracing', '-e', CODE ]);
+
+  proc.once('exit', () => {


Please add common.mustCall() around the callback.

sam-github · 2016-10-28T02:14:25Z

@matthewloring I still think the configuration should be via CLI options. JSON should be avoided unless necessary, where necessary means "complex data structures", which this doesn't have, its a bunch of boolean or string flags. Its not even nice for dev use... typing CLI options is easy, seeing CLI docs in the help output is easy, having to write your options into a file for a one off trace run is not easy. Sure, do it for permanent config like .eslintrc, but ephemeral config like tracing? Doesn't make sense to me.

I have tooling that allows node monitoring and tracing to be enabled in production, and I've been looking forward to the v8 trace lib getting integrated, pretty excited about this.

Restarting node with new CLI options is easy, having to write my config into filesystem (somewhere, where?) is not convenient. There isn't even a way to guarantee its cleaned up afterwards. I can do it (well, assuming I'm not running in docker with a read-only FS I can do it), but its not a good way.

Trott · 2016-10-28T03:51:51Z

test/parallel/test-trace-event.js

+proc.once('exit', common.mustCall(() => {
+  assert(common.fileExists(FILE_NAME));
+  fs.readFile(FILE_NAME, (err, data) => {
+    fs.unlinkSync(FILE_NAME);


Tiniest of nits that can totally be ignored: No need to clean up after the test in the temp directory. Each test that needs to use the temp directory runs common.refreshTmpDir() which will clean up anything there.

Fixed, thanks.

matthewloring · 2016-10-28T17:03:01Z

@sam-github That makes a lot of sense. I'm happy to introduce command line flags for included/excluded categories and get rid of the json configuration. I'm going to give it a little time before changing this in case anyone has other ideas on configuration approaches.

Fishrock123 · 2016-10-28T22:40:00Z

Does this have any performance impact when off?

fmeawad · 2016-10-28T23:39:42Z

@Fishrock123 The performance impact is minimal specially when off

For every call site, we check if the category is enabled or disabled the first time the call site was visited, and this value is cached so that we do not have to do the expensive category check again.

If tracing was off, then it was enabled: all cached references are updated. And we do that to avoid doing the category check every time we visit the call site.

But that limits the ability to change the enabled categories when tracing is already on. Instead, we need to stop change, then start again.

That being said, trace-events should not be used to track high frequency event*, sampling and runtime stats should be used instead (both are getting standardized in tracing).
*events in tight loops.

trevnorris · 2016-10-30T19:37:44Z

@fmeawad Ignoring the tight loop scenario, a single http request can make 12-18 async calls. A high speed proxy can process upwards of 30k reqs/sec. Which results in 360k-540k async calls/sec. This ignores sync calls that would also be traced (e.g. writes to a socket that are immediately flushed to the kernel). At that volume, what performance impact would we expect to see with this both enabled and disabled?

trevnorris · 2016-10-30T19:40:52Z

On the side, this PR doesn't replace async hooks in any way. The two are complimentary.

jasongin · 2016-10-31T17:14:52Z

doc/api/debugger.md

+`--trace-config` flag:
+
+```txt
+node --enable-trace --trace-config=trace-config.json server.js


--enable-tracing

Thanks, fixed.

jasongin · 2016-10-31T17:33:35Z

doc/api/debugger.md

+node --enable-trace --trace-config=trace-config.json server.js
+```
+
+where `trace-config.json` may override any of the default configuration values:


More clarification would be helpful here:

Are the values below actually the defaults, or just examples?

What are the valid values for record_mode?

What do each of those boolean flags mean?

Are there any other known categories for the node/v8 engine? (I realize user code can add arbitrary tracing categories.)

Configuration has been simplified to just specify enabled categories through a command line flag. Other configuration options are not useful at this time (only one record_mode supported by the buffer, systrace not being used by node, etc). We are working on getting a list of categories compiled here: https://github.com/v8/v8/wiki/Tracing%20V8. Currently node does not introduce any categories of its own. The node category introduced by this PR is just a placeholder and can be updated when the community decides how/where trace points should be added to core.

jasongin · 2016-10-31T17:37:08Z

doc/api/debugger.md

+  "enable_systrace": true,
+  "enable_argument_filter": true,
+  "included_categories": [ "v8", "node" ],
+  "excluded_categories": [ ]


Does excluding categories actually do anything? As far as I can see, TraceConfig::IsCategoryGroupEnabled() ignores that excluded category list, and the list is not checked anywhere else either.

This is used by Chrome since they specify enabled categories using regular expressions which can be refined by excluded categories. The node/v8 category parser doesn't support regexes so this isn't needed at this time.

jasongin · 2016-10-31T17:52:03Z

src/tracing/agent.cc

+    std::string str((std::istreambuf_iterator<char>(fin)),
+                    std::istreambuf_iterator<char>());
+    TraceConfigParser::FillTraceConfig(env->isolate(), trace_config,
+                                       str.c_str());


It looks like the above code will crash if the trace config file is not found or has invalid contents. Is that acceptable? Or should there be a more helpful error message?

fmeawad · 2016-10-31T18:16:21Z

@trevnorris According to my math, If you are using a single thread for that, an async call can take as low as 1.5us, a trace event can take up to 4us, therefore I do not recommend using trace events for that. The off overhead is going to be high as well, it will be ~10% here.

But it seems this is an easy experiment to conduct, and that would be my recommendation here.

matthewloring · 2016-10-31T18:29:45Z

@trevnorris Just for a data point, adding the trace events used to generate the graphs above to async-wrap (but with tracing disabled) caused no change in request latency and ~2% reduction in requests per second for a server with no logic:

var server = http.createServer(function(req, res) {
  res.end('Hello world');
});

The % performance impact would be even lower if the server did anything before responding. We will definitely need to be careful about how many trace points are added and where they go.

jasongin · 2016-10-31T18:50:46Z

src/tracing/trace_config_parser.cc

+bool TraceConfigParser::GetBoolean(Isolate* isolate, Local<Context> context,
+                                   Local<Object> object, const char* property) {
+  Local<Value> value = GetValue(isolate, context, object, property);
+  if (value->IsNumber()) {


Should this be:

if (value->IsNumber() || value->IsBoolean())

I'm not certain IsNumber() is false for a boolean literal, but I'm assuming that's the case.

jasongin · 2016-10-31T22:06:29Z

src/tracing/node_trace_writer.cc

+    Mutex::ScopedLock stream_scoped_lock(stream_mutex_);
+    if (total_traces_ >= kTracesPerFile) {
+      total_traces_ = 0;
+      // Destroying the member JSONTraceWriter object appends "]"\n"" to


"]}" to be more precise. (And no \n.)

Fixed, thanks!

matthewloring · 2016-10-31T22:31:01Z

@sam-github I've updated the category configuration to use the --enabled-categories command line flag.

@jasongin Thank you for the review. This round of comments should all be addressed by the last commit.

jasongin · 2016-10-31T22:40:27Z

doc/api/debugger.md

+Node.js application.
+
+The set of categories for which traces are recorded can be specified using the
+`--enabled-categories` flag followed by a list of comma separated category names.


Probably the categories command-line option should have the word 'tracing' in it somehow, so that it's more obviously associated with tracing. Maybe --tracing-categories?

And is there any way to help avoid confusion with the other command-line options starting with --trace-, which are actually about stack traces?

Hmm, that's a good point. Maybe --enable-trace-events and --trace-event-categories?

Would it make sense to have them all start with --trace-event so its clear they go together. For example:

--trace-events-enabled
--trace-event-categories

Not sure how this fits with the way we use enabled/disabled for existing options but having all options related to trace-events start with the same prefix might make it easier to know they are related.

Updated the flags.

evanlucas · 2017-01-31T16:18:35Z

@matthewloring This isn't landing cleanly on v7.x. Mind submitting a backport PR?

richardlau · 2017-01-31T19:14:46Z

If this is backported please also include #10959.

matthewloring · 2017-02-01T17:57:10Z

@evanlucas I opened a backport PR here: #11106.

Trott · 2017-03-03T06:45:20Z

Adding possibly-gratuitous but hopefully-not-harmful do-not-land labels for 4.x and 6.x. /cc @MylesBorins (3 of 3)

jasnell · 2017-03-03T14:54:59Z

ping @nodejs/lts ... do we want this in 4 and 6?
/cc @nodejs/ctc ... thoughts?

matthewloring · 2017-03-03T23:24:41Z

The versions of V8 in 4 and 6 do not have the APIs that this change depends on.

`node_trace.*.log` files are generated by `NodeTraceWriter`. Refs: nodejs#9304

`node_trace.*.log` files are generated by `NodeTraceWriter`. Refs: #9304 PR-URL: #12754 Reviewed-By: Сковорода Никита Андреевич <[email protected]> Reviewed-By: James M Snell <[email protected]> Reviewed-By: Anna Henningsen <[email protected]> Reviewed-By: Colin Ihrig <[email protected]>

`node_trace.*.log` files are generated by `NodeTraceWriter`. Refs: nodejs#9304 PR-URL: nodejs#12754 Reviewed-By: Сковорода Никита Андреевич <[email protected]> Reviewed-By: James M Snell <[email protected]> Reviewed-By: Anna Henningsen <[email protected]> Reviewed-By: Colin Ihrig <[email protected]>

`node_trace.*.log` files are generated by `NodeTraceWriter`. Refs: #9304 PR-URL: #12754 Reviewed-By: Сковорода Никита Андреевич <[email protected]> Reviewed-By: James M Snell <[email protected]> Reviewed-By: Anna Henningsen <[email protected]> Reviewed-By: Colin Ihrig <[email protected]>

matthewloring added the c++ Issues and PRs that require attention from people who are familiar with C++. label Oct 26, 2016

nodejs-github-bot added build Issues and PRs related to build files or the CI. c++ Issues and PRs that require attention from people who are familiar with C++. labels Oct 26, 2016

mscdex removed the build Issues and PRs related to build files or the CI. label Oct 27, 2016

cjihrig reviewed Oct 27, 2016

View reviewed changes

Trott reviewed Oct 28, 2016

View reviewed changes

jasongin reviewed Oct 31, 2016

View reviewed changes

joshgav mentioned this pull request Oct 31, 2016

doc: update Diag WG info #9329

Merged

2 tasks

jasongin reviewed Oct 31, 2016

View reviewed changes

mscdex added the trace_events Issues and PRs related to V8, Node.js core, and userspace code trace events. label Jan 29, 2017

evanlucas added the dont-land-on-v7.x label Jan 31, 2017

This was referenced Jan 31, 2017

Fix trace warnings #10416

Merged

src: always initialize tracing controller in agent #10507

Closed

tracing: fix TracingController cleanup #10623

Closed

matthewloring mentioned this pull request Feb 1, 2017

v7.x backport: src: add tracing controller #11106

Closed

This was referenced Feb 6, 2017

src: separate trace_event_common from trace_event #10628

Closed

[trace_event] tracking issue nodejs/diagnostics#84

Open

targos mentioned this pull request Mar 2, 2017

github labelling to more clearly indicate state of PRs wrt. backporting nodejs/Release#183

Closed

Trott mentioned this pull request Mar 3, 2017

test: increase strictness for test-trace-event #11065

Closed

2 tasks

Trott added dont-land-on-v4.x labels Mar 3, 2017

jasnell mentioned this pull request Apr 4, 2017

8.0.0 Release Proposal #12220

Closed

jasnell mentioned this pull request Apr 25, 2017

Collaborator nominations #12646

Closed

watilde mentioned this pull request Apr 30, 2017

tools: ignore node_trace.*.log #12754

Closed

2 tasks

watilde added a commit to watilde/node that referenced this pull request May 1, 2017

tools: ignore node_trace.*.log

f4b82ae

`node_trace.*.log` files are generated by `NodeTraceWriter`. Refs: nodejs#9304

Trace event support for Node.js #9304

Trace event support for Node.js #9304

Conversation

matthewloring commented Oct 26, 2016 • edited Loading

Checklist

Affected core subsystem(s)

Description of change

Generating Trace Events

Viewing Trace Events

Usage

AndreasMadsen commented Oct 27, 2016

matthewloring commented Oct 27, 2016

cjihrig commented Oct 27, 2016

matthewloring commented Oct 27, 2016

cjihrig commented Oct 27, 2016

sam-github commented Oct 27, 2016

matthewloring commented Oct 27, 2016

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

sam-github commented Oct 28, 2016

Choose a reason for hiding this comment

Choose a reason for hiding this comment

matthewloring commented Oct 28, 2016

Fishrock123 commented Oct 28, 2016

fmeawad commented Oct 28, 2016 • edited Loading

trevnorris commented Oct 30, 2016

trevnorris commented Oct 30, 2016

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

fmeawad commented Oct 31, 2016 • edited Loading

matthewloring commented Oct 31, 2016 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

matthewloring commented Oct 31, 2016

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

evanlucas commented Jan 31, 2017

richardlau commented Jan 31, 2017

matthewloring commented Feb 1, 2017

Trott commented Mar 3, 2017

jasnell commented Mar 3, 2017

matthewloring commented Mar 3, 2017

matthewloring commented Oct 26, 2016 •

edited

Loading

fmeawad commented Oct 28, 2016 •

edited

Loading

fmeawad commented Oct 31, 2016 •

edited

Loading

matthewloring commented Oct 31, 2016 •

edited

Loading