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); +}));