From a8c3d03df0e839178f1046f9123d29c31779f2dd Mon Sep 17 00:00:00 2001 From: legendecas Date: Fri, 10 Feb 2023 01:00:32 +0800 Subject: [PATCH] src: fix negative nodeTiming milestone values PR-URL: https://github.com/nodejs/node/pull/46588 Fixes: https://github.com/nodejs/node/issues/45958 Refs: https://github.com/nodejs/node/pull/43781 Reviewed-By: James M Snell Reviewed-By: Minwoo Jung --- src/env.cc | 7 +-- src/env.h | 17 +++++-- src/node_perf.cc | 5 +- src/node_perf_common.h | 2 + .../test-perf-hooks-worker-timeorigin.js | 8 ++-- test/parallel/test-performance-nodetiming.js | 46 +++++++++++++++++++ 6 files changed, 73 insertions(+), 12 deletions(-) create mode 100644 test/parallel/test-performance-nodetiming.js diff --git a/src/env.cc b/src/env.cc index 8af50e2f1b0181..efeccad346475a 100644 --- a/src/env.cc +++ b/src/env.cc @@ -671,8 +671,9 @@ Environment::Environment(IsolateData* isolate_data, stream_base_state_(isolate_, StreamBase::kNumStreamBaseStateFields, MAYBE_FIELD_PTR(env_info, stream_base_state)), - time_origin_(PERFORMANCE_NOW()), - time_origin_timestamp_(GetCurrentTimeInMicroseconds()), + time_origin_(performance::performance_process_start), + time_origin_timestamp_(performance::performance_process_start_timestamp), + environment_start_(PERFORMANCE_NOW()), flags_(flags), thread_id_(thread_id.id == static_cast(-1) ? AllocateEnvironmentThreadId().id @@ -803,7 +804,7 @@ void Environment::InitializeMainContext(Local context, set_exiting(false); performance_state_->Mark(performance::NODE_PERFORMANCE_MILESTONE_ENVIRONMENT, - time_origin_); + environment_start_); 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 c0e28d6c2ee751..bf16b48fa24b0b 100644 --- a/src/env.h +++ b/src/env.h @@ -846,9 +846,11 @@ class Environment : public MemoryRetainer { inline HandleWrapQueue* handle_wrap_queue() { return &handle_wrap_queue_; } inline ReqWrapQueue* req_wrap_queue() { return &req_wrap_queue_; } + // https://w3c.github.io/hr-time/#dfn-time-origin inline uint64_t time_origin() { return time_origin_; } + // https://w3c.github.io/hr-time/#dfn-get-time-origin-timestamp inline double time_origin_timestamp() { return time_origin_timestamp_; } @@ -1057,10 +1059,17 @@ class Environment : public MemoryRetainer { AliasedInt32Array stream_base_state_; - // 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_; + // As PerformanceNodeTiming is exposed in worker_threads, the per_process + // time origin is exposed in the worker threads. This is an intentional + // diverge from the HTML spec of web workers. + // Process start time from the monotonic clock. This should not be used as an + // absolute time, but only as a time relative to another monotonic clock time. + const uint64_t time_origin_; + // Process start timestamp from the wall clock. This is an absolute time + // exposed as `performance.timeOrigin`. + const double time_origin_timestamp_; + // This is the time when the environment is created. + const uint64_t environment_start_; std::unique_ptr performance_state_; bool has_serialized_options_ = false; diff --git a/src/node_perf.cc b/src/node_perf.cc index 8e8173e16ca7fa..1a97f25b6ca484 100644 --- a/src/node_perf.cc +++ b/src/node_perf.cc @@ -38,6 +38,9 @@ using v8::Value; // Nanoseconds in a millisecond, as a float. #define NANOS_PER_MILLIS 1e6 +const uint64_t performance_process_start = PERFORMANCE_NOW(); +const double performance_process_start_timestamp = + GetCurrentTimeInMicroseconds(); uint64_t performance_v8_start; PerformanceState::PerformanceState(Isolate* isolate, @@ -271,7 +274,7 @@ void CreateELDHistogram(const FunctionCallbackInfo& args) { void GetTimeOrigin(const FunctionCallbackInfo& args) { Environment* env = Environment::GetCurrent(args); args.GetReturnValue().Set( - Number::New(args.GetIsolate(), env->time_origin() / 1e6)); + Number::New(args.GetIsolate(), env->time_origin() / NANOS_PER_MILLIS)); } void GetTimeOriginTimeStamp(const FunctionCallbackInfo& args) { diff --git a/src/node_perf_common.h b/src/node_perf_common.h index f457d73c579c01..d519222616a174 100644 --- a/src/node_perf_common.h +++ b/src/node_perf_common.h @@ -20,6 +20,8 @@ namespace performance { // These occur before the environment is created. Cache them // here and add them to the milestones when the env is init'd. +extern const uint64_t performance_process_start; +extern const double performance_process_start_timestamp; extern uint64_t performance_v8_start; #define NODE_PERFORMANCE_MILESTONES(V) \ diff --git a/test/parallel/test-perf-hooks-worker-timeorigin.js b/test/parallel/test-perf-hooks-worker-timeorigin.js index b87beb76bb3e19..a7cf35db904fd9 100644 --- a/test/parallel/test-perf-hooks-worker-timeorigin.js +++ b/test/parallel/test-perf-hooks-worker-timeorigin.js @@ -9,10 +9,10 @@ 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); + // PerformanceNodeTiming exposes process milestones so the + // `performance.timeOrigin` in the `worker_threads.Worker` must be the start + // time of the process. + assert.strictEqual(timeOrigin, performance.timeOrigin); })); w.on('exit', common.mustCall((code) => { diff --git a/test/parallel/test-performance-nodetiming.js b/test/parallel/test-performance-nodetiming.js new file mode 100644 index 00000000000000..cc76c80a647a91 --- /dev/null +++ b/test/parallel/test-performance-nodetiming.js @@ -0,0 +1,46 @@ +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const { performance } = require('perf_hooks'); +const { isMainThread } = require('worker_threads'); + +const { nodeTiming } = performance; +assert.strictEqual(nodeTiming.name, 'node'); +assert.strictEqual(nodeTiming.entryType, 'node'); + +assert.strictEqual(nodeTiming.startTime, 0); +const now = performance.now(); +assert.ok(nodeTiming.duration >= now); + +// Check that the nodeTiming milestone values are in the correct order and greater than 0. +const keys = ['nodeStart', 'v8Start', 'environment', 'bootstrapComplete']; +for (let idx = 0; idx < keys.length; idx++) { + if (idx === 0) { + assert.ok(nodeTiming[keys[idx]] >= 0); + continue; + } + assert.ok(nodeTiming[keys[idx]] > nodeTiming[keys[idx - 1]], `expect nodeTiming['${keys[idx]}'] > nodeTiming['${keys[idx - 1]}']`); +} + +// loop milestones. +assert.strictEqual(nodeTiming.idleTime, 0); +if (isMainThread) { + // Main thread does not start loop until the first tick is finished. + assert.strictEqual(nodeTiming.loopStart, -1); +} else { + // Worker threads run the user script after loop is started. + assert.ok(nodeTiming.loopStart >= nodeTiming.bootstrapComplete); +} +assert.strictEqual(nodeTiming.loopExit, -1); + +setTimeout(common.mustCall(() => { + assert.ok(nodeTiming.idleTime >= 0); + assert.ok(nodeTiming.idleTime + nodeTiming.loopExit <= nodeTiming.duration); + assert.ok(nodeTiming.loopStart >= nodeTiming.bootstrapComplete); +}, 1), 1); + +// Can not be wrapped in common.mustCall(). +process.on('exit', () => { + assert.ok(nodeTiming.loopExit > 0); +});