Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

src: per-environment time origin value #43781

Closed
Closed
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
53 changes: 40 additions & 13 deletions 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 };
}

Expand All @@ -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,
};
2 changes: 1 addition & 1 deletion lib/internal/perf/performance.js
Expand Up @@ -31,7 +31,7 @@ const {
filterBufferMapByNameAndType,
} = 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');
Expand Down
32 changes: 9 additions & 23 deletions lib/internal/worker.js
Expand Up @@ -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 {
Expand Down Expand Up @@ -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 = {
Expand Down
5 changes: 3 additions & 2 deletions src/env.cc
Expand Up @@ -352,7 +352,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<uint64_t>(-1)
? AllocateEnvironmentThreadId().id
Expand Down Expand Up @@ -455,7 +456,7 @@ void Environment::InitializeMainContext(Local<Context> context,
should_abort_on_uncaught_toggle_[0] = 1;

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

Expand Down
12 changes: 11 additions & 1 deletion src/env.h
Expand Up @@ -1380,6 +1380,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;
Expand Down Expand Up @@ -1568,7 +1575,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::PerformanceState> performance_state_;

bool has_run_bootstrapping_code_ = false;
Expand Down
4 changes: 2 additions & 2 deletions src/node_http2.cc
Expand Up @@ -640,7 +640,7 @@ void Http2Stream::EmitStatistics() {
std::unique_ptr<Http2StreamPerformanceEntry> entry =
std::make_unique<Http2StreamPerformanceEntry>(
"Http2Stream",
start - (node::performance::timeOrigin / 1e6),
start - (env()->time_origin() / 1e6),
duration,
statistics_);

Expand All @@ -660,7 +660,7 @@ void Http2Session::EmitStatistics() {
std::unique_ptr<Http2SessionPerformanceEntry> entry =
std::make_unique<Http2SessionPerformanceEntry>(
"Http2Session",
start - (node::performance::timeOrigin / 1e6),
start - (env()->time_origin() / 1e6),
duration,
statistics_);

Expand Down
22 changes: 12 additions & 10 deletions src/node_perf.cc
Expand Up @@ -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,
Expand Down Expand Up @@ -160,9 +158,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<GCPerformanceEntry> entry =
std::make_unique<GCPerformanceEntry>(
Expand Down Expand Up @@ -257,12 +256,15 @@ void CreateELDHistogram(const FunctionCallbackInfo<Value>& args) {
}

void GetTimeOrigin(const FunctionCallbackInfo<Value>& 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<Value>& 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 Initialize(Local<Object> target,
Expand Down
2 changes: 0 additions & 2 deletions src/node_perf.h
Expand Up @@ -21,8 +21,6 @@ class ExternalReferenceRegistry;

namespace performance {

extern const uint64_t timeOrigin;

inline const char* GetPerformanceMilestoneName(
PerformanceMilestone milestone) {
switch (milestone) {
Expand Down
3 changes: 1 addition & 2 deletions src/node_worker.cc
Expand Up @@ -816,8 +816,7 @@ void Worker::LoopStartTime(const FunctionCallbackInfo<Value>& 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 {
Expand Down
20 changes: 20 additions & 0 deletions 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);
}));