From 997da3d1342d91721f81ecf9eae1b7f6bbfabae2 Mon Sep 17 00:00:00 2001 From: legendecas Date: Tue, 12 Jul 2022 00:26:17 +0800 Subject: [PATCH 1/3] src: per-environment time origin value According to https://html.spec.whatwg.org/#environment-settings-object, the timeOrigin is a per-environment value. Worker's timeOrigin is the time when the worker is created. PR-URL: https://github.com/nodejs/node/pull/43781 Reviewed-By: Matteo Collina Reviewed-By: Anna Henningsen Reviewed-By: Paolo Insogna Reviewed-By: Joyee Cheung --- lib/internal/perf/event_loop_utilization.js | 53 ++++++++++++++----- lib/internal/perf/performance.js | 2 +- lib/internal/worker.js | 32 ++++------- src/env.cc | 5 +- src/env.h | 12 ++++- src/node_http2.cc | 4 +- src/node_perf.cc | 22 ++++---- src/node_perf.h | 2 - src/node_worker.cc | 3 +- .../test-perf-hooks-worker-timeorigin.js | 20 +++++++ 10 files changed, 99 insertions(+), 56 deletions(-) create mode 100644 test/parallel/test-perf-hooks-worker-timeorigin.js diff --git a/lib/internal/perf/event_loop_utilization.js b/lib/internal/perf/event_loop_utilization.js index d73b2f5a831ab9..583bb72745fe88 100644 --- a/lib/internal/perf/event_loop_utilization.js +++ b/lib/internal/perf/event_loop_utilization.js @@ -1,13 +1,26 @@ 'use strict'; -const nodeTiming = require('internal/perf/nodetiming'); - -const { now } = require('internal/perf/utils'); +const { + constants: { + NODE_PERFORMANCE_MILESTONE_LOOP_START, + }, + loopIdleTime, + milestones, +} = internalBinding('performance'); function eventLoopUtilization(util1, util2) { - const ls = nodeTiming.loopStart; + // Get the original milestone timestamps that calculated from the beginning + // of the process. + return internalEventLoopUtilization( + milestones[NODE_PERFORMANCE_MILESTONE_LOOP_START] / 1e6, + loopIdleTime(), + util1, + util2 + ); +} - if (ls <= 0) { +function internalEventLoopUtilization(loopStart, loopIdleTime, util1, util2) { + if (loopStart <= 0) { return { idle: 0, active: 0, utilization: 0 }; } @@ -17,17 +30,31 @@ function eventLoopUtilization(util1, util2) { return { idle, active, utilization: active / (idle + active) }; } - const idle = nodeTiming.idleTime; - const active = now() - ls - idle; + // Using process.hrtime() to get the time from the beginning of the process, + // and offset it by the loopStart time (which is also calculated from the + // beginning of the process). + const now = process.hrtime(); + const active = now[0] * 1e3 + now[1] / 1e6 - loopStart - loopIdleTime; if (!util1) { - return { idle, active, utilization: active / (idle + active) }; + return { + idle: loopIdleTime, + active, + utilization: active / (loopIdleTime + active), + }; } - const idle_delta = idle - util1.idle; - const active_delta = active - util1.active; - const utilization = active_delta / (idle_delta + active_delta); - return { idle: idle_delta, active: active_delta, utilization }; + const idleDelta = loopIdleTime - util1.idle; + const activeDelta = active - util1.active; + const utilization = activeDelta / (idleDelta + activeDelta); + return { + idle: idleDelta, + active: activeDelta, + utilization, + }; } -module.exports = eventLoopUtilization; +module.exports = { + internalEventLoopUtilization, + eventLoopUtilization, +}; diff --git a/lib/internal/perf/performance.js b/lib/internal/perf/performance.js index 54021b01440c98..610523853f86f5 100644 --- a/lib/internal/perf/performance.js +++ b/lib/internal/perf/performance.js @@ -35,7 +35,7 @@ const { setDispatchBufferFull, } = require('internal/perf/observe'); -const eventLoopUtilization = require('internal/perf/event_loop_utilization'); +const { eventLoopUtilization } = require('internal/perf/event_loop_utilization'); const nodeTiming = require('internal/perf/nodetiming'); const timerify = require('internal/perf/timerify'); const { customInspectSymbol: kInspect } = require('internal/util'); diff --git a/lib/internal/worker.js b/lib/internal/worker.js index 8e396195209b83..a13644589d6b3b 100644 --- a/lib/internal/worker.js +++ b/lib/internal/worker.js @@ -27,7 +27,9 @@ const { const EventEmitter = require('events'); const assert = require('internal/assert'); const path = require('path'); -const { now } = require('internal/perf/utils'); +const { + internalEventLoopUtilization +} = require('internal/perf/event_loop_utilization'); const errorCodes = require('internal/errors').codes; const { @@ -472,28 +474,12 @@ function eventLoopUtilization(util1, util2) { return { idle: 0, active: 0, utilization: 0 }; } - if (util2) { - const idle = util1.idle - util2.idle; - const active = util1.active - util2.active; - return { idle, active, utilization: active / (idle + active) }; - } - - const idle = this[kHandle].loopIdleTime(); - - // Using performance.now() here is fine since it's always the time from - // the beginning of the process, and is why it needs to be offset by the - // loopStart time (which is also calculated from the beginning of the - // process). - const active = now() - this[kLoopStartTime] - idle; - - if (!util1) { - return { idle, active, utilization: active / (idle + active) }; - } - - const idle_delta = idle - util1.idle; - const active_delta = active - util1.active; - const utilization = active_delta / (idle_delta + active_delta); - return { idle: idle_delta, active: active_delta, utilization }; + return internalEventLoopUtilization( + this[kLoopStartTime], + this[kHandle].loopIdleTime(), + util1, + util2 + ); } module.exports = { diff --git a/src/env.cc b/src/env.cc index 9888b1bb866524..d7bf0bd43bd391 100644 --- a/src/env.cc +++ b/src/env.cc @@ -662,7 +662,8 @@ Environment::Environment(IsolateData* isolate_data, stream_base_state_(isolate_, StreamBase::kNumStreamBaseStateFields, MAYBE_FIELD_PTR(env_info, stream_base_state)), - environment_start_time_(PERFORMANCE_NOW()), + time_origin_(PERFORMANCE_NOW()), + time_origin_timestamp_(GetCurrentTimeInMicroseconds()), flags_(flags), thread_id_(thread_id.id == static_cast(-1) ? AllocateEnvironmentThreadId().id @@ -767,7 +768,7 @@ void Environment::InitializeMainContext(Local context, set_exiting(false); performance_state_->Mark(performance::NODE_PERFORMANCE_MILESTONE_ENVIRONMENT, - environment_start_time_); + time_origin_); performance_state_->Mark(performance::NODE_PERFORMANCE_MILESTONE_NODE_START, per_process::node_start_time); diff --git a/src/env.h b/src/env.h index 4d5e72f9f44762..a65b37d2e13397 100644 --- a/src/env.h +++ b/src/env.h @@ -855,6 +855,13 @@ class Environment : public MemoryRetainer { inline HandleWrapQueue* handle_wrap_queue() { return &handle_wrap_queue_; } inline ReqWrapQueue* req_wrap_queue() { return &req_wrap_queue_; } + inline uint64_t time_origin() { + return time_origin_; + } + inline double time_origin_timestamp() { + return time_origin_timestamp_; + } + inline bool EmitProcessEnvWarning() { bool current_value = emit_env_nonstring_warning_; emit_env_nonstring_warning_ = false; @@ -1045,7 +1052,10 @@ class Environment : public MemoryRetainer { AliasedInt32Array stream_base_state_; - uint64_t environment_start_time_; + // https://w3c.github.io/hr-time/#dfn-time-origin + uint64_t time_origin_; + // https://w3c.github.io/hr-time/#dfn-get-time-origin-timestamp + double time_origin_timestamp_; std::unique_ptr performance_state_; bool has_serialized_options_ = false; diff --git a/src/node_http2.cc b/src/node_http2.cc index d88e25da6c6776..36cbb1c3f534e4 100644 --- a/src/node_http2.cc +++ b/src/node_http2.cc @@ -644,7 +644,7 @@ void Http2Stream::EmitStatistics() { std::unique_ptr entry = std::make_unique( "Http2Stream", - start - (node::performance::timeOrigin / 1e6), + start - (env()->time_origin() / 1e6), duration, statistics_); @@ -664,7 +664,7 @@ void Http2Session::EmitStatistics() { std::unique_ptr entry = std::make_unique( "Http2Session", - start - (node::performance::timeOrigin / 1e6), + start - (env()->time_origin() / 1e6), duration, statistics_); diff --git a/src/node_perf.cc b/src/node_perf.cc index 4cf13a6c24b442..e8e5a5a9f7a24a 100644 --- a/src/node_perf.cc +++ b/src/node_perf.cc @@ -35,11 +35,9 @@ using v8::Value; // Microseconds in a millisecond, as a float. #define MICROS_PER_MILLIS 1e3 +// Nanoseconds in a millisecond, as a float. +#define NANOS_PER_MILLIS 1e6 -// https://w3c.github.io/hr-time/#dfn-time-origin -const uint64_t timeOrigin = PERFORMANCE_NOW(); -// https://w3c.github.io/hr-time/#dfn-time-origin-timestamp -const double timeOriginTimestamp = GetCurrentTimeInMicroseconds(); uint64_t performance_v8_start; PerformanceState::PerformanceState(Isolate* isolate, @@ -170,9 +168,10 @@ void MarkGarbageCollectionEnd( return; double start_time = - (state->performance_last_gc_start_mark - timeOrigin) / 1e6; - double duration = - (PERFORMANCE_NOW() / 1e6) - (state->performance_last_gc_start_mark / 1e6); + (state->performance_last_gc_start_mark - env->time_origin()) / + NANOS_PER_MILLIS; + double duration = (PERFORMANCE_NOW() / NANOS_PER_MILLIS) - + (state->performance_last_gc_start_mark / NANOS_PER_MILLIS); std::unique_ptr entry = std::make_unique( @@ -270,12 +269,15 @@ void CreateELDHistogram(const FunctionCallbackInfo& args) { } void GetTimeOrigin(const FunctionCallbackInfo& args) { - args.GetReturnValue().Set(Number::New(args.GetIsolate(), timeOrigin / 1e6)); + Environment* env = Environment::GetCurrent(args); + args.GetReturnValue().Set( + Number::New(args.GetIsolate(), env->time_origin() / 1e6)); } void GetTimeOriginTimeStamp(const FunctionCallbackInfo& args) { - args.GetReturnValue().Set( - Number::New(args.GetIsolate(), timeOriginTimestamp / MICROS_PER_MILLIS)); + Environment* env = Environment::GetCurrent(args); + args.GetReturnValue().Set(Number::New( + args.GetIsolate(), env->time_origin_timestamp() / MICROS_PER_MILLIS)); } void MarkBootstrapComplete(const FunctionCallbackInfo& args) { diff --git a/src/node_perf.h b/src/node_perf.h index b1a991713866ab..3e994ce5a63b7d 100644 --- a/src/node_perf.h +++ b/src/node_perf.h @@ -21,8 +21,6 @@ class ExternalReferenceRegistry; namespace performance { -extern const uint64_t timeOrigin; - inline const char* GetPerformanceMilestoneName( PerformanceMilestone milestone) { switch (milestone) { diff --git a/src/node_worker.cc b/src/node_worker.cc index 4a675fdfe7732b..0aa191aad23943 100644 --- a/src/node_worker.cc +++ b/src/node_worker.cc @@ -845,8 +845,7 @@ void Worker::LoopStartTime(const FunctionCallbackInfo& args) { double loop_start_time = w->env_->performance_state()->milestones[ node::performance::NODE_PERFORMANCE_MILESTONE_LOOP_START]; CHECK_GE(loop_start_time, 0); - args.GetReturnValue().Set( - (loop_start_time - node::performance::timeOrigin) / 1e6); + args.GetReturnValue().Set(loop_start_time / 1e6); } namespace { diff --git a/test/parallel/test-perf-hooks-worker-timeorigin.js b/test/parallel/test-perf-hooks-worker-timeorigin.js new file mode 100644 index 00000000000000..b87beb76bb3e19 --- /dev/null +++ b/test/parallel/test-perf-hooks-worker-timeorigin.js @@ -0,0 +1,20 @@ +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const { Worker } = require('worker_threads'); + +const w = new Worker(` +require('worker_threads').parentPort.postMessage(performance.timeOrigin); +`, { eval: true }); + +w.on('message', common.mustCall((timeOrigin) => { + // Worker is created after this main context, it's + // `performance.timeOrigin` must be greater than this + // main context's. + assert.ok(timeOrigin > performance.timeOrigin); +})); + +w.on('exit', common.mustCall((code) => { + assert.strictEqual(code, 0); +})); From 299e6b44cc496913dd81a4d26638d605085ab9fc Mon Sep 17 00:00:00 2001 From: Chengzhong Wu Date: Wed, 31 Aug 2022 22:41:42 +0800 Subject: [PATCH 2/3] src: introduce node::Realm To distinguish per-context values from the node::Environment, split those values to a new node::Realm structure and consolidate bootstrapping methods with it. PR-URL: https://github.com/nodejs/node/pull/44179 Refs: https://github.com/nodejs/node/issues/42528 Reviewed-By: Joyee Cheung Reviewed-By: James M Snell --- test/pummel/test-heapdump-env.js | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/test/pummel/test-heapdump-env.js b/test/pummel/test-heapdump-env.js index 2e9f75cbfff3ba..703ad8f690ce95 100644 --- a/test/pummel/test-heapdump-env.js +++ b/test/pummel/test-heapdump-env.js @@ -38,4 +38,10 @@ validateSnapshotNodes('Node / Realm', [{ ] }]); +validateSnapshotNodes('Node / Realm', [{ + children: [ + { node_name: 'process', edge_name: 'process_object' }, + ] +}]); + console.log(context); // Make sure it's not GC'ed From 024450a320af0c1fa170e0fd16160d554a4355a4 Mon Sep 17 00:00:00 2001 From: MURAKAMI Masahiko Date: Mon, 7 Nov 2022 21:02:56 +0900 Subject: [PATCH 3/3] test_runner: avoid swallowing of asynchronously thrown errors Fixes: https://github.com/nodejs/node/issues/44612 PR-URL: https://github.com/nodejs/node/pull/45264 Reviewed-By: Moshe Atlow Reviewed-By: Benjamin Gruenbaum --- doc/api/test.md | 4 +-- lib/internal/test_runner/harness.js | 1 + test/es-module/test-esm-repl-imports.js | 2 +- .../extraneous_set_immediate_async.mjs | 5 +++ .../extraneous_set_timeout_async.mjs | 5 +++ .../test-runner-extraneous-async-activity.js | 31 +++++++++++++++++++ 6 files changed, 45 insertions(+), 3 deletions(-) create mode 100644 test/fixtures/test-runner/extraneous_set_immediate_async.mjs create mode 100644 test/fixtures/test-runner/extraneous_set_timeout_async.mjs create mode 100644 test/parallel/test-runner-extraneous-async-activity.js diff --git a/doc/api/test.md b/doc/api/test.md index 5fd6191d1d5778..632cf912782e94 100644 --- a/doc/api/test.md +++ b/doc/api/test.md @@ -272,8 +272,8 @@ top level of the file's TAP output. The second `setImmediate()` creates an `uncaughtException` event. `uncaughtException` and `unhandledRejection` events originating from a completed -test are handled by the `test` module and reported as diagnostic warnings in -the top level of the file's TAP output. +test are marked as failed by the `test` module and reported as diagnostic +warnings in the top level of the file's TAP output. ```js test('a test that creates asynchronous activity', (t) => { diff --git a/lib/internal/test_runner/harness.js b/lib/internal/test_runner/harness.js index 62d26a1a1bd8bf..e6af310f9ea623 100644 --- a/lib/internal/test_runner/harness.js +++ b/lib/internal/test_runner/harness.js @@ -44,6 +44,7 @@ function createProcessEventHandler(eventName, rootTest) { `triggered an ${eventName} event.`; rootTest.diagnostic(msg); + process.exitCode = 1; return; } diff --git a/test/es-module/test-esm-repl-imports.js b/test/es-module/test-esm-repl-imports.js index 9547824756f5ec..a6224a54cee504 100644 --- a/test/es-module/test-esm-repl-imports.js +++ b/test/es-module/test-esm-repl-imports.js @@ -9,7 +9,7 @@ const { describe, it } = require('node:test'); describe('ESM: REPL runs', { concurrency: true }, () => { - it((context, done) => { + it((done) => { const child = spawn(execPath, [ '--interactive', ], { diff --git a/test/fixtures/test-runner/extraneous_set_immediate_async.mjs b/test/fixtures/test-runner/extraneous_set_immediate_async.mjs new file mode 100644 index 00000000000000..cf001fb42bedc0 --- /dev/null +++ b/test/fixtures/test-runner/extraneous_set_immediate_async.mjs @@ -0,0 +1,5 @@ +import test from 'node:test'; + +test('extraneous async activity test', () => { + setImmediate(() => { throw new Error(); }); +}); diff --git a/test/fixtures/test-runner/extraneous_set_timeout_async.mjs b/test/fixtures/test-runner/extraneous_set_timeout_async.mjs new file mode 100644 index 00000000000000..be4aaa80edc2e4 --- /dev/null +++ b/test/fixtures/test-runner/extraneous_set_timeout_async.mjs @@ -0,0 +1,5 @@ +import test from 'node:test'; + +test('extraneous async activity test', () => { + setTimeout(() => { throw new Error(); }, 100); +}); diff --git a/test/parallel/test-runner-extraneous-async-activity.js b/test/parallel/test-runner-extraneous-async-activity.js new file mode 100644 index 00000000000000..d0fbf5fd2b487c --- /dev/null +++ b/test/parallel/test-runner-extraneous-async-activity.js @@ -0,0 +1,31 @@ +'use strict'; +require('../common'); +const fixtures = require('../common/fixtures'); +const assert = require('assert'); +const { spawnSync } = require('child_process'); + +{ + const child = spawnSync(process.execPath, [ + '--test', + fixtures.path('test-runner', 'extraneous_set_immediate_async.mjs'), + ]); + const stdout = child.stdout.toString(); + assert.match(stdout, /^# pass 0$/m); + assert.match(stdout, /^# fail 1$/m); + assert.match(stdout, /^# cancelled 0$/m); + assert.strictEqual(child.status, 1); + assert.strictEqual(child.signal, null); +} + +{ + const child = spawnSync(process.execPath, [ + '--test', + fixtures.path('test-runner', 'extraneous_set_timeout_async.mjs'), + ]); + const stdout = child.stdout.toString(); + assert.match(stdout, /^# pass 0$/m); + assert.match(stdout, /^# fail 1$/m); + assert.match(stdout, /^# cancelled 0$/m); + assert.strictEqual(child.status, 1); + assert.strictEqual(child.signal, null); +}