Skip to content

Commit 6760c9a

Browse files
committed
src: fix negative nodeTiming milestone values
1 parent 1b87cb6 commit 6760c9a

File tree

6 files changed

+66
-12
lines changed

6 files changed

+66
-12
lines changed

src/env.cc

Lines changed: 4 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -670,8 +670,9 @@ Environment::Environment(IsolateData* isolate_data,
670670
stream_base_state_(isolate_,
671671
StreamBase::kNumStreamBaseStateFields,
672672
MAYBE_FIELD_PTR(env_info, stream_base_state)),
673-
time_origin_(PERFORMANCE_NOW()),
674-
time_origin_timestamp_(GetCurrentTimeInMicroseconds()),
673+
time_origin_(performance::performance_process_start),
674+
time_origin_timestamp_(performance::performance_process_start_timestamp),
675+
environment_start_(PERFORMANCE_NOW()),
675676
flags_(flags),
676677
thread_id_(thread_id.id == static_cast<uint64_t>(-1)
677678
? AllocateEnvironmentThreadId().id
@@ -777,7 +778,7 @@ void Environment::InitializeMainContext(Local<Context> context,
777778
set_exiting(false);
778779

779780
performance_state_->Mark(performance::NODE_PERFORMANCE_MILESTONE_ENVIRONMENT,
780-
time_origin_);
781+
environment_start_);
781782
performance_state_->Mark(performance::NODE_PERFORMANCE_MILESTONE_NODE_START,
782783
per_process::node_start_time);
783784

src/env.h

Lines changed: 13 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -863,9 +863,11 @@ class Environment : public MemoryRetainer {
863863
inline HandleWrapQueue* handle_wrap_queue() { return &handle_wrap_queue_; }
864864
inline ReqWrapQueue* req_wrap_queue() { return &req_wrap_queue_; }
865865

866+
// https://w3c.github.io/hr-time/#dfn-time-origin
866867
inline uint64_t time_origin() {
867868
return time_origin_;
868869
}
870+
// https://w3c.github.io/hr-time/#dfn-get-time-origin-timestamp
869871
inline double time_origin_timestamp() {
870872
return time_origin_timestamp_;
871873
}
@@ -1071,10 +1073,17 @@ class Environment : public MemoryRetainer {
10711073

10721074
AliasedInt32Array stream_base_state_;
10731075

1074-
// https://w3c.github.io/hr-time/#dfn-time-origin
1075-
uint64_t time_origin_;
1076-
// https://w3c.github.io/hr-time/#dfn-get-time-origin-timestamp
1077-
double time_origin_timestamp_;
1076+
// As PerformanceNodeTiming is exposed in worker_threads, the per_process
1077+
// time origin is exposed in the worker threads. This is an intentional
1078+
// diverge from the HTML spec of web workers.
1079+
// Process start time from the monotonic clock. This should not be used as an
1080+
// absolute time, but only as a time relative to another monotonic clock time.
1081+
const uint64_t time_origin_;
1082+
// Process start timestamp from the wall clock. This is an absolute time
1083+
// exposed as `performance.timeOrigin`.
1084+
const double time_origin_timestamp_;
1085+
// This is the time when the environment is created.
1086+
const uint64_t environment_start_;
10781087
std::unique_ptr<performance::PerformanceState> performance_state_;
10791088

10801089
bool has_serialized_options_ = false;

src/node_perf.cc

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -38,6 +38,9 @@ using v8::Value;
3838
// Nanoseconds in a millisecond, as a float.
3939
#define NANOS_PER_MILLIS 1e6
4040

41+
const uint64_t performance_process_start = PERFORMANCE_NOW();
42+
const double performance_process_start_timestamp =
43+
GetCurrentTimeInMicroseconds();
4144
uint64_t performance_v8_start;
4245

4346
PerformanceState::PerformanceState(Isolate* isolate,
@@ -271,7 +274,7 @@ void CreateELDHistogram(const FunctionCallbackInfo<Value>& args) {
271274
void GetTimeOrigin(const FunctionCallbackInfo<Value>& args) {
272275
Environment* env = Environment::GetCurrent(args);
273276
args.GetReturnValue().Set(
274-
Number::New(args.GetIsolate(), env->time_origin() / 1e6));
277+
Number::New(args.GetIsolate(), env->time_origin() / NANOS_PER_MILLIS));
275278
}
276279

277280
void GetTimeOriginTimeStamp(const FunctionCallbackInfo<Value>& args) {

src/node_perf_common.h

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -20,6 +20,8 @@ namespace performance {
2020

2121
// These occur before the environment is created. Cache them
2222
// here and add them to the milestones when the env is init'd.
23+
extern const uint64_t performance_process_start;
24+
extern const double performance_process_start_timestamp;
2325
extern uint64_t performance_v8_start;
2426

2527
#define NODE_PERFORMANCE_MILESTONES(V) \

test/parallel/test-perf-hooks-worker-timeorigin.js

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -9,10 +9,10 @@ require('worker_threads').parentPort.postMessage(performance.timeOrigin);
99
`, { eval: true });
1010

1111
w.on('message', common.mustCall((timeOrigin) => {
12-
// Worker is created after this main context, it's
13-
// `performance.timeOrigin` must be greater than this
14-
// main context's.
15-
assert.ok(timeOrigin > performance.timeOrigin);
12+
// PerformanceNodeTiming exposes process milestones so the
13+
// `performance.timeOrigin` in the `worker_threads.Worker` must be the start
14+
// time of the process.
15+
assert.strictEqual(timeOrigin, performance.timeOrigin);
1616
}));
1717

1818
w.on('exit', common.mustCall((code) => {
Lines changed: 39 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,39 @@
1+
'use strict';
2+
3+
const common = require('../common');
4+
const assert = require('assert');
5+
const { performance } = require('perf_hooks');
6+
7+
const { nodeTiming } = performance;
8+
assert.strictEqual(nodeTiming.name, 'node');
9+
assert.strictEqual(nodeTiming.entryType, 'node');
10+
11+
assert.strictEqual(nodeTiming.startTime, 0);
12+
const now = performance.now();
13+
assert.ok(nodeTiming.duration >= now);
14+
15+
// Check that the nodeTiming milestone values are in the correct order and greater than 0.
16+
const keys = ['nodeStart', 'v8Start', 'environment', 'bootstrapComplete'];
17+
for (let idx = 0; idx < keys.length; idx++) {
18+
if (idx === 0) {
19+
assert.ok(nodeTiming[keys[idx]] >= 0);
20+
continue;
21+
}
22+
assert.ok(nodeTiming[keys[idx]] > nodeTiming[keys[idx - 1]], `expect nodeTiming['${keys[idx]}'] > nodeTiming['${keys[idx - 1]}']`);
23+
}
24+
25+
// loop milestones.
26+
assert.strictEqual(nodeTiming.idleTime, 0);
27+
assert.strictEqual(nodeTiming.loopStart, -1);
28+
assert.strictEqual(nodeTiming.loopExit, -1);
29+
30+
setTimeout(common.mustCall(() => {
31+
assert.ok(nodeTiming.idleTime >= 0);
32+
assert.ok(nodeTiming.idleTime + nodeTiming.loopExit <= nodeTiming.duration);
33+
assert.ok(nodeTiming.loopStart >= nodeTiming.bootstrapComplete);
34+
}, 1), 1);
35+
36+
// Can not be wrapped in common.mustCall().
37+
process.on('exit', () => {
38+
assert.ok(nodeTiming.loopExit > 0);
39+
});

0 commit comments

Comments
 (0)