async-hooks: add trace events to AsyncWrap

[AndreasMadsen]

rebase of #14347 This is for debugging purposes, I'm getting a segmentation fault when running just node, but with trace_events enables it works. @matthewloring doesn't get the segmentation fault, so I'm running the CI on this PR to check it out.

This will allow trace event to record timing information for all
asynchronous operations that are observed by AsyncWrap.

Checklist

• make -j4 test (UNIX), or vcbuild test (Windows) passes
• tests and/or benchmarks are included
• commit message follows commit guidelines

Affected core subsystem(s)

async_hooks, trace_events

[AndreasMadsen]

CI: https://ci.nodejs.org/job/node-test-pull-request/10185/

[matthewloring]

The CI is segfaulting as well. I can try to reproduce it again.

[matthewloring]

I suspect this is a breakage inside the trace event macros. It has been a few versions of V8 since they were updated so we will probably have to do something like #12127 again. As soon as this change lands, we'll be able to test for such breakages inside node to ensure the macros are updated when new versions of V8 are picked up.

[matthewloring]

Actually it looks like the macros haven't changed much. There were some changes to how the tracing controller is maintained with the new platform implementation. Does this patch help?

diff --git a/src/node.cc b/src/node.cc
index d6678dd967..c14d5229dd 100644
--- a/src/node.cc
+++ b/src/node.cc
@@ -268,7 +268,7 @@ static struct {
         trace_enabled ? tracing_agent_->GetTracingController() : nullptr);
     V8::InitializePlatform(platform_);
     tracing::TraceEventHelper::SetTracingController(
-        trace_enabled ? tracing_agent_->GetTracingController() : nullptr);
+        trace_enabled ? tracing_agent_->GetTracingController() : new v8::TracingController());
   }
 
   void Dispose() {

[AndreasMadsen]

@matthewloring it appears too.

Running a new CI: https://ci.nodejs.org/job/node-test-pull-request/10190/

[AndreasMadsen]

I've added a simple process.binding('trace_events') module that just supports basic emit and categoryGroupEnabled. The latter is to see if a category is enabled, which we should use to check if the node category is enabled. The code is a simplification of that in https://github.com/jasongin/nodejs/tree/tracejs.

There appears to be a bug with categories. Running the code below with node --trace-events-enabled --trace-event-categories v8 benchmark_server.js 10 shows that both v8 and custom are enabled. But only v8 should be enabled. In the trace_events output the custom events are shown too, the reported category for these events is v8.

If node --trace-events-enabled --trace-event-categories custom benchmark_server.js 10 is used, then both v8 and custom are reported disabled and there is no trace_events output.

/cc @jasongin @matthewloring

'use strict';
const http = require('http');
const fs = require('fs');
const trace_events = process.binding('trace_events');

const sleeptime = parseInt(process.argv[2], 10) || 0;
console.log(`sleeping ${sleeptime} ms at each request`);

console.log(trace_events.categoryGroupEnabled('v8'));
console.log(trace_events.categoryGroupEnabled('custom'));

function sleep (msec) {
  var start = Date.now();
  while (Date.now() - start < msec) {}
}

const server = http.createServer(function (req, res) {
  sleep(sleeptime);
  fs.createReadStream(__filename).pipe(res);
});


server.listen(8080, '127.0.0.1', function () {
  let left = 100;
  for (let i = 0; i < 100; i++) {
    trace_events.emit('S'.charCodeAt(0), 'custom', 'request-time', i + 1, 'triggerId', 10)
    http.get('http://127.0.0.1:8080', function (res) {
      res.resume();
      res.on('end', function () {
        trace_events.emit('F'.charCodeAt(0), 'custom', 'request-time', i + 1, 'triggerId', 20)
        left -= 1;
        if (left === 0) server.close();
      });
    });
  }
});

[BridgeAR]

This needs a rebase

[AndreasMadsen]

@addaleax could you take a look? I don't understand why fetching the c-string of args[4] changes the value of name.

[addaleax]

@AndreasMadsen The memory associated with Utf8Value.out() is tied to the lifetime of the Utf8Value itself – you can’t really use GetName like this, sorry.

(It sounds like what happens here is that when name = GetName() is called, the name string is converted to utf8, that memory is returned by GetName(), then freed because the Utf8Value goes out of scope; when you try to update arg_names[0] here, the same thing happens, and this just re-uses the memory allocated for name.)

[AndreasMadsen]

Thanks, this does make sense to me. However, I'm not sure how to appropriately fix it. Can you help me?

[addaleax]

The easiest way would be to just keep the Utf8Value around while you use the string (basically what you do here – this is also what we do in most of the codebase, so grepping around should show enough examples).

The second-easiest thing would probably be to create std::strings from those Utf8Values and use them instead, e.g. GetName() could return a std::string and should start working :)

[AndreasMadsen]

Thanks. I was worried if the if-block scoping would cause some issues.

[addaleax]

Oh – right, the block scope is an issue here. I think you can actually move the Utf8Value declaration to outside of the diff … if that doesn’t work, std::string is probably the way to go

need to take another look later

[addaleax]

Looking at the V8 source code, this doesn’t seem to be true? (https://github.com/nodejs/node/blob/master/deps/v8/src/libplatform/tracing/tracing-controller.cc#L168 & related places use string comparisons, not pointer comparisons)

[AndreasMadsen]

Yeah, I'm confused too. This is where it is documented: https://github.com/nodejs/node/blob/master/src/tracing/trace_event_common.h#L123

[addaleax]

Hm, okay … /cc @matthewloring

[addaleax]

I really can’t make out a code path where this is actually needed … but it would be really good to have that verified by somebody who is familiar with the tracing code

[AndreasMadsen]

Agreed. It is very confusing. I think trace_events runs in a separate thread, can that affect it somehow?

[addaleax]

Feel free to ignore, but common code style is to use braces if the body of an if statement longer than one line

[addaleax]

(feel free to also ignore: common code style is to have } and else (if) on the same line

[addaleax]

You can just use env->context(), and if you want to have context be a local variable I’d put it somewhere near the top (where env is declared as well)

[AndreasMadsen]

I have fixed all issues, added more tests, fixed lint issues and squashed all commits.

This is now ready for review :)

CI: https://ci.nodejs.org/job/node-test-pull-request/10399/

[AndreasMadsen]

/cc @nodejs/diagnostics

[addaleax]

Is this used somewhere?

[addaleax]

I really can’t make out a code path where this is actually needed … but it would be really good to have that verified by somebody who is familiar with the tracing code

[addaleax]

nit: You can pass Locals as Local<Value>, they are basically just pointers so copying them is effectively free

[AndreasMadsen]

@matthewloring so it turns out trace_events isn't that much faster than just using fs.write and template strings to dump the data. Are we doing something wrong?

---

benchmark server tested using 10 wrk runs with default parameters.

'use strict';

const http = require('http');
const fs = require('fs');

const server = http.createServer(function (req, res) {
  fs.createReadStream(__filename).pipe(res);
});


server.listen(8080, '127.0.0.1', function () {
  console.log('http://127.0.0.1:8080');
});

[AndreasMadsen]

CI: https://ci.nodejs.org/job/node-test-pull-request/10409/

[matthewloring]

@AndreasMadsen I'm sorry but I don't fully understand the graph. Are you comparing throughput with trace event active (and trace points inside async wrap) vs. throughput with fs.write calls inside the JS async wrap code?

[AndreasMadsen]

Hmm, I'm not sure if throughput is the right word. It is the requests per second.

The 4 runs are:

• baseline: node server.js
• naive async_hooks(all): node -r log.js server.js
• trace_events async_hooks(all): node --trace-events-enabled --trace-event-categories node.async_hooks server.js
• trace_events async_hooks(cpp): node --trace-events-enabled --trace-event-categories node.async_hooks server.js but with the JS async_hooks consumer always disabled.

log.js

'use strict';

const async_hooks = require('async_hooks');
const fs = require('fs');
const whitelistProviders = new Set(Object.keys(process.binding('async_wrap').Providers));

const providerMap = new Map();
const tick = process.hrtime();
const fd = fs.openSync('naive_async_hooks_event_logger.log', 'w');
let skip = false;

function ts() {
  const tock = process.hrtime(tick);
  return Math.floor(tock[0] * 1e6 + tock[1] * 1e-3);
}

function checkError(err) {
  if (err) throw err;
}

async_hooks.createHook({
  init(asyncId, provider, triggerAsyncId, resource) {
    if (skip) return;
    if (!whitelistProviders.has(provider)) return;
    providerMap.set(asyncId, provider);

    skip = true;
    fs.write(fd, `{"pid":${process.pid},"tid":775,"ts":${ts()},"ph":"b","cat":"node","name":"${provider}","dur":0,"tdur":0,"id":0x"${asyncId.toString(16)}","args":{}}\n`, checkError);
    skip = false;
  },

  before(asyncId) {
    if (!providerMap.has(asyncId)) return;
    const provider = providerMap.get(asyncId);

    skip = true;
    fs.write(fd, `{"pid":${process.pid},"tid":775,"ts":${ts()},"ph":"b","cat":"node","name":"${provider}_CALLBACK","dur":0,"tdur":0,"id":0x"${asyncId.toString(16)}","args":{}}\n`, checkError);
    skip = false;
  },

  after(asyncId) {
    if (!providerMap.has(asyncId)) return;
    const provider = providerMap.get(asyncId);

    skip = true;
    fs.write(fd, `{"pid":${process.pid},"tid":775,"ts":${ts()},"ph":"e","cat":"node","name":"${provider}_CALLBACK","dur":0,"tdur":0,"id":0x"${asyncId.toString(16)}","args":{}}\n`, checkError);
    skip = false;
  },

  destroy(asyncId) {
    if (!providerMap.has(asyncId)) return;
    const provider = providerMap.get(asyncId);
    providerMap.delete(asyncId);

    skip = true;
    fs.write(fd, `{"pid":${process.pid},"tid":775,"ts":${ts()},"ph":"e","cat":"node","name":"${provider}","dur":0,"tdur":0,"id":0x"${asyncId.toString(16)}","args":{}}\n`, checkError);
    skip = false;
  }
}).enable();

process.on('exit', function () {
  fs.closeSync(fd);
});

edit: oh, I guess that comparison isn't fair since run.js it doesn't log the process.nextTick events. I will rerun.

[AndreasMadsen]

Fixed the benchmark. The results are more reasonable now.

---

The comment is collapsed, but could you also look at #15538 (comment)

[matthewloring]

I agree that not logging next ticks would skew the results. I would expect trace events to do substantially better than any logging done from JS but would have to do some profiling to have a more detailed picture.

[AndreasMadsen]

The CI is almost green, I'm getting this error on win2008r2-vs2017/vs2015 specifically.

Mismatched <anonymous> function calls. Expected exactly 1, actual 2.
    at Object.exports.mustCall (c:\workspace\node-test-binary-windows\COMPILED_BY\vs2015\RUNNER\win2008r2-vs2017\RUN_SUBSET\1\test\common\index.js:485:10)
    at Object.<anonymous> (c:\workspace\node-test-binary-windows\COMPILED_BY\vs2015\RUNNER\win2008r2-vs2017\RUN_SUBSET\1\test\parallel\test-async-wrap-uncaughtexception.js:14:33)
    at Module._compile (module.js:600:30)
    at Object.Module._extensions..js (module.js:611:10)
    at Module.load (module.js:521:32)
    at tryModuleLoad (module.js:484:12)
    at Function.Module._load (module.js:476:3)
    at Function.Module.runMain (module.js:641:10)
    at startup (bootstrap_node.js:187:16)

I'm not sure what could have caused that :/

[AndreasMadsen]

running windows CI again: https://ci.nodejs.org/job/node-test-commit-windows-fanned/12263/

[AndreasMadsen]

Ouch, looks like the error is legit. But I'm totally lost how this error could have any relation to this PR. It is also oddly specific to the Windows version and VS version, so I'm not sure there are any good reasons. I'm clueless.

[AndreasMadsen]

/cc @nodejs/platform-windows - Please help :/

[bnoordhuis]

This should have been NODE_BUILTIN_MODULE_CONTEXT_AWARE(...) and probably breaks the shared/static library build. I'll open a PR to rectify and remove NODE_MODULE_CONTEXT_AWARE_BUILTIN() while I'm at it.

edit: #17071

[AndreasMadsen]

Thanks 😂

[bnoordhuis]

Back-porters, this should land along with #17071 (edit: #17071 in turn depends on #16565.)