diff --git a/.github/workflows/build-shared.yml b/.github/workflows/build-shared.yml index 6b0ef92c3df7..05a3ef81215c 100644 --- a/.github/workflows/build-shared.yml +++ b/.github/workflows/build-shared.yml @@ -27,6 +27,11 @@ on: required: false type: boolean default: false + perfetto: + description: Whether the build links perfetto, which the trace event tests need trace_processor_shell for. + required: false + type: boolean + default: false secrets: CACHIX_AUTH_TOKEN: description: Cachix auth token for nodejs.cachix.org. @@ -78,6 +83,11 @@ jobs: core.exportVariable('ACTIONS_RUNTIME_TOKEN', process.env.ACTIONS_RUNTIME_TOKEN || ''); core.exportVariable('NIX_SCCACHE', '(import {}).sccache'); + - name: Get trace_processor + if: inputs.perfetto + shell: bash + run: make -C "$TAR_DIR" trace-processor + - name: Build Node.js and run tests shell: bash run: | diff --git a/.github/workflows/test-linux-perfetto.yml b/.github/workflows/test-linux-perfetto.yml index e300ee59aa86..8629058ea952 100644 --- a/.github/workflows/test-linux-perfetto.yml +++ b/.github/workflows/test-linux-perfetto.yml @@ -62,6 +62,9 @@ jobs: - name: Build working-directory: node run: make build-ci -j4 V=1 CONFIG_FLAGS="--error-on-warn --v8-enable-temporal-support --with-perfetto" + - name: Get trace_processor + working-directory: node + run: make trace-processor - name: Test working-directory: node run: make test-ci -j1 V=1 TEST_CI_ARGS="-p actions --measure-flakiness 9" diff --git a/.github/workflows/test-shared.yml b/.github/workflows/test-shared.yml index be3c22face09..b2da56266dea 100644 --- a/.github/workflows/test-shared.yml +++ b/.github/workflows/test-shared.yml @@ -163,6 +163,7 @@ jobs: with: runner: ${{ matrix.runner }} with-sccache: ${{ github.base_ref == 'main' || github.ref_name == 'main' }} + perfetto: ${{ matrix.perfetto || false }} extra-nix-flags: | --arg useSeparateDerivationForV8 true \ ${{ matrix.perfetto && '--arg withPerfetto true \' || '\' }} diff --git a/.gitignore b/.gitignore index 9277cdf090f0..77359262813b 100644 --- a/.gitignore +++ b/.gitignore @@ -116,6 +116,10 @@ tools/*/*.i.tmp /tools/eslint/node_modules /tools/lint-md/node_modules +# === Rules for tools/perfetto === +/tools/perfetto/trace_processor_shell +/tools/perfetto/.version + # === Rules for test artifacts === /*.tap /*.xml diff --git a/Makefile b/Makefile index 8dec67750f0c..3d1ad1e1987b 100644 --- a/Makefile +++ b/Makefile @@ -235,6 +235,7 @@ distclean: ## Remove all build and test artifacts. $(RM) -r node_modules $(RM) -r deps/icu $(RM) -r deps/icu4c*.tgz deps/icu4c*.zip deps/icu-tmp + $(RM) tools/perfetto/trace_processor_shell tools/perfetto/.version $(RM) $(BINARYTAR).* $(TARBALL).* .PHONY: check @@ -338,6 +339,10 @@ coverage-run-js: ## Run JavaScript tests with coverage. TEST_CI_ARGS="$(TEST_CI_ARGS) --type=coverage" $(MAKE) jstest $(MAKE) coverage-report-js +.PHONY: trace-processor +trace-processor: ## Download perfetto's trace_processor_shell. + @tools/perfetto/get_trace_processor + .PHONY: test # This does not run tests of third-party libraries inside deps. test: all ## Run default tests and build docs. @@ -1319,7 +1324,7 @@ ifeq ($(SKIP_SHARED_DEPS), 1) $(RM) -r $(TARNAME)/deps/ngtcp2 find $(TARNAME)/deps/openssl -maxdepth 1 -type f ! -name 'nodejs-openssl.cnf' -exec $(RM) {} + find $(TARNAME)/deps/openssl -mindepth 1 -maxdepth 1 -type d -exec $(RM) -r {} + - $(RM) -r $(TARNAME)/deps/perfetto + find $(TARNAME)/deps/perfetto -mindepth 1 -maxdepth 1 ! -name 'VERSION' -exec $(RM) -r {} + $(RM) -r $(TARNAME)/deps/simdjson $(RM) -r $(TARNAME)/deps/sqlite $(RM) -r $(TARNAME)/deps/uv diff --git a/test/common/index.js b/test/common/index.js index ce083ee7294e..a2c7106a528c 100755 --- a/test/common/index.js +++ b/test/common/index.js @@ -1029,6 +1029,7 @@ const common = { hasSQLite, hasFFI, hasLocalStorage, + hasPerfetto, invalidArgTypeHelper, isAlive, isASan, diff --git a/test/common/trace_events.js b/test/common/trace_events.js new file mode 100644 index 000000000000..19b714b136e1 --- /dev/null +++ b/test/common/trace_events.js @@ -0,0 +1,64 @@ +'use strict'; + +// Helpers to deal with both Chrome legacy JSON trace format, and Perfetto +// binary format. +// This depends on perfetto's `trace_processor_shell` converts to pftrace format +// to JSON format. Run `make trace-processor` to download it. + +const assert = require('assert'); +const { spawnSync } = require('child_process'); +const fs = require('fs'); +const path = require('path'); +const common = require('./'); + +const traceProcessor = path.resolve( + __dirname, '..', '..', 'tools', 'perfetto', 'trace_processor_shell'); + +// The JSON form of a trace runs about three times the size of the trace it was +// converted from, and the traces these tests produce are a few hundred KiB at +// most. This is an assumed MAX size of a JSON conversion size limit for tests. +const kMaxTraceJsonBytes = 64 * 1024 * 1024; + +const traceFileExt = common.hasPerfetto ? 'pftrace' : 'log'; +const defaultTraceFileName = `node_trace.1.${traceFileExt}`; + +// Only perfetto traces need converting, so a missing `trace_processor_shell` +// does not stop anything on a legacy build. +function checkTraceProcessor() { + if (common.hasPerfetto && !fs.existsSync(traceProcessor)) { + assert.fail('trace_processor_shell is missing, ' + + 'run `make trace-processor` to download it'); + } +} + +function readTraceEvents(file) { + if (!common.hasPerfetto) { + return JSON.parse(fs.readFileSync(file, 'utf8')).traceEvents; + } + + const converted = spawnSync(traceProcessor, ['convert', 'json', file], + { maxBuffer: kMaxTraceJsonBytes }); + assert.ifError(converted.error); + assert.strictEqual( + converted.status, 0, + `trace_processor_shell failed: ${converted.stderr}`); + return JSON.parse(converted.stdout.toString()).traceEvents; +} + +// A perfetto trace event carries the single category it was emitted with. The +// legacy backend instead groups it with every ancestor category, so +// `node.net.native` is recorded as `node,node.net,node.net.native`. +function traceCategory(name) { + if (common.hasPerfetto) { + return name; + } + const parts = name.split('.'); + return parts.map((_, i) => parts.slice(0, i + 1).join('.')).join(','); +} + +module.exports = { + defaultTraceFileName, + readTraceEvents, + checkTraceProcessor, + traceCategory, +}; diff --git a/test/parallel/test-inspector-tracing-domain.js b/test/parallel/test-inspector-tracing-domain.js index b9e62a483e83..688f618f2f79 100644 --- a/test/parallel/test-inspector-tracing-domain.js +++ b/test/parallel/test-inspector-tracing-domain.js @@ -3,6 +3,9 @@ const common = require('../common'); common.skipIfInspectorDisabled(); +// The inspector NodeTracing domain is not wired up on a perfetto build, see +// src/inspector_agent.cc, so every command here fails with +// ERR_INSPECTOR_COMMAND. common.skipIfPerfettoEnabled(); const { isMainThread } = require('worker_threads'); diff --git a/test/parallel/test-module-print-timing.mjs b/test/parallel/test-module-print-timing.mjs index 6b0bfee8431b..409a497fa90e 100644 --- a/test/parallel/test-module-print-timing.mjs +++ b/test/parallel/test-module-print-timing.mjs @@ -7,6 +7,8 @@ import tmpdir from '../common/tmpdir.js'; import { spawnSyncAndAssert } from '../common/child_process.js'; import fixtures from '../common/fixtures.js'; +// The dynamic tracing case below records nothing on a perfetto build: a +// category enabled after the tracing session started stays off. skipIfPerfettoEnabled(); tmpdir.refresh(); diff --git a/test/parallel/test-permission-fs-write-trace-events.js b/test/parallel/test-permission-fs-write-trace-events.js index 37285c3660d2..4ca4fede7bb6 100644 --- a/test/parallel/test-permission-fs-write-trace-events.js +++ b/test/parallel/test-permission-fs-write-trace-events.js @@ -1,11 +1,9 @@ -// Flags: --expose-internals 'use strict'; const common = require('../common'); const { spawnSyncAndExitWithoutError } = require('../common/child_process'); const { isMainThread } = require('worker_threads'); -common.skipIfPerfettoEnabled(); if (!isMainThread) { common.skip('This test only works on a main thread'); } @@ -13,6 +11,7 @@ if (!isMainThread) { const assert = require('assert'); const fs = require('fs'); const tmpdir = require('../common/tmpdir'); +const { defaultTraceFileName } = require('../common/trace_events'); try { require('trace_events'); @@ -56,7 +55,7 @@ assert.throws(() => { }, common.expectsError({ code: 'ERR_ACCESS_DENIED', permission: 'FileSystemWrite', - resource: 'node_trace.1.log', + resource: defaultTraceFileName, })); -assert.strictEqual(fs.existsSync('node_trace.1.log'), false); +assert.strictEqual(fs.existsSync(defaultTraceFileName), false); diff --git a/test/parallel/test-trace-events-all.js b/test/parallel/test-trace-events-all.js deleted file mode 100644 index 107a9ca3a00a..000000000000 --- a/test/parallel/test-trace-events-all.js +++ /dev/null @@ -1,57 +0,0 @@ -'use strict'; -const common = require('../common'); -const assert = require('assert'); -const cp = require('child_process'); -const fs = require('fs'); - -common.skipIfPerfettoEnabled(); - -const CODE = - 'setTimeout(() => { for (let i = 0; i < 100000; i++) { "test" + i } }, 1)'; - -const tmpdir = require('../common/tmpdir'); -tmpdir.refresh(); -const FILE_NAME = tmpdir.resolve('node_trace.1.log'); - -const proc = cp.spawn(process.execPath, - [ '--trace-events-enabled', '-e', CODE ], - { cwd: tmpdir.path }); - -proc.once('exit', common.mustCall(() => { - assert(fs.existsSync(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.startsWith('V8.')) - 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) => { - if (trace.pid !== proc.pid) - return false; - if (trace.cat !== 'node,node.async_hooks') - return false; - if (trace.name !== 'Timeout') - return false; - return true; - })); - })); -})); diff --git a/test/parallel/test-trace-events-async-hooks-dynamic.js b/test/parallel/test-trace-events-async-hooks-dynamic.js index b64582633fb0..8c6ef26e6387 100644 --- a/test/parallel/test-trace-events-async-hooks-dynamic.js +++ b/test/parallel/test-trace-events-async-hooks-dynamic.js @@ -10,6 +10,8 @@ try { common.skip('missing trace events'); } +// Perfetto records nothing for a category enabled after the tracing session +// started, so there is no dynamic enabling to test there yet. common.skipIfPerfettoEnabled(); const assert = require('assert'); diff --git a/test/parallel/test-trace-events-async-hooks.js b/test/parallel/test-trace-events-async-hooks.js deleted file mode 100644 index e81d686c2288..000000000000 --- a/test/parallel/test-trace-events-async-hooks.js +++ /dev/null @@ -1,67 +0,0 @@ -'use strict'; -const common = require('../common'); -const assert = require('assert'); -const cp = require('child_process'); -const fs = require('fs'); -const util = require('util'); - -common.skipIfPerfettoEnabled(); - -const CODE = - 'setTimeout(() => { for (let i = 0; i < 100000; i++) { "test" + i } }, 1)'; - -const tmpdir = require('../common/tmpdir'); -tmpdir.refresh(); -const FILE_NAME = tmpdir.resolve('node_trace.1.log'); - -const proc = cp.spawn(process.execPath, - [ '--trace-event-categories', 'node.async_hooks', - '-e', CODE ], - { cwd: tmpdir.path }); - -proc.once('exit', common.mustCall(() => { - assert(fs.existsSync(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,node.async_hooks') - 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,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')); - }); - assert.ok(initEvents.every((trace) => { - return (trace.args.data.executionAsyncId > 0 && - trace.args.data.triggerAsyncId > 0); - }), `Unexpected initEvents format: ${util.inspect(initEvents)}`); - })); -})); diff --git a/test/parallel/test-trace-events-binding.js b/test/parallel/test-trace-events-binding.js index b4cba883024b..43cd559e4b47 100644 --- a/test/parallel/test-trace-events-binding.js +++ b/test/parallel/test-trace-events-binding.js @@ -4,6 +4,8 @@ const assert = require('assert'); const cp = require('child_process'); const fs = require('fs'); +// V8's trace() builtin only accepts the begin, end and instant phases on a +// perfetto build, so the nestable async phase used here throws a TypeError. common.skipIfPerfettoEnabled(); const CODE = ` diff --git a/test/parallel/test-trace-events-console.js b/test/parallel/test-trace-events-console.js index 4b48695c5688..8dc0a39bf9a7 100644 --- a/test/parallel/test-trace-events-console.js +++ b/test/parallel/test-trace-events-console.js @@ -5,6 +5,9 @@ const cp = require('child_process'); const fs = require('fs'); const tmpdir = require('../common/tmpdir'); +// console.count() throws on a perfetto build once node.console is enabled: +// internal/trace_events picks the nestable async instant phase for counters, +// which V8's trace() builtin rejects there. common.skipIfPerfettoEnabled(); // Tests that node.console trace events for counters and time methods are diff --git a/test/parallel/test-trace-events-dynamic-enable.js b/test/parallel/test-trace-events-dynamic-enable.js index af8f9095b00b..c9802b46d333 100644 --- a/test/parallel/test-trace-events-dynamic-enable.js +++ b/test/parallel/test-trace-events-dynamic-enable.js @@ -4,6 +4,8 @@ const common = require('../common'); common.skipIfInspectorDisabled(); +// Needs two things a perfetto build does not have: the inspector NodeTracing +// domain, and recording for a category enabled after the session started. common.skipIfPerfettoEnabled(); const { isMainThread } = require('worker_threads'); diff --git a/test/parallel/test-trace-events-fs-async.js b/test/parallel/test-trace-events-fs-async.js index 2a658838b39e..30233aeb7350 100644 --- a/test/parallel/test-trace-events-fs-async.js +++ b/test/parallel/test-trace-events-fs-async.js @@ -5,6 +5,11 @@ const cp = require('child_process'); const fs = require('fs'); const util = require('util'); +// MKDir passes UV_FS_UNLINK to FS_ASYNC_TRACE_BEGIN1 (src/node_file.cc), so +// the begin event is named `unlink` while the end event is named `mkdir`. The +// legacy backend records both names, and this test passes off the end event. +// Perfetto matches an async pair by name and drops the unmatched end, leaving +// no `mkdir` event at all. common.skipIfPerfettoEnabled(); const tests = { __proto__: null }; diff --git a/test/parallel/test-trace-events-get-category-enabled-buffer.js b/test/parallel/test-trace-events-get-category-enabled-buffer.js index 929f1ae3f2a8..d00e32cfc22c 100644 --- a/test/parallel/test-trace-events-get-category-enabled-buffer.js +++ b/test/parallel/test-trace-events-get-category-enabled-buffer.js @@ -10,6 +10,8 @@ try { common.skip('missing trace events'); } +// Perfetto aborts on a category that is not in its static registry, and its +// enabled flag does not follow createTracing().enable(). common.skipIfPerfettoEnabled(); const { createTracing, getEnabledCategories } = require('trace_events'); diff --git a/test/parallel/test-trace-events-metadata.js b/test/parallel/test-trace-events-metadata.js index d92615fb94ec..e806a7dda2dc 100644 --- a/test/parallel/test-trace-events-metadata.js +++ b/test/parallel/test-trace-events-metadata.js @@ -4,6 +4,8 @@ const assert = require('assert'); const cp = require('child_process'); const fs = require('fs'); +// A perfetto build drops the legacy metadata events, so none of the +// process_name, version or node entries checked here are recorded. common.skipIfPerfettoEnabled(); const CODE = diff --git a/test/parallel/test-trace-events-v8.js b/test/parallel/test-trace-events-v8.js deleted file mode 100644 index f71c4a057afe..000000000000 --- a/test/parallel/test-trace-events-v8.js +++ /dev/null @@ -1,59 +0,0 @@ -'use strict'; -const common = require('../common'); -const assert = require('assert'); -const cp = require('child_process'); -const fs = require('fs'); - -common.skipIfPerfettoEnabled(); - -const CODE = - 'setTimeout(() => { for (let i = 0; i < 100000; i++) { "test" + i } }, 1)'; - -const tmpdir = require('../common/tmpdir'); -tmpdir.refresh(); -const FILE_NAME = tmpdir.resolve('node_trace.1.log'); - -const proc = cp.spawn(process.execPath, - [ '--trace-events-enabled', - '--trace-event-categories', 'v8', - '-e', CODE ], - { cwd: tmpdir.path }); - -proc.once('exit', common.mustCall(() => { - assert(fs.existsSync(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.startsWith('V8.')) - 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; - 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-worker-metadata-with-name.js b/test/parallel/test-trace-events-worker-metadata-with-name.js index 0140d08a5f01..1fa3d1e5f796 100644 --- a/test/parallel/test-trace-events-worker-metadata-with-name.js +++ b/test/parallel/test-trace-events-worker-metadata-with-name.js @@ -5,6 +5,8 @@ const cp = require('child_process'); const fs = require('fs'); const { isMainThread } = require('worker_threads'); +// A perfetto build names a thread through its track descriptor rather than +// a thread_name metadata event, and without the `[worker ]` prefix. common.skipIfPerfettoEnabled(); if (isMainThread) { diff --git a/test/parallel/test-trace-events-worker-metadata.js b/test/parallel/test-trace-events-worker-metadata.js index 2e6c20255ce7..9e8ebeef5006 100644 --- a/test/parallel/test-trace-events-worker-metadata.js +++ b/test/parallel/test-trace-events-worker-metadata.js @@ -5,6 +5,8 @@ const cp = require('child_process'); const fs = require('fs'); const { isMainThread } = require('worker_threads'); +// A perfetto build names a thread through its track descriptor rather than +// a thread_name metadata event, and without the `[worker ]` prefix. common.skipIfPerfettoEnabled(); if (isMainThread) { diff --git a/test/trace_events/README.md b/test/trace_events/README.md new file mode 100644 index 000000000000..abed2b96d771 --- /dev/null +++ b/test/trace_events/README.md @@ -0,0 +1,10 @@ +# `trace_events` Tests + +When the `node` binary is built with configure flag `--with-perfetto`, +the tests in this folder depends on `tools/perfetto/trace_processor_shell`, +which is downloaded with `tools/perfetto/get_trace_processor` via +`make trace-processor`, to convert Perfetto binary trace files to +JSON format. + +Refer to +for help of the `trace_processor_shell` CLI. diff --git a/test/trace_events/test-trace-events-all.js b/test/trace_events/test-trace-events-all.js new file mode 100644 index 000000000000..fe422d03a77a --- /dev/null +++ b/test/trace_events/test-trace-events-all.js @@ -0,0 +1,62 @@ +'use strict'; +const common = require('../common'); +const assert = require('assert'); +const cp = require('child_process'); +const fs = require('fs'); + +const { + defaultTraceFileName, + readTraceEvents, + checkTraceProcessor, + traceCategory, +} = require('../common/trace_events'); + +checkTraceProcessor(); + +const CODE = + 'setTimeout(() => { for (let i = 0; i < 100000; i++) { "test" + i } }, 1)'; + +const tmpdir = require('../common/tmpdir'); +tmpdir.refresh(); +const FILE_NAME = tmpdir.resolve(defaultTraceFileName); + +const proc = cp.spawn(process.execPath, + [ '--trace-events-enabled', '-e', CODE ], + { cwd: tmpdir.path }); + +proc.once('exit', common.mustCall(() => { + assert(fs.existsSync(FILE_NAME)); + const traces = readTraceEvents(FILE_NAME); + 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.startsWith('V8.')) + 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 !== traceCategory('node.async_hooks')) + 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 !== traceCategory('node.async_hooks')) + return false; + if (trace.name !== 'Timeout') + return false; + return true; + })); +})); diff --git a/test/parallel/test-trace-events-api.js b/test/trace_events/test-trace-events-api.js similarity index 69% rename from test/parallel/test-trace-events-api.js rename to test/trace_events/test-trace-events-api.js index dcbc0ac237e3..6d50213d7750 100644 --- a/test/parallel/test-trace-events-api.js +++ b/test/trace_events/test-trace-events-api.js @@ -4,8 +4,6 @@ const common = require('../common'); const { isMainThread } = require('worker_threads'); -common.skipIfPerfettoEnabled(); - if (!isMainThread) { // https://github.com/nodejs/node/issues/22767 common.skip('This test only works on a main thread'); @@ -21,11 +19,18 @@ const assert = require('assert'); const cp = require('child_process'); const fs = require('fs'); const tmpdir = require('../common/tmpdir'); +const { + defaultTraceFileName, + readTraceEvents, + checkTraceProcessor, +} = require('../common/trace_events'); const { createTracing, - getEnabledCategories + getEnabledCategories, } = require('trace_events'); +checkTraceProcessor(); + function getEnabledCategoriesFromCommandLine() { const indexOfCatFlag = process.execArgv.indexOf('--trace-event-categories'); if (indexOfCatFlag === -1) { @@ -41,11 +46,11 @@ assert.strictEqual(getEnabledCategories(), enabledCategories); for (const i of [1, 'foo', true, false, null, undefined]) { assert.throws(() => createTracing(i), { code: 'ERR_INVALID_ARG_TYPE', - name: 'TypeError' + name: 'TypeError', }); assert.throws(() => createTracing({ categories: i }), { code: 'ERR_INVALID_ARG_TYPE', - name: 'TypeError' + name: 'TypeError', }); } @@ -53,8 +58,8 @@ assert.throws( () => createTracing({ categories: [] }), { code: 'ERR_TRACE_EVENTS_CATEGORY_REQUIRED', - name: 'TypeError' - } + name: 'TypeError', + }, ); const tracing = createTracing({ categories: [ 'node.perf' ] }); @@ -84,22 +89,19 @@ tracing2.disable(); // Purposefully disable twice to test calling twice assert.strictEqual(getEnabledCategories(), enabledCategories); if (isChild) { - const { internalBinding } = require('internal/test/binding'); - + // Perfetto only accepts the synchronous begin/end phases, so take the phase + // constants from internal/trace_events, which picks the right pair. const { - trace: { - TRACE_EVENT_PHASE_NESTABLE_ASYNC_BEGIN: kBeforeEvent, - TRACE_EVENT_PHASE_NESTABLE_ASYNC_END: kEndEvent, - } - } = internalBinding('constants'); - - const { trace } = internalBinding('trace_events'); + trace, + kAsyncBegin, + kAsyncEnd, + } = require('internal/trace_events'); tracing.enable(); - trace(kBeforeEvent, 'foo', 'test1', 0, 'test'); + trace(kAsyncBegin, 'foo', 'test1', 0, 'test'); setTimeout(() => { - trace(kEndEvent, 'foo', 'test1'); + trace(kAsyncEnd, 'foo', 'test1'); }, 1); } else { // Test that enabled tracing references do not get garbage collected @@ -138,8 +140,9 @@ function testApiInChildProcess(execArgs, cb) { const parentDir = process.cwd(); process.chdir(tmpdir.path); - const expectedBegins = [{ cat: 'foo', name: 'test1' }]; - const expectedEnds = [{ cat: 'foo', name: 'test1' }]; + // The child emits one begin/end pair. Perfetto merges a pair into a single + // complete event when the trace is converted back. + const expectedPhases = common.hasPerfetto ? ['X'] : ['b', 'e']; const proc = cp.fork(__filename, ['child'], @@ -149,41 +152,24 @@ function testApiInChildProcess(execArgs, cb) { '--expose-internals', '--no-warnings', ...execArgs, - ] + ], }); proc.once('exit', common.mustCall(() => { - const file = tmpdir.resolve('node_trace.1.log'); - + const file = tmpdir.resolve(defaultTraceFileName); assert(fs.existsSync(file)); - fs.readFile(file, common.mustSucceed((data) => { - const traces = JSON.parse(data.toString()).traceEvents - .filter((trace) => trace.cat !== '__metadata'); - - assert.strictEqual( - traces.length, - expectedBegins.length + expectedEnds.length); - for (const trace of traces) { - assert.strictEqual(trace.pid, proc.pid); - switch (trace.ph) { - case 'b': { - const expectedBegin = expectedBegins.shift(); - assert.strictEqual(trace.cat, expectedBegin.cat); - assert.strictEqual(trace.name, expectedBegin.name); - break; - } - case 'e': { - const expectedEnd = expectedEnds.shift(); - assert.strictEqual(trace.cat, expectedEnd.cat); - assert.strictEqual(trace.name, expectedEnd.name); - break; - } - default: - assert.fail('Unexpected trace event phase'); - } - } - process.chdir(parentDir); - cb && process.nextTick(cb); - })); + + const traces = readTraceEvents(file) + .filter((trace) => trace.cat !== '__metadata'); + + assert.deepStrictEqual(traces.map((trace) => trace.ph), expectedPhases); + for (const trace of traces) { + assert.strictEqual(trace.pid, proc.pid); + assert.strictEqual(trace.cat, 'foo'); + assert.strictEqual(trace.name, 'test1'); + } + + process.chdir(parentDir); + cb && process.nextTick(cb); })); } diff --git a/test/parallel/test-trace-events-async-hooks-worker.js b/test/trace_events/test-trace-events-async-hooks-worker.js similarity index 83% rename from test/parallel/test-trace-events-async-hooks-worker.js rename to test/trace_events/test-trace-events-async-hooks-worker.js index f4c56653e280..4fdeb2138ebe 100644 --- a/test/parallel/test-trace-events-async-hooks-worker.js +++ b/test/trace_events/test-trace-events-async-hooks-worker.js @@ -10,11 +10,17 @@ try { common.skip('missing trace events'); } -common.skipIfPerfettoEnabled(); - const assert = require('assert'); const cp = require('child_process'); const fs = require('fs'); +const { + defaultTraceFileName, + readTraceEvents, + checkTraceProcessor, + traceCategory, +} = require('../common/trace_events'); + +checkTraceProcessor(); const code = 'setTimeout(() => { for (let i = 0; i < 100000; i++) { "test" + i } }, 1)'; @@ -29,7 +35,7 @@ worker.stderr.on('data', worker.on('exit', () => { ${code} })`; const tmpdir = require('../common/tmpdir'); -const filename = tmpdir.resolve('node_trace.1.log'); +const filename = tmpdir.resolve(defaultTraceFileName); tmpdir.refresh(); const proc = cp.spawnSync( @@ -39,7 +45,7 @@ const proc = cp.spawnSync( cwd: tmpdir.path, env: { ...process.env, 'NODE_DEBUG_NATIVE': 'tracing', - 'NODE_DEBUG': 'tracing' } + 'NODE_DEBUG': 'tracing' }, }); console.log('process exit with signal:', proc.signal); @@ -47,13 +53,12 @@ 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; +const traces = readTraceEvents(filename); function filterTimeoutTraces(trace) { if (trace.pid !== proc.pid) return false; - if (trace.cat !== 'node,node.async_hooks') + if (trace.cat !== traceCategory('node.async_hooks')) return false; if (trace.name !== 'Timeout') return false; diff --git a/test/trace_events/test-trace-events-async-hooks.js b/test/trace_events/test-trace-events-async-hooks.js new file mode 100644 index 000000000000..c404402594a1 --- /dev/null +++ b/test/trace_events/test-trace-events-async-hooks.js @@ -0,0 +1,74 @@ +'use strict'; +const common = require('../common'); +const assert = require('assert'); +const cp = require('child_process'); +const fs = require('fs'); +const util = require('util'); + +const { + defaultTraceFileName, + readTraceEvents, + checkTraceProcessor, + traceCategory, +} = require('../common/trace_events'); + +checkTraceProcessor(); + +const CODE = + 'setTimeout(() => { for (let i = 0; i < 100000; i++) { "test" + i } }, 1)'; + +const tmpdir = require('../common/tmpdir'); +tmpdir.refresh(); +const FILE_NAME = tmpdir.resolve(defaultTraceFileName); + +const proc = cp.spawn(process.execPath, + [ '--trace-event-categories', 'node.async_hooks', + '-e', CODE ], + { cwd: tmpdir.path }); + +proc.once('exit', common.mustCall(() => { + assert(fs.existsSync(FILE_NAME)); + const traces = readTraceEvents(FILE_NAME); + assert(traces.length > 0); + // V8 trace events should not 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 !== traceCategory('node.async_hooks')) + 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 !== traceCategory('node.async_hooks')) + return false; + if (trace.name !== 'Timeout') + return false; + return true; + })); + + // Check args in init events. Perfetto records the begin/end pair of an + // async_hooks event as one complete event. + const initPhase = common.hasPerfetto ? 'X' : 'b'; + const initEvents = traces.filter((trace) => { + return (trace.ph === initPhase && !trace.name.includes('_CALLBACK')); + }); + assert.ok(initEvents.every((trace) => { + return (trace.args.data.executionAsyncId > 0 && + trace.args.data.triggerAsyncId > 0); + }), `Unexpected initEvents format: ${util.inspect(initEvents)}`); +})); diff --git a/test/parallel/test-trace-events-bootstrap.js b/test/trace_events/test-trace-events-bootstrap.js similarity index 64% rename from test/parallel/test-trace-events-bootstrap.js rename to test/trace_events/test-trace-events-bootstrap.js index 56a35ee8c759..dfead479bb7c 100644 --- a/test/parallel/test-trace-events-bootstrap.js +++ b/test/trace_events/test-trace-events-bootstrap.js @@ -5,7 +5,13 @@ const cp = require('child_process'); const fs = require('fs'); const tmpdir = require('../common/tmpdir'); -common.skipIfPerfettoEnabled(); +const { + defaultTraceFileName, + readTraceEvents, + checkTraceProcessor, +} = require('../common/trace_events'); + +checkTraceProcessor(); const names = [ 'environment', @@ -27,20 +33,18 @@ if (process.argv[2] === 'child') { execArgv: [ '--trace-event-categories', 'node.bootstrap', - ] + ], }); proc.once('exit', common.mustCall(() => { - const file = tmpdir.resolve('node_trace.1.log'); + const file = tmpdir.resolve(defaultTraceFileName); assert(fs.existsSync(file)); - fs.readFile(file, common.mustSucceed((data) => { - const traces = JSON.parse(data.toString()).traceEvents - .filter((trace) => trace.cat !== '__metadata'); - traces.forEach((trace) => { - assert.strictEqual(trace.pid, proc.pid); - assert(names.includes(trace.name)); - }); - })); + const traces = readTraceEvents(file) + .filter((trace) => trace.cat !== '__metadata'); + traces.forEach((trace) => { + assert.strictEqual(trace.pid, proc.pid); + assert(names.includes(trace.name)); + }); })); } diff --git a/test/parallel/test-trace-events-environment.js b/test/trace_events/test-trace-events-environment.js similarity index 82% rename from test/parallel/test-trace-events-environment.js rename to test/trace_events/test-trace-events-environment.js index 46de418caf13..07561e58a948 100644 --- a/test/parallel/test-trace-events-environment.js +++ b/test/trace_events/test-trace-events-environment.js @@ -7,7 +7,13 @@ const cp = require('child_process'); const fs = require('fs'); const tmpdir = require('../common/tmpdir'); -common.skipIfPerfettoEnabled(); +const { + defaultTraceFileName, + readTraceEvents, + checkTraceProcessor, +} = require('../common/trace_events'); + +checkTraceProcessor(); // This tests the emission of node.environment trace events @@ -39,16 +45,15 @@ if (process.argv[2] === 'child') { execArgv: [ '--trace-event-categories', 'node.environment', - ] + ], }); - proc.once('exit', common.mustCall(async () => { - const file = tmpdir.resolve('node_trace.1.log'); + proc.once('exit', common.mustCall(() => { + const file = tmpdir.resolve(defaultTraceFileName); const checkSet = new Set(); assert(fs.existsSync(file)); - const data = await fs.promises.readFile(file); - for (const trace of JSON.parse(data.toString()).traceEvents + for (const trace of readTraceEvents(file) .filter((trace) => trace.cat !== '__metadata')) { assert.strictEqual(trace.pid, proc.pid); assert(names.has(trace.name)); diff --git a/test/parallel/test-trace-events-file-pattern.js b/test/trace_events/test-trace-events-file-pattern.js similarity index 79% rename from test/parallel/test-trace-events-file-pattern.js rename to test/trace_events/test-trace-events-file-pattern.js index 3e6e339173f6..4b053aeb60cb 100644 --- a/test/parallel/test-trace-events-file-pattern.js +++ b/test/trace_events/test-trace-events-file-pattern.js @@ -5,7 +5,12 @@ const assert = require('assert'); const cp = require('child_process'); const fs = require('fs'); -common.skipIfPerfettoEnabled(); +const { + readTraceEvents, + checkTraceProcessor, +} = require('../common/trace_events'); + +checkTraceProcessor(); tmpdir.refresh(); @@ -24,8 +29,5 @@ proc.once('exit', common.mustCall(() => { const expectedFilename = tmpdir.resolve(`${proc.pid}-1-${proc.pid}-1.tracing.log`); assert(fs.existsSync(expectedFilename)); - fs.readFile(expectedFilename, common.mustCall((err, data) => { - const traces = JSON.parse(data.toString()).traceEvents; - assert(traces.length > 0); - })); + assert(readTraceEvents(expectedFilename).length > 0); })); diff --git a/test/parallel/test-trace-events-fs-sync.js b/test/trace_events/test-trace-events-fs-sync.js similarity index 95% rename from test/parallel/test-trace-events-fs-sync.js rename to test/trace_events/test-trace-events-fs-sync.js index 800d1a83b64f..0fddb93dfda7 100644 --- a/test/parallel/test-trace-events-fs-sync.js +++ b/test/trace_events/test-trace-events-fs-sync.js @@ -5,7 +5,14 @@ const cp = require('child_process'); const fs = require('fs'); const util = require('util'); -common.skipIfPerfettoEnabled(); +const { + defaultTraceFileName, + readTraceEvents, + checkTraceProcessor, + traceCategory, +} = require('../common/trace_events'); + +checkTraceProcessor(); const tests = { __proto__: null }; @@ -117,7 +124,7 @@ if (common.canCreateSymLink()) { const tmpdir = require('../common/tmpdir'); tmpdir.refresh(); -const traceFile = tmpdir.resolve('node_trace.1.log'); +const traceFile = tmpdir.resolve(defaultTraceFileName); for (const tr in tests) { const proc = cp.spawnSync(process.execPath, @@ -136,15 +143,14 @@ for (const tr in tests) { // Confirm that trace log file is created. assert(fs.existsSync(traceFile)); - const data = fs.readFileSync(traceFile); - const traces = JSON.parse(data.toString()).traceEvents; + const traces = readTraceEvents(traceFile); assert(traces.length > 0); // C++ fs sync trace events should be generated. assert(traces.some((trace) => { if (trace.pid !== proc.pid) return false; - if (trace.cat !== 'node,node.fs,node.fs.sync') + if (trace.cat !== traceCategory('node.fs.sync')) return false; if (trace.name !== tr) return false; diff --git a/test/parallel/test-trace-events-http.js b/test/trace_events/test-trace-events-http.js similarity index 55% rename from test/parallel/test-trace-events-http.js rename to test/trace_events/test-trace-events-http.js index 47ac4dff9b33..32c8bc7d1674 100644 --- a/test/parallel/test-trace-events-http.js +++ b/test/trace_events/test-trace-events-http.js @@ -5,7 +5,14 @@ const cp = require('child_process'); const fs = require('fs'); const tmpdir = require('../common/tmpdir'); -common.skipIfPerfettoEnabled(); +const { + defaultTraceFileName, + readTraceEvents, + checkTraceProcessor, + traceCategory, +} = require('../common/trace_events'); + +checkTraceProcessor(); const CODE = ` const http = require('http'); @@ -18,7 +25,7 @@ const CODE = ` `; tmpdir.refresh(); -const FILE_NAME = tmpdir.resolve('node_trace.1.log'); +const FILE_NAME = tmpdir.resolve(defaultTraceFileName); const proc = cp.spawn(process.execPath, [ '--trace-events-enabled', @@ -28,18 +35,15 @@ const proc = cp.spawn(process.execPath, proc.once('exit', common.mustCall(() => { assert(fs.existsSync(FILE_NAME)); - fs.readFile(FILE_NAME, common.mustCall((err, data) => { - assert(!err); - const traces = JSON.parse(data.toString()).traceEvents; - assert(traces.length > 0); - let count = 0; - for (const trace of traces) { - if (trace.cat === 'node,node.http' && - ['http.server.request', 'http.client.request'].includes(trace.name)) { - count++; - } + const traces = readTraceEvents(FILE_NAME); + assert(traces.length > 0); + let count = 0; + for (const trace of traces) { + if (trace.cat === traceCategory('node.http') && + ['http.server.request', 'http.client.request'].includes(trace.name)) { + count++; } - // Two begin, two end - assert.strictEqual(count, 4); - })); + } + // Two begin and two end, which perfetto records as two complete events. + assert.strictEqual(count, common.hasPerfetto ? 2 : 4); })); diff --git a/test/parallel/test-trace-events-net-abstract-socket.js b/test/trace_events/test-trace-events-net-abstract-socket.js similarity index 55% rename from test/parallel/test-trace-events-net-abstract-socket.js rename to test/trace_events/test-trace-events-net-abstract-socket.js index 9505fb214ad4..4f933be8dd8f 100644 --- a/test/parallel/test-trace-events-net-abstract-socket.js +++ b/test/trace_events/test-trace-events-net-abstract-socket.js @@ -5,8 +5,15 @@ const cp = require('child_process'); const fs = require('fs'); const tmpdir = require('../common/tmpdir'); +const { + defaultTraceFileName, + readTraceEvents, + checkTraceProcessor, + traceCategory, +} = require('../common/trace_events'); + if (!common.isLinux) common.skip(); -common.skipIfPerfettoEnabled(); +checkTraceProcessor(); const CODE = ` const net = require('net'); @@ -15,7 +22,7 @@ const CODE = ` `; tmpdir.refresh(); -const FILE_NAME = tmpdir.resolve('node_trace.1.log'); +const FILE_NAME = tmpdir.resolve(defaultTraceFileName); const proc = cp.spawn(process.execPath, [ '--trace-events-enabled', @@ -25,20 +32,18 @@ const proc = cp.spawn(process.execPath, proc.once('exit', common.mustCall(() => { assert(fs.existsSync(FILE_NAME)); - fs.readFile(FILE_NAME, common.mustCall((err, data) => { - const traces = JSON.parse(data.toString()).traceEvents; - assert(traces.length > 0); - let count = 0; - traces.forEach((trace) => { - if (trace.cat === 'node,node.net,node.net.native' && - trace.name === 'connect') { - count++; - if (trace.ph === 'b') { - assert.ok(!!trace.args.path_type); - assert.ok(!!trace.args.pipe_path); - } + const traces = readTraceEvents(FILE_NAME); + assert(traces.length > 0); + let count = 0; + traces.forEach((trace) => { + if (trace.cat === traceCategory('node.net.native') && + trace.name === 'connect') { + count++; + if (trace.ph === 'b') { + assert.ok(!!trace.args.path_type); + assert.ok(!!trace.args.pipe_path); } - }); - assert.strictEqual(count, 4); - })); + } + }); + assert.strictEqual(count, 4); })); diff --git a/test/parallel/test-trace-events-net.js b/test/trace_events/test-trace-events-net.js similarity index 62% rename from test/parallel/test-trace-events-net.js rename to test/trace_events/test-trace-events-net.js index 98a5167f957c..90d501984aa7 100644 --- a/test/parallel/test-trace-events-net.js +++ b/test/trace_events/test-trace-events-net.js @@ -5,7 +5,14 @@ const cp = require('child_process'); const fs = require('fs'); const tmpdir = require('../common/tmpdir'); -common.skipIfPerfettoEnabled(); +const { + defaultTraceFileName, + readTraceEvents, + checkTraceProcessor, + traceCategory, +} = require('../common/trace_events'); + +checkTraceProcessor(); const CODE = ` const net = require('net'); @@ -20,7 +27,7 @@ const CODE = ` `; tmpdir.refresh(); -const FILE_NAME = tmpdir.resolve('node_trace.1.log'); +const FILE_NAME = tmpdir.resolve(defaultTraceFileName); const proc = cp.spawn(process.execPath, [ '--trace-events-enabled', @@ -30,16 +37,15 @@ const proc = cp.spawn(process.execPath, proc.once('exit', common.mustCall(() => { assert(fs.existsSync(FILE_NAME)); - fs.readFile(FILE_NAME, common.mustCall((err, data) => { - const traces = JSON.parse(data.toString()).traceEvents; - assert(traces.length > 0); - let count = 0; - for (const trace of traces) { - if (trace.cat === 'node,node.net,node.net.native' && trace.name === 'connect') { - count++; - } + const traces = readTraceEvents(FILE_NAME); + assert(traces.length > 0); + let count = 0; + for (const trace of traces) { + if (trace.cat === traceCategory('node.net.native') && + trace.name === 'connect') { + count++; } - // Two begin, two end - assert.strictEqual(count, 4); - })); + } + // Two begin, two end + assert.strictEqual(count, 4); })); diff --git a/test/parallel/test-trace-events-none.js b/test/trace_events/test-trace-events-none.js similarity index 65% rename from test/parallel/test-trace-events-none.js rename to test/trace_events/test-trace-events-none.js index 641787b3b56d..dd2a47e94135 100644 --- a/test/parallel/test-trace-events-none.js +++ b/test/trace_events/test-trace-events-none.js @@ -4,26 +4,30 @@ const assert = require('assert'); const cp = require('child_process'); const fs = require('fs'); -common.skipIfPerfettoEnabled(); +const { + defaultTraceFileName, + readTraceEvents, + checkTraceProcessor, +} = require('../common/trace_events'); + +checkTraceProcessor(); const CODE = 'setTimeout(() => { for (let i = 0; i < 100000; i++) { "test" + i } }, 1)'; const tmpdir = require('../common/tmpdir'); tmpdir.refresh(); -const FILE_NAME = tmpdir.resolve('node_trace.1.log'); +const FILE_NAME = tmpdir.resolve(defaultTraceFileName); const proc_no_categories = cp.spawn( process.execPath, [ '--trace-event-categories', '""', '-e', CODE ], - { cwd: tmpdir.path } + { cwd: tmpdir.path }, ); proc_no_categories.once('exit', common.mustCall(() => { assert(fs.existsSync(FILE_NAME)); // Only __metadata categories should have been emitted. - fs.readFile(FILE_NAME, common.mustCall((err, data) => { - assert.ok(JSON.parse(data.toString()).traceEvents.every( - (trace) => trace.cat === '__metadata')); - })); + assert.ok(readTraceEvents(FILE_NAME).every( + (trace) => trace.cat === '__metadata')); })); diff --git a/test/parallel/test-trace-events-process-exit.js b/test/trace_events/test-trace-events-process-exit.js similarity index 66% rename from test/parallel/test-trace-events-process-exit.js rename to test/trace_events/test-trace-events-process-exit.js index c4066809f3f2..cb09c1e3cdcc 100644 --- a/test/parallel/test-trace-events-process-exit.js +++ b/test/trace_events/test-trace-events-process-exit.js @@ -4,11 +4,17 @@ const assert = require('assert'); const cp = require('child_process'); const fs = require('fs'); -common.skipIfPerfettoEnabled(); +const { + defaultTraceFileName, + readTraceEvents, + checkTraceProcessor, +} = require('../common/trace_events'); + +checkTraceProcessor(); const tmpdir = require('../common/tmpdir'); tmpdir.refresh(); -const FILE_NAME = tmpdir.resolve('node_trace.1.log'); +const FILE_NAME = tmpdir.resolve(defaultTraceFileName); const proc = cp.spawn(process.execPath, [ '--trace-events-enabled', @@ -17,8 +23,5 @@ const proc = cp.spawn(process.execPath, proc.once('exit', common.mustCall(() => { assert(fs.existsSync(FILE_NAME)); - fs.readFile(FILE_NAME, common.mustCall((err, data) => { - const traces = JSON.parse(data.toString()).traceEvents; - assert(traces.length > 0); - })); + assert(readTraceEvents(FILE_NAME).length > 0); })); diff --git a/test/parallel/test-trace-events-promises.js b/test/trace_events/test-trace-events-promises.js similarity index 60% rename from test/parallel/test-trace-events-promises.js rename to test/trace_events/test-trace-events-promises.js index 4626ed9f08a3..d633d55cab3d 100644 --- a/test/parallel/test-trace-events-promises.js +++ b/test/trace_events/test-trace-events-promises.js @@ -5,7 +5,13 @@ const cp = require('child_process'); const fs = require('fs'); const tmpdir = require('../common/tmpdir'); -common.skipIfPerfettoEnabled(); +const { + defaultTraceFileName, + readTraceEvents, + checkTraceProcessor, +} = require('../common/trace_events'); + +checkTraceProcessor(); if (process.argv[2] === 'child') { const p = Promise.reject(1); // Handled later @@ -23,22 +29,20 @@ if (process.argv[2] === 'child') { '--no-warnings', '--trace-event-categories', 'node.promises.rejections', - ] + ], }); proc.once('exit', common.mustCall(() => { - const file = tmpdir.resolve('node_trace.1.log'); + const file = tmpdir.resolve(defaultTraceFileName); assert(fs.existsSync(file)); - fs.readFile(file, common.mustCall((err, data) => { - const traces = JSON.parse(data.toString()).traceEvents - .filter((trace) => trace.cat !== '__metadata'); - traces.forEach((trace) => { - assert.strictEqual(trace.pid, proc.pid); - assert.strictEqual(trace.name, 'rejections'); - assert(trace.args.unhandled <= 2); - assert(trace.args.handledAfter <= 1); - }); - })); + const traces = readTraceEvents(file) + .filter((trace) => trace.cat !== '__metadata'); + traces.forEach((trace) => { + assert.strictEqual(trace.pid, proc.pid); + assert.strictEqual(trace.name, 'rejections'); + assert(trace.args.unhandled <= 2); + assert(trace.args.handledAfter <= 1); + }); })); } diff --git a/test/parallel/test-trace-events-threadpool.js b/test/trace_events/test-trace-events-threadpool.js similarity index 70% rename from test/parallel/test-trace-events-threadpool.js rename to test/trace_events/test-trace-events-threadpool.js index 36d3b306d0e5..f32517e17d7a 100644 --- a/test/parallel/test-trace-events-threadpool.js +++ b/test/trace_events/test-trace-events-threadpool.js @@ -6,7 +6,14 @@ const fs = require('fs'); const tmpdir = require('../common/tmpdir'); const { scheduler } = require('timers/promises'); -common.skipIfPerfettoEnabled(); +const { + defaultTraceFileName, + readTraceEvents, + checkTraceProcessor, + traceCategory, +} = require('../common/trace_events'); + +checkTraceProcessor(); if (!common.hasCrypto) common.skip('missing crypto'); @@ -22,7 +29,7 @@ if (process.env.isChild === '1') { } tmpdir.refresh(); -const FILE_NAME = tmpdir.resolve('node_trace.1.log'); +const FILE_NAME = tmpdir.resolve(defaultTraceFileName); cp.spawnSync(process.execPath, [ @@ -40,8 +47,7 @@ cp.spawnSync(process.execPath, }); assert(fs.existsSync(FILE_NAME)); -const data = fs.readFileSync(FILE_NAME); -const traces = JSON.parse(data.toString()).traceEvents; +const traces = readTraceEvents(FILE_NAME); assert(traces.length > 0); @@ -50,8 +56,8 @@ let cryptoCount = 0; traces.forEach((item) => { if ([ - 'node,node.threadpoolwork,node.threadpoolwork.sync', - 'node,node.threadpoolwork,node.threadpoolwork.async', + traceCategory('node.threadpoolwork.sync'), + traceCategory('node.threadpoolwork.async'), ].includes(item.cat)) { if (item.name === 'zlib') { zlibCount++; @@ -61,6 +67,8 @@ traces.forEach((item) => { } }); -// There are two types, each type has two async events and sync events at least -assert.ok(zlibCount >= 4); -assert.ok(cryptoCount >= 4); +// There are two types, each type has two async events and sync events at +// least. Perfetto records the sync begin/end pair as one complete event. +const expected = common.hasPerfetto ? 3 : 4; +assert.ok(zlibCount >= expected); +assert.ok(cryptoCount >= expected); diff --git a/test/trace_events/test-trace-events-v8.js b/test/trace_events/test-trace-events-v8.js new file mode 100644 index 000000000000..d6c3821407e2 --- /dev/null +++ b/test/trace_events/test-trace-events-v8.js @@ -0,0 +1,64 @@ +'use strict'; +const common = require('../common'); +const assert = require('assert'); +const cp = require('child_process'); +const fs = require('fs'); + +const { + defaultTraceFileName, + readTraceEvents, + checkTraceProcessor, + traceCategory, +} = require('../common/trace_events'); + +checkTraceProcessor(); + +const CODE = + 'setTimeout(() => { for (let i = 0; i < 100000; i++) { "test" + i } }, 1)'; + +const tmpdir = require('../common/tmpdir'); +tmpdir.refresh(); +const FILE_NAME = tmpdir.resolve(defaultTraceFileName); + +const proc = cp.spawn(process.execPath, + [ '--trace-events-enabled', + '--trace-event-categories', 'v8', + '-e', CODE ], + { cwd: tmpdir.path }); + +proc.once('exit', common.mustCall(() => { + assert(fs.existsSync(FILE_NAME)); + const traces = readTraceEvents(FILE_NAME); + 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.startsWith('V8.')) + return false; + return true; + })); + + // C++ async_hooks trace events should not be generated. + assert(!traces.some((trace) => { + if (trace.pid !== proc.pid) + return false; + if (trace.cat !== traceCategory('node.async_hooks')) + return false; + return true; + })); + + + // JavaScript async_hooks trace events should not be generated. + assert(!traces.some((trace) => { + if (trace.pid !== proc.pid) + return false; + if (trace.cat !== traceCategory('node.async_hooks')) + return false; + if (trace.name !== 'Timeout') + return false; + return true; + })); +})); diff --git a/test/parallel/test-trace-events-vm.js b/test/trace_events/test-trace-events-vm.js similarity index 62% rename from test/parallel/test-trace-events-vm.js rename to test/trace_events/test-trace-events-vm.js index d2156245ab5d..c2b9d95e0f04 100644 --- a/test/parallel/test-trace-events-vm.js +++ b/test/trace_events/test-trace-events-vm.js @@ -5,7 +5,13 @@ const cp = require('child_process'); const fs = require('fs'); const tmpdir = require('../common/tmpdir'); -common.skipIfPerfettoEnabled(); +const { + defaultTraceFileName, + readTraceEvents, + checkTraceProcessor, +} = require('../common/trace_events'); + +checkTraceProcessor(); const names = [ 'ContextifyScript::New', @@ -24,20 +30,18 @@ if (process.argv[2] === 'child') { execArgv: [ '--trace-event-categories', 'node.vm.script', - ] + ], }); proc.once('exit', common.mustCall(() => { - const file = tmpdir.resolve('node_trace.1.log'); + const file = tmpdir.resolve(defaultTraceFileName); assert(fs.existsSync(file)); - fs.readFile(file, common.mustCall((err, data) => { - const traces = JSON.parse(data.toString()).traceEvents - .filter((trace) => trace.cat !== '__metadata'); - for (const trace of traces) { - assert.strictEqual(trace.pid, proc.pid); - assert(names.includes(trace.name)); - } - })); + const traces = readTraceEvents(file) + .filter((trace) => trace.cat !== '__metadata'); + for (const trace of traces) { + assert.strictEqual(trace.pid, proc.pid); + assert(names.includes(trace.name)); + } })); } diff --git a/test/trace_events/testcfg.py b/test/trace_events/testcfg.py new file mode 100644 index 000000000000..e62bbff517f7 --- /dev/null +++ b/test/trace_events/testcfg.py @@ -0,0 +1,6 @@ +import sys, os +sys.path.append(os.path.join(os.path.dirname(__file__), '..')) +import testpy + +def GetConfiguration(context, root): + return testpy.ParallelTestConfiguration(context, root, 'trace_events') diff --git a/test/trace_events/trace_events.status b/test/trace_events/trace_events.status new file mode 100644 index 000000000000..03423cb74a03 --- /dev/null +++ b/test/trace_events/trace_events.status @@ -0,0 +1,7 @@ +prefix trace_events + +# To mark a test as flaky, list the test name in the appropriate section +# below, without ".js", followed by ": PASS,FLAKY". Example: +# sample-test : PASS,FLAKY + +[true] # This section applies to all platforms diff --git a/tools/perfetto/get_trace_processor b/tools/perfetto/get_trace_processor new file mode 100755 index 000000000000..55939418c6bd --- /dev/null +++ b/tools/perfetto/get_trace_processor @@ -0,0 +1,39 @@ +#!/bin/sh +# Downloads perfetto's trace_processor_shell, matching the SDK version vendored +# in deps/perfetto. The trace events tests read back the binary traces that +# perfetto builds write through this tool. +set -e + +tools_dir=$(CDPATH= cd -- "$(dirname -- "$0")" && pwd) +version=$(cat "$tools_dir/../../deps/perfetto/VERSION") +trace_processor="$tools_dir/trace_processor_shell" +stamp="$tools_dir/.version" + +if [ -x "$trace_processor" ] && [ "$(cat "$stamp" 2>/dev/null)" = "$version" ]; then + echo "trace_processor_shell v$version is already downloaded" + exit 0 +fi + +# Perfetto names its release archives -, which does not match uname. +case "$(uname -s)" in + Darwin) os=mac ;; + Linux) os=linux ;; + *) echo "No perfetto release for $(uname -s)" >&2; exit 1 ;; +esac + +case "$(uname -m)" in + x86_64 | amd64) arch=amd64 ;; + arm64 | aarch64) arch=arm64 ;; + *) echo "No perfetto release for $(uname -m)" >&2; exit 1 ;; +esac + +url="https://github.com/google/perfetto/releases/download/v$version/$os-$arch.zip" +archive="$tools_dir/$os-$arch.zip" + +rm -f "$trace_processor" "$stamp" +echo "Downloading $url" +curl -sSfL -o "$archive" "$url" +unzip -q -j -o "$archive" '*/trace_processor_shell' -d "$tools_dir" +rm -f "$archive" +chmod +x "$trace_processor" +printf '%s\n' "$version" > "$stamp"