Skip to content

Commit

Permalink
src: fix negative nodeTiming milestone values
Browse files Browse the repository at this point in the history
PR-URL: #46588
Fixes: #45958
Refs: #43781
Reviewed-By: James M Snell <jasnell@gmail.com>
Reviewed-By: Minwoo Jung <nodecorelab@gmail.com>
  • Loading branch information
legendecas authored and targos committed Mar 14, 2023
1 parent 074692a commit 6740679
Show file tree
Hide file tree
Showing 6 changed files with 73 additions and 12 deletions.
7 changes: 4 additions & 3 deletions src/env.cc
Original file line number Diff line number Diff line change
Expand Up @@ -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<uint64_t>(-1)
? AllocateEnvironmentThreadId().id
Expand Down Expand Up @@ -777,7 +778,7 @@ void Environment::InitializeMainContext(Local<Context> 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);

Expand Down
17 changes: 13 additions & 4 deletions src/env.h
Original file line number Diff line number Diff line change
Expand Up @@ -842,9 +842,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_;
}
Expand Down Expand Up @@ -1044,10 +1046,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::PerformanceState> performance_state_;

bool has_serialized_options_ = false;
Expand Down
5 changes: 4 additions & 1 deletion src/node_perf.cc
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down Expand Up @@ -271,7 +274,7 @@ void CreateELDHistogram(const FunctionCallbackInfo<Value>& args) {
void GetTimeOrigin(const FunctionCallbackInfo<Value>& 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<Value>& args) {
Expand Down
2 changes: 2 additions & 0 deletions src/node_perf_common.h
Original file line number Diff line number Diff line change
Expand Up @@ -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) \
Expand Down
8 changes: 4 additions & 4 deletions test/parallel/test-perf-hooks-worker-timeorigin.js
Original file line number Diff line number Diff line change
Expand Up @@ -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) => {
Expand Down
46 changes: 46 additions & 0 deletions test/parallel/test-performance-nodetiming.js
Original file line number Diff line number Diff line change
@@ -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);
});

0 comments on commit 6740679

Please sign in to comment.