From b318df3dc47196d05ee2b4feb7b8bc50486b2bfb 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 --- src/env.cc | 7 ++-- src/env.h | 7 ++++ src/node_perf.cc | 6 ++- src/node_perf_common.h | 2 + .../test-perf-hooks-worker-timeorigin.js | 8 ++-- test/parallel/test-performance-nodetiming.js | 39 +++++++++++++++++++ 6 files changed, 61 insertions(+), 8 deletions(-) create mode 100644 test/parallel/test-performance-nodetiming.js diff --git a/src/env.cc b/src/env.cc index 692a344703a196..1a3522fa99b90b 100644 --- a/src/env.cc +++ b/src/env.cc @@ -670,8 +670,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 @@ -777,7 +778,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 c2eb764e740400..f65918bc986cb0 100644 --- a/src/env.h +++ b/src/env.h @@ -863,9 +863,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_; } @@ -1071,10 +1073,15 @@ class Environment : public MemoryRetainer { AliasedInt32Array stream_base_state_; + // Web Workers have a different time origin than the main thread. However, + // as PerformanceNodeTiming is exposed in worker_threads, we need to expose + // the per_process time origin of the main thread to the worker threads too. // 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_; + // This is the time when the environment is created. + 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 edc578d1b89ea7..82eb84aa2934ee 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,9 +274,10 @@ 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)); } +// https://w3c.github.io/hr-time/#dfn-get-time-origin-timestamp void GetTimeOriginTimeStamp(const FunctionCallbackInfo& args) { Environment* env = Environment::GetCurrent(args); args.GetReturnValue().Set(Number::New( 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..b51e75e0b81e9d --- /dev/null +++ b/test/parallel/test-performance-nodetiming.js @@ -0,0 +1,39 @@ +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const { performance } = require('perf_hooks'); + +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); +assert.strictEqual(nodeTiming.loopStart, -1); +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); +});