Skip to content

Commit

Permalink
perf_hooks: fix timing
Browse files Browse the repository at this point in the history
Fixes: #17892
Fixes: #17893
Fixes: #18992

PR-URL: #18993
Reviewed-By: James M Snell <jasnell@gmail.com>
Reviewed-By: Anna Henningsen <anna@addaleax.net>
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
Reviewed-By: Anatoli Papirovski <apapirovski@mac.com>
TimothyGu authored and jasnell committed Mar 6, 2018

Verified

This commit was signed with the committer’s verified signature.
arithefirst April Hall
1 parent ad72142 commit 9256dbb
Showing 6 changed files with 182 additions and 52 deletions.
31 changes: 20 additions & 11 deletions doc/api/perf_hooks.md
Original file line number Diff line number Diff line change
@@ -181,7 +181,8 @@ added: v8.5.0

* Returns: {number}

Returns the current high resolution millisecond timestamp.
Returns the current high resolution millisecond timestamp, where 0 represents
the start of the current `node` process.

### performance.timeOrigin
<!-- YAML
@@ -190,8 +191,8 @@ added: v8.5.0

* {number}

The [`timeOrigin`][] specifies the high resolution millisecond timestamp from
which all performance metric durations are measured.
The [`timeOrigin`][] specifies the high resolution millisecond timestamp at
which the current `node` process began, measured in Unix time.

### performance.timerify(fn)
<!-- YAML
@@ -302,7 +303,8 @@ added: v8.5.0
* {number}

The high resolution millisecond timestamp at which the Node.js process
completed bootstrap.
completed bootstrapping. If bootstrapping has not yet finished, the property
has the value of -1.

### performanceNodeTiming.clusterSetupEnd
<!-- YAML
@@ -311,7 +313,8 @@ added: v8.5.0

* {number}

The high resolution millisecond timestamp at which cluster processing ended.
The high resolution millisecond timestamp at which cluster processing ended. If
cluster processing has not yet ended, the property has the value of -1.

### performanceNodeTiming.clusterSetupStart
<!-- YAML
@@ -321,6 +324,7 @@ added: v8.5.0
* {number}

The high resolution millisecond timestamp at which cluster processing started.
If cluster processing has not yet started, the property has the value of -1.

### performanceNodeTiming.loopExit
<!-- YAML
@@ -330,7 +334,8 @@ added: v8.5.0
* {number}

The high resolution millisecond timestamp at which the Node.js event loop
exited.
exited. If the event loop has not yet exited, the property has the value of -1.
It can only have a value of not -1 in a handler of the [`'exit'`][] event.

### performanceNodeTiming.loopStart
<!-- YAML
@@ -340,7 +345,8 @@ added: v8.5.0
* {number}

The high resolution millisecond timestamp at which the Node.js event loop
started.
started. If the event loop has not yet started (e.g., in the first tick of the
main script), the property has the value of -1.

### performanceNodeTiming.moduleLoadEnd
<!-- YAML
@@ -395,8 +401,9 @@ added: v8.5.0

* {number}

The high resolution millisecond timestamp at which third_party_main processing
ended.
The high resolution millisecond timestamp at which third\_party\_main
processing ended. If third\_party\_main processing has not yet ended, the
property has the value of -1.

### performanceNodeTiming.thirdPartyMainStart
<!-- YAML
@@ -405,8 +412,9 @@ added: v8.5.0

* {number}

The high resolution millisecond timestamp at which third_party_main processing
started.
The high resolution millisecond timestamp at which third\_party\_main
processing started. If third\_party\_main processing has not yet started, the
property has the value of -1.

### performanceNodeTiming.v8Start
<!-- YAML
@@ -642,6 +650,7 @@ obs.observe({ entryTypes: ['function'], buffered: true });
require('some-module');
```

[`'exit'`]: process.html#process_event_exit
[`timeOrigin`]: https://w3c.github.io/hr-time/#dom-performance-timeorigin
[Async Hooks]: async_hooks.html
[W3C Performance Timeline]: https://w3c.github.io/performance-timeline/
52 changes: 33 additions & 19 deletions lib/perf_hooks.js
Original file line number Diff line number Diff line change
@@ -8,6 +8,7 @@ const {
observerCounts,
setupObservers,
timeOrigin,
timeOriginTimestamp,
timerify,
constants
} = process.binding('performance');
@@ -146,6 +147,13 @@ function now() {
return hr[0] * 1000 + hr[1] / 1e6;
}

function getMilestoneTimestamp(milestoneIdx) {
const ns = milestones[milestoneIdx];
if (ns === -1)
return ns;
return ns / 1e6 - timeOrigin;
}

class PerformanceNodeTiming {
constructor() {}

@@ -158,67 +166,72 @@ class PerformanceNodeTiming {
}

get startTime() {
return timeOrigin;
return 0;
}

get duration() {
return now() - timeOrigin;
}

get nodeStart() {
return milestones[NODE_PERFORMANCE_MILESTONE_NODE_START];
return getMilestoneTimestamp(NODE_PERFORMANCE_MILESTONE_NODE_START);
}

get v8Start() {
return milestones[NODE_PERFORMANCE_MILESTONE_V8_START];
return getMilestoneTimestamp(NODE_PERFORMANCE_MILESTONE_V8_START);
}

get environment() {
return milestones[NODE_PERFORMANCE_MILESTONE_ENVIRONMENT];
return getMilestoneTimestamp(NODE_PERFORMANCE_MILESTONE_ENVIRONMENT);
}

get loopStart() {
return milestones[NODE_PERFORMANCE_MILESTONE_LOOP_START];
return getMilestoneTimestamp(NODE_PERFORMANCE_MILESTONE_LOOP_START);
}

get loopExit() {
return milestones[NODE_PERFORMANCE_MILESTONE_LOOP_EXIT];
return getMilestoneTimestamp(NODE_PERFORMANCE_MILESTONE_LOOP_EXIT);
}

get bootstrapComplete() {
return milestones[NODE_PERFORMANCE_MILESTONE_BOOTSTRAP_COMPLETE];
return getMilestoneTimestamp(NODE_PERFORMANCE_MILESTONE_BOOTSTRAP_COMPLETE);
}

get thirdPartyMainStart() {
return milestones[NODE_PERFORMANCE_MILESTONE_THIRD_PARTY_MAIN_START];
return getMilestoneTimestamp(
NODE_PERFORMANCE_MILESTONE_THIRD_PARTY_MAIN_START);
}

get thirdPartyMainEnd() {
return milestones[NODE_PERFORMANCE_MILESTONE_THIRD_PARTY_MAIN_END];
return getMilestoneTimestamp(
NODE_PERFORMANCE_MILESTONE_THIRD_PARTY_MAIN_END);
}

get clusterSetupStart() {
return milestones[NODE_PERFORMANCE_MILESTONE_CLUSTER_SETUP_START];
return getMilestoneTimestamp(
NODE_PERFORMANCE_MILESTONE_CLUSTER_SETUP_START);
}

get clusterSetupEnd() {
return milestones[NODE_PERFORMANCE_MILESTONE_CLUSTER_SETUP_END];
return getMilestoneTimestamp(NODE_PERFORMANCE_MILESTONE_CLUSTER_SETUP_END);
}

get moduleLoadStart() {
return milestones[NODE_PERFORMANCE_MILESTONE_MODULE_LOAD_START];
return getMilestoneTimestamp(NODE_PERFORMANCE_MILESTONE_MODULE_LOAD_START);
}

get moduleLoadEnd() {
return milestones[NODE_PERFORMANCE_MILESTONE_MODULE_LOAD_END];
return getMilestoneTimestamp(NODE_PERFORMANCE_MILESTONE_MODULE_LOAD_END);
}

get preloadModuleLoadStart() {
return milestones[NODE_PERFORMANCE_MILESTONE_PRELOAD_MODULE_LOAD_START];
return getMilestoneTimestamp(
NODE_PERFORMANCE_MILESTONE_PRELOAD_MODULE_LOAD_START);
}

get preloadModuleLoadEnd() {
return milestones[NODE_PERFORMANCE_MILESTONE_PRELOAD_MODULE_LOAD_END];
return getMilestoneTimestamp(
NODE_PERFORMANCE_MILESTONE_PRELOAD_MODULE_LOAD_END);
}

[kInspect]() {
@@ -467,11 +480,11 @@ class Performance extends PerformanceObserverEntryList {
}

get timeOrigin() {
return timeOrigin;
return timeOriginTimestamp;
}

now() {
return now();
return now() - timeOrigin;
}

mark(name) {
@@ -550,8 +563,9 @@ class Performance extends PerformanceObserverEntryList {

[kInspect]() {
return {
timeOrigin,
nodeTiming
maxEntries: this.maxEntries,
nodeTiming: this.nodeTiming,
timeOrigin: this.timeOrigin
};
}
}
35 changes: 35 additions & 0 deletions src/node_perf.cc
Original file line number Diff line number Diff line change
@@ -3,6 +3,10 @@

#include <vector>

#ifdef __POSIX__
#include <sys/time.h> // gettimeofday
#endif

namespace node {
namespace performance {

@@ -21,13 +25,38 @@ using v8::Object;
using v8::String;
using v8::Value;

// Microseconds in a second, as a float.
#define MICROS_PER_SEC 1e6
// Microseconds in a millisecond, as a float.
#define MICROS_PER_MILLIS 1e3

// 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_node_start;
uint64_t performance_v8_start;

uint64_t performance_last_gc_start_mark_ = 0;
v8::GCType performance_last_gc_type_ = v8::GCType::kGCTypeAll;

double GetCurrentTimeInMicroseconds() {
#ifdef _WIN32
// The difference between the Unix Epoch and the Windows Epoch in 100-ns ticks.
#define TICKS_TO_UNIX_EPOCH 116444736000000000LL
FILETIME ft;
GetSystemTimeAsFileTime(&ft);
uint64_t filetime_int = static_cast<uint64_t>(ft.dwHighDateTime) << 32 |
ft.dwLowDateTime;
// FILETIME is measured in terms of 100 ns. Convert that to 1 us (1000 ns).
return (filetime_int - TICKS_TO_UNIX_EPOCH) / 10.;
#else
struct timeval tp;
gettimeofday(&tp, nullptr);
return MICROS_PER_SEC * tp.tv_sec + tp.tv_usec;
#endif
}

// Initialize the performance entry object properties
inline void InitObject(const PerformanceEntry& entry, Local<Object> obj) {
Environment* env = entry.env();
@@ -384,6 +413,12 @@ void Init(Local<Object> target,
v8::Number::New(isolate, timeOrigin / 1e6),
attr).ToChecked();

target->DefineOwnProperty(
context,
FIXED_ONE_BYTE_STRING(isolate, "timeOriginTimestamp"),
v8::Number::New(isolate, timeOriginTimestamp / MICROS_PER_MILLIS),
attr).ToChecked();

target->DefineOwnProperty(context,
env->constants_string(),
constants,
8 changes: 6 additions & 2 deletions src/node_perf.h
Original file line number Diff line number Diff line change
@@ -23,6 +23,10 @@ using v8::Local;
using v8::Object;
using v8::Value;

extern const uint64_t timeOrigin;

double GetCurrentTimeInMicroseconds();

static inline PerformanceMilestone ToPerformanceMilestoneEnum(const char* str) {
#define V(name, label) \
if (strcmp(str, label) == 0) return NODE_PERFORMANCE_MILESTONE_##name;
@@ -78,11 +82,11 @@ class PerformanceEntry {
return ToPerformanceEntryTypeEnum(type().c_str());
}

double startTime() const { return startTime_ / 1e6; }
double startTime() const { return startTimeNano() / 1e6; }

double duration() const { return durationNano() / 1e6; }

uint64_t startTimeNano() const { return startTime_; }
uint64_t startTimeNano() const { return startTime_ - timeOrigin; }

uint64_t durationNano() const { return endTime_ - startTime_; }

6 changes: 5 additions & 1 deletion src/node_perf_common.h
Original file line number Diff line number Diff line change
@@ -4,6 +4,7 @@
#include "node.h"
#include "v8.h"

#include <algorithm>
#include <map>
#include <string>

@@ -76,7 +77,10 @@ class performance_state {
isolate,
offsetof(performance_state_internal, observers),
NODE_PERFORMANCE_ENTRY_TYPE_INVALID,
root) {}
root) {
for (size_t i = 0; i < milestones.Length(); i++)
milestones[i] = -1.;
}

AliasedBuffer<uint8_t, v8::Uint8Array> root;
AliasedBuffer<double, v8::Float64Array> milestones;
Loading

0 comments on commit 9256dbb

Please sign in to comment.