test: refactor trace event category tests

- Add descriptions
- Filter out the relevant traces for testing, ignore the irrelevant
  ones.

PR-URL: #26605
Reviewed-By: James M Snell <jasnell@gmail.com>
Reviewed-By: Anna Henningsen <anna@addaleax.net>

Author: joyeecheung

test/parallel/test-trace-events-async-hooks-dynamic.js

@@ -1,5 +1,8 @@
 'use strict';
 
+// This tests that tracing can be enabled dynamically with the
+// trace_events module.
+
 const common = require('../common');
 try {
   require('trace_events');
@@ -11,7 +14,6 @@ const assert = require('assert');
 const cp = require('child_process');
 const fs = require('fs');
 const path = require('path');
-const util = require('util');
 
 const enable = `require("trace_events").createTracing(
 { categories: ["node.async_hooks"] }).enable();`;
@@ -32,55 +34,31 @@ const proc = cp.spawnSync(
       'NODE_DEBUG': 'tracing'
     })
   });
-console.log(proc.signal);
-console.log(proc.stderr.toString());
-assert.strictEqual(proc.status, 0);
 
+console.log('process exit with signal:', proc.signal);
+console.log('process stderr:', proc.stderr.toString());
+
+assert.strictEqual(proc.status, 0);
 assert(fs.existsSync(filename));
 const data = fs.readFileSync(filename, 'utf-8');
 const traces = JSON.parse(data).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,node.async_hooks')
-    return false;
-  return true;
-}));
 
-// JavaScript async_hooks trace events should be generated.
-assert(traces.some((trace) => {
+function filterTimeoutTraces(trace) {
   if (trace.pid !== proc.pid)
     return false;
   if (trace.cat !== 'node,node.async_hooks')
     return false;
   if (trace.name !== 'Timeout')
     return false;
   return true;
-}));
+}
 
-// Check args in init events
-const initEvents = traces.filter((trace) => {
-  return (trace.ph === 'b' && !trace.name.includes('_CALLBACK'));
-});
-for (const trace of initEvents) {
-  console.log(trace);
-  if (trace.args.data.executionAsyncId > 0 &&
-    trace.args.data.triggerAsyncId > 0) {
-    continue;
+{
+  const timeoutTraces = traces.filter(filterTimeoutTraces);
+  assert.notDeepStrictEqual(timeoutTraces, []);
+  const threads = new Set();
+  for (const trace of timeoutTraces) {
+    threads.add(trace.tid);
   }
-  assert.fail('Unexpected initEvent: ',
-              util.inspect(trace, { depth: Infinity }));
+  assert.notDeepStrictEqual(timeoutTraces, []);
 }

test/parallel/test-trace-events-async-hooks-worker.js

@@ -1,5 +1,8 @@
 'use strict';
 
+// This tests that enabling node.async_hooks in main threads also
+// affects the workers.
+
 const common = require('../common');
 try {
   require('trace_events');
@@ -11,17 +14,18 @@ const assert = require('assert');
 const cp = require('child_process');
 const fs = require('fs');
 const path = require('path');
-const util = require('util');
 
 const code =
   'setTimeout(() => { for (var i = 0; i < 100000; i++) { "test" + i } }, 1)';
-const worker = `const { Worker } = require('worker_threads');
-  const worker = new Worker('${code}',
-  { eval: true, stdout: true, stderr: true });
-  worker.stdout.on('data',
-    (chunk) => console.log('worker', chunk.toString()));
-  worker.stderr.on('data',
-    (chunk) => console.error('worker', chunk.toString()));`;
+const worker =
+`const { Worker } = require('worker_threads');
+const worker = new Worker('${code}',
+{ eval: true, stdout: true, stderr: true });
+worker.stdout.on('data',
+  (chunk) => console.log('worker', chunk.toString()));
+worker.stderr.on('data',
+  (chunk) => console.error('worker', chunk.toString()));
+worker.on('exit', () => { ${code} })`;
 
 const tmpdir = require('../common/tmpdir');
 const filename = path.join(tmpdir.path, 'node_trace.1.log');
@@ -38,60 +42,32 @@ const proc = cp.spawnSync(
     })
   });
 
-console.log(proc.signal);
-console.log(proc.stderr.toString());
-assert.strictEqual(proc.status, 0);
+console.log('process exit with signal:', proc.signal);
+console.log('process stderr:', proc.stderr.toString());
 
+assert.strictEqual(proc.status, 0);
 assert(fs.existsSync(filename));
 const data = fs.readFileSync(filename, 'utf-8');
 const traces = JSON.parse(data).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,node.async_hooks')
-    return false;
-  return true;
-}));
-
-// JavaScript async_hooks trace events should be generated.
-assert(traces.some((trace) => {
+function filterTimeoutTraces(trace) {
   if (trace.pid !== proc.pid)
     return false;
   if (trace.cat !== 'node,node.async_hooks')
     return false;
   if (trace.name !== 'Timeout')
     return false;
   return true;
-}));
-
-// Check args in init events
-const initEvents = traces.filter((trace) => {
-  return (trace.ph === 'b' && !trace.name.includes('_CALLBACK'));
-});
+}
 
-for (const trace of initEvents) {
-  if (trace.name === 'MESSAGEPORT' &&
-    trace.args.data.executionAsyncId === 0 &&
-    trace.args.data.triggerAsyncId === 0) {
-    continue;
-  }
-  if (trace.args.data.executionAsyncId > 0 &&
-    trace.args.data.triggerAsyncId > 0) {
-    continue;
+{
+  const timeoutTraces = traces.filter(filterTimeoutTraces);
+  assert.notDeepStrictEqual(timeoutTraces, []);
+  const threads = new Set();
+  for (const trace of timeoutTraces) {
+    threads.add(trace.tid);
   }
-  assert.fail('Unexpected initEvent: ',
-              util.inspect(trace, { depth: Infinity }));
+  assert.notDeepStrictEqual(timeoutTraces, []);
+  console.log('Threads with Timeout traces:', threads);
+  assert.strictEqual(threads.size, 2);
 }