From dabda03ea9ef4baab20e3a377a753174475eb468 Mon Sep 17 00:00:00 2001 From: legendecas Date: Tue, 12 Jul 2022 00:26:17 +0800 Subject: [PATCH] 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 26a80f51cf66c4..7bf4d9f12acb4b 100644 --- a/lib/internal/perf/performance.js +++ b/lib/internal/perf/performance.js @@ -31,7 +31,7 @@ const { filterBufferMapByNameAndType, } = 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 b4f22a4ee43e22..e4a708ec1de645 100644 --- a/src/env.cc +++ b/src/env.cc @@ -743,7 +743,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 @@ -843,7 +844,7 @@ void Environment::InitializeMainContext(Local context, should_abort_on_uncaught_toggle_[0] = 1; 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 86d88e67274c2c..04528583cb47f4 100644 --- a/src/env.h +++ b/src/env.h @@ -1363,6 +1363,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; @@ -1550,7 +1557,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_run_bootstrapping_code_ = false; diff --git a/src/node_http2.cc b/src/node_http2.cc index 4c180c539a7d5e..f5723821f3f48c 100644 --- a/src/node_http2.cc +++ b/src/node_http2.cc @@ -640,7 +640,7 @@ void Http2Stream::EmitStatistics() { std::unique_ptr entry = std::make_unique( "Http2Stream", - start - (node::performance::timeOrigin / 1e6), + start - (env()->time_origin() / 1e6), duration, statistics_); @@ -660,7 +660,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 253f72157e8a7b..2511a71ba2c08c 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, @@ -160,9 +158,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( @@ -257,12 +256,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 Initialize(Local target, 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 8385bc96231257..c70ccd6bd43edd 100644 --- a/src/node_worker.cc +++ b/src/node_worker.cc @@ -816,8 +816,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); +}));