async_hooks: add trace events to async_hooks

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

PR-URL: https://github.com/nodejs/node/pull/15538
Reviewed-By: Matteo Collina <matteo.collina@gmail.com>
Reviewed-By: James M Snell <jasnell@gmail.com>
Reviewed-By: Anna Henningsen <anna@addaleax.net>

7 files changed, 275 insertions, 41 deletions

diff --git a/test/parallel/test-trace-event.js b/test/parallel/test-trace-event.js
deleted file mode 100644
index 434c7db4d2..0000000000
--- a/test/parallel/test-trace-event.js
+++ /dev/null
@@ -1,41 +0,0 @@
-'use strict';
-const common = require('../common');
-const assert = require('assert');
-const cp = require('child_process');
-const fs = require('fs');
-
-const CODE = 'for (var i = 0; i < 100000; i++) { "test" + i }';
-const FILE_NAME = 'node_trace.1.log';
-
-common.refreshTmpDir();
-process.chdir(common.tmpDir);
-
-const proc_no_categories = cp.spawn(
-  process.execPath,
-  [ '--trace-events-enabled', '--trace-event-categories', '""', '-e', CODE ]
-);
-
-proc_no_categories.once('exit', common.mustCall(() => {
-  assert(!common.fileExists(FILE_NAME));
-
-  const proc = cp.spawn(process.execPath,
-                        [ '--trace-events-enabled', '-e', CODE ]);
-
-  proc.once('exit', common.mustCall(() => {
-    assert(common.fileExists(FILE_NAME));
-    fs.readFile(FILE_NAME, common.mustCall((err, data) => {
-      const traces = JSON.parse(data.toString()).traceEvents;
-      assert(traces.length > 0);
-      // Values that should be present on all runs to approximate correctness.
-      assert(traces.some((trace) => {
-        if (trace.pid !== proc.pid)
-          return false;
-        if (trace.cat !== 'v8')
-          return false;
-        if (trace.name !== 'V8.ScriptCompiler')
-          return false;
-        return true;
-      }));
-    }));
-  }));
-}));
diff --git a/test/parallel/test-trace-events-all.js b/test/parallel/test-trace-events-all.js
new file mode 100644
index 0000000000..329f99f591
--- /dev/null
+++ b/test/parallel/test-trace-events-all.js
@@ -0,0 +1,56 @@
+'use strict';
+const common = require('../common');
+const assert = require('assert');
+const cp = require('child_process');
+const fs = require('fs');
+
+const CODE =
+  'setTimeout(() => { for (var i = 0; i < 100000; i++) { "test" + i } }, 1)';
+const FILE_NAME = 'node_trace.1.log';
+
+common.refreshTmpDir();
+process.chdir(common.tmpDir);
+
+const proc = cp.spawn(process.execPath,
+                      [ '--trace-events-enabled', '-e', CODE ]);
+
+proc.once('exit', common.mustCall(() => {
+  assert(common.fileExists(FILE_NAME));
+  fs.readFile(FILE_NAME, common.mustCall((err, data) => {
+    const traces = JSON.parse(data.toString()).traceEvents;
+    assert(traces.length > 0);
+    // V8 trace events should be generated.
+    assert(traces.some((trace) => {
+      if (trace.pid !== proc.pid)
+        return false;
+      if (trace.cat !== 'v8')
+        return false;
+      if (trace.name !== 'V8.ScriptCompiler')
+        return false;
+      return true;
+    }));
+
+    // C++ async_hooks trace events should be generated.
+    assert(traces.some((trace) => {
+      if (trace.pid !== proc.pid)
+        return false;
+      if (trace.cat !== 'node.async_hooks')
+        return false;
+      if (trace.name !== 'TIMERWRAP')
+        return false;
+      return true;
+    }));
+
+
+    // JavaScript async_hooks trace events should be generated.
+    assert(traces.some((trace) => {
+      if (trace.pid !== proc.pid)
+        return false;
+      if (trace.cat !== 'node.async_hooks')
+        return false;
+      if (trace.name !== 'Timeout')
+        return false;
+      return true;
+    }));
+  }));
+}));
diff --git a/test/parallel/test-trace-events-async-hooks.js b/test/parallel/test-trace-events-async-hooks.js
new file mode 100644
index 0000000000..7f8fb10620
--- /dev/null
+++ b/test/parallel/test-trace-events-async-hooks.js
@@ -0,0 +1,58 @@
+'use strict';
+const common = require('../common');
+const assert = require('assert');
+const cp = require('child_process');
+const fs = require('fs');
+
+const CODE =
+  'setTimeout(() => { for (var i = 0; i < 100000; i++) { "test" + i } }, 1)';
+const FILE_NAME = 'node_trace.1.log';
+
+common.refreshTmpDir();
+process.chdir(common.tmpDir);
+
+const proc = cp.spawn(process.execPath,
+                      [ '--trace-events-enabled',
+                        '--trace-event-categories', 'node.async_hooks',
+                        '-e', CODE ]);
+
+proc.once('exit', common.mustCall(() => {
+  assert(common.fileExists(FILE_NAME));
+  fs.readFile(FILE_NAME, common.mustCall((err, data) => {
+    const traces = JSON.parse(data.toString()).traceEvents;
+    assert(traces.length > 0);
+    // V8 trace events should be generated.
+    assert(!traces.some((trace) => {
+      if (trace.pid !== proc.pid)
+        return false;
+      if (trace.cat !== 'v8')
+        return false;
+      if (trace.name !== 'V8.ScriptCompiler')
+        return false;
+      return true;
+    }));
+
+    // C++ async_hooks trace events should be generated.
+    assert(traces.some((trace) => {
+      if (trace.pid !== proc.pid)
+        return false;
+      if (trace.cat !== 'node.async_hooks')
+        return false;
+      if (trace.name !== 'TIMERWRAP')
+        return false;
+      return true;
+    }));
+
+
+    // JavaScript async_hooks trace events should be generated.
+    assert(traces.some((trace) => {
+      if (trace.pid !== proc.pid)
+        return false;
+      if (trace.cat !== 'node.async_hooks')
+        return false;
+      if (trace.name !== 'Timeout')
+        return false;
+      return true;
+    }));
+  }));
+}));
diff --git a/test/parallel/test-trace-events-binding.js b/test/parallel/test-trace-events-binding.js
new file mode 100644
index 0000000000..628c9cace7
--- /dev/null
+++ b/test/parallel/test-trace-events-binding.js
@@ -0,0 +1,48 @@
+'use strict';
+const common = require('../common');
+const assert = require('assert');
+const cp = require('child_process');
+const fs = require('fs');
+
+const CODE = `
+  process.binding("trace_events").emit(
+    'b'.charCodeAt(0), 'custom',
+    'type-value', 10, 'extra-value', 20);
+  process.binding("trace_events").emit(
+    'b'.charCodeAt(0), 'custom',
+    'type-value', 20);
+  process.binding("trace_events").emit(
+    'b'.charCodeAt(0), 'missing',
+    'type-value', 10, 'extra-value', 20);
+`;
+const FILE_NAME = 'node_trace.1.log';
+
+common.refreshTmpDir();
+process.chdir(common.tmpDir);
+
+const proc = cp.spawn(process.execPath,
+                      [ '--trace-events-enabled',
+                        '--trace-event-categories', 'custom',
+                        '-e', CODE ]);
+
+proc.once('exit', common.mustCall(() => {
+  assert(common.fileExists(FILE_NAME));
+  fs.readFile(FILE_NAME, common.mustCall((err, data) => {
+    const traces = JSON.parse(data.toString()).traceEvents;
+    assert.strictEqual(traces.length, 2);
+
+    assert.strictEqual(traces[0].pid, proc.pid);
+    assert.strictEqual(traces[0].ph, 'b');
+    assert.strictEqual(traces[0].cat, 'custom');
+    assert.strictEqual(traces[0].name, 'type-value');
+    assert.strictEqual(traces[0].id, '0xa');
+    assert.deepStrictEqual(traces[0].args, { 'extra-value': 20 });
+
+    assert.strictEqual(traces[1].pid, proc.pid);
+    assert.strictEqual(traces[1].ph, 'b');
+    assert.strictEqual(traces[1].cat, 'custom');
+    assert.strictEqual(traces[1].name, 'type-value');
+    assert.strictEqual(traces[1].id, '0x14');
+    assert.deepStrictEqual(traces[1].args, { });
+  }));
+}));
diff --git a/test/parallel/test-trace-events-category-used.js b/test/parallel/test-trace-events-category-used.js
new file mode 100644
index 0000000000..39d09ad862
--- /dev/null
+++ b/test/parallel/test-trace-events-category-used.js
@@ -0,0 +1,35 @@
+'use strict';
+const common = require('../common');
+const assert = require('assert');
+const cp = require('child_process');
+
+const CODE = `console.log(
+  process.binding("trace_events").categoryGroupEnabled("custom")
+);`;
+
+common.refreshTmpDir();
+process.chdir(common.tmpDir);
+
+const procEnabled = cp.spawn(
+  process.execPath,
+  [ '--trace-events-enabled', '--trace-event-categories', 'custom', '-e', CODE ]
+);
+let procEnabledOutput = '';
+
+procEnabled.stdout.on('data', (data) => procEnabledOutput += data);
+procEnabled.stderr.pipe(process.stderr);
+procEnabled.once('exit', common.mustCall(() => {
+  assert.strictEqual(procEnabledOutput, 'true\n');
+}));
+
+const procDisabled = cp.spawn(
+  process.execPath,
+  [ '--trace-events-enabled', '--trace-event-categories', 'other', '-e', CODE ]
+);
+let procDisabledOutput = '';
+
+procDisabled.stdout.on('data', (data) => procDisabledOutput += data);
+procDisabled.stderr.pipe(process.stderr);
+procDisabled.once('exit', common.mustCall(() => {
+  assert.strictEqual(procDisabledOutput, 'false\n');
+}));
diff --git a/test/parallel/test-trace-events-none.js b/test/parallel/test-trace-events-none.js
new file mode 100644
index 0000000000..9a4d587f2d
--- /dev/null
+++ b/test/parallel/test-trace-events-none.js
@@ -0,0 +1,20 @@
+'use strict';
+const common = require('../common');
+const assert = require('assert');
+const cp = require('child_process');
+
+const CODE =
+  'setTimeout(() => { for (var i = 0; i < 100000; i++) { "test" + i } }, 1)';
+const FILE_NAME = 'node_trace.1.log';
+
+common.refreshTmpDir();
+process.chdir(common.tmpDir);
+
+const proc_no_categories = cp.spawn(
+  process.execPath,
+  [ '--trace-events-enabled', '--trace-event-categories', '""', '-e', CODE ]
+);
+
+proc_no_categories.once('exit', common.mustCall(() => {
+  assert(!common.fileExists(FILE_NAME));
+}));
diff --git a/test/parallel/test-trace-events-v8.js b/test/parallel/test-trace-events-v8.js
new file mode 100644
index 0000000000..b17b1473ec
--- /dev/null
+++ b/test/parallel/test-trace-events-v8.js
@@ -0,0 +1,58 @@
+'use strict';
+const common = require('../common');
+const assert = require('assert');
+const cp = require('child_process');
+const fs = require('fs');
+
+const CODE =
+  'setTimeout(() => { for (var i = 0; i < 100000; i++) { "test" + i } }, 1)';
+const FILE_NAME = 'node_trace.1.log';
+
+common.refreshTmpDir();
+process.chdir(common.tmpDir);
+
+const proc = cp.spawn(process.execPath,
+                      [ '--trace-events-enabled',
+                        '--trace-event-categories', 'v8',
+                        '-e', CODE ]);
+
+proc.once('exit', common.mustCall(() => {
+  assert(common.fileExists(FILE_NAME));
+  fs.readFile(FILE_NAME, common.mustCall((err, data) => {
+    const traces = JSON.parse(data.toString()).traceEvents;
+    assert(traces.length > 0);
+    // V8 trace events should be generated.
+    assert(traces.some((trace) => {
+      if (trace.pid !== proc.pid)
+        return false;
+      if (trace.cat !== 'v8')
+        return false;
+      if (trace.name !== 'V8.ScriptCompiler')
+        return false;
+      return true;
+    }));
+
+    // C++ async_hooks trace events should be generated.
+    assert(!traces.some((trace) => {
+      if (trace.pid !== proc.pid)
+        return false;
+      if (trace.cat !== 'node.async_hooks')
+        return false;
+      if (trace.name !== 'TIMERWRAP')
+        return false;
+      return true;
+    }));
+
+
+    // JavaScript async_hooks trace events should be generated.
+    assert(!traces.some((trace) => {
+      if (trace.pid !== proc.pid)
+        return false;
+      if (trace.cat !== 'node.async_hooks')
+        return false;
+      if (trace.name !== 'Timeout')
+        return false;
+      return true;
+    }));
+  }));
+}));