perf_hooks: fix timing

Fixes: https://github.com/nodejs/node/issues/17892
Fixes: https://github.com/nodejs/node/issues/17893
Fixes: https://github.com/nodejs/node/issues/18992

PR-URL: https://github.com/nodejs/node/pull/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>

doc/api/perf_hooks.md

@@ -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
+The [`timeOrigin`][] specifies the high resolution millisecond timestamp at
-which all performance metric durations are measured.
+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
+The high resolution millisecond timestamp at which third\_party\_main
-ended.
+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
+The high resolution millisecond timestamp at which third\_party\_main
-started.
+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/

lib/perf_hooks.js

@@ -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,7 +166,7 @@ class PerformanceNodeTiming {
   }
 
   get startTime() {
-    return timeOrigin;
+    return 0;
   }
 
   get duration() {
@@ -166,59 +174,64 @@ class PerformanceNodeTiming {
   }
 
   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,
+      maxEntries: this.maxEntries,
-      nodeTiming
+      nodeTiming: this.nodeTiming,
+      timeOrigin: this.timeOrigin
     };
   }
 }

src/node_perf.cc

@@ -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,

src/node_perf.h

@@ -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_; }
 

src/node_perf_common.h

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

test/parallel/test-performance.js

@@ -7,6 +7,12 @@ const { performance } = require('perf_hooks');
 assert(performance);
 assert(performance.nodeTiming);
 assert.strictEqual(typeof performance.timeOrigin, 'number');
+// Use a fairly large epsilon value, since we can only guarantee that the node
+// process started up in 20 seconds.
+assert(Math.abs(performance.timeOrigin - Date.now()) < 20000);
+
+const inited = performance.now();
+assert(inited < 20000);
 
 {
   const entries = performance.getEntries();
@@ -104,23 +110,81 @@ assert.strictEqual(typeof performance.timeOrigin, 'number');
 assert.strictEqual(performance.nodeTiming.name, 'node');
 assert.strictEqual(performance.nodeTiming.entryType, 'node');
 
-[
+function checkNodeTiming(props) {
-  'startTime',
+  for (const prop of Object.keys(props)) {
-  'duration',
+    if (props[prop].around !== undefined) {
-  'nodeStart',
+      assert.strictEqual(typeof performance.nodeTiming[prop], 'number');
-  'v8Start',
+      const delta = performance.nodeTiming[prop] - props[prop].around;
-  'bootstrapComplete',
+      assert(Math.abs(delta) < 1000);
-  'environment',
+    } else {
-  'loopStart',
+      assert.strictEqual(performance.nodeTiming[prop], props[prop]);
-  'loopExit',
+    }
-  'thirdPartyMainStart',
+  }
-  'thirdPartyMainEnd',
+}
-  'clusterSetupStart',
+
-  'clusterSetupEnd',
+checkNodeTiming({
-  'moduleLoadStart',
+  name: 'node',
-  'moduleLoadEnd',
+  entryType: 'node',
-  'preloadModuleLoadStart',
+  startTime: 0,
-  'preloadModuleLoadEnd'
+  duration: { around: performance.now() },
-].forEach((i) => {
+  nodeStart: { around: 0 },
-  assert.strictEqual(typeof performance.nodeTiming[i], 'number');
+  v8Start: { around: 0 },
+  bootstrapComplete: -1,
+  environment: { around: 0 },
+  loopStart: -1,
+  loopExit: -1,
+  thirdPartyMainStart: -1,
+  thirdPartyMainEnd: -1,
+  clusterSetupStart: -1,
+  clusterSetupEnd: -1,
+  moduleLoadStart: { around: inited },
+  moduleLoadEnd: { around: inited },
+  preloadModuleLoadStart: { around: inited },
+  preloadModuleLoadEnd: { around: inited },
+});
+
+setTimeout(() => {
+  checkNodeTiming({
+    name: 'node',
+    entryType: 'node',
+    startTime: 0,
+    duration: { around: performance.now() },
+    nodeStart: { around: 0 },
+    v8Start: { around: 0 },
+    bootstrapComplete: { around: inited },
+    environment: { around: 0 },
+    loopStart: { around: inited },
+    loopExit: -1,
+    thirdPartyMainStart: -1,
+    thirdPartyMainEnd: -1,
+    clusterSetupStart: -1,
+    clusterSetupEnd: -1,
+    moduleLoadStart: { around: inited },
+    moduleLoadEnd: { around: inited },
+    preloadModuleLoadStart: { around: inited },
+    preloadModuleLoadEnd: { around: inited },
+  });
+}, 2000);
+
+process.on('exit', () => {
+  checkNodeTiming({
+    name: 'node',
+    entryType: 'node',
+    startTime: 0,
+    duration: { around: performance.now() },
+    nodeStart: { around: 0 },
+    v8Start: { around: 0 },
+    bootstrapComplete: { around: inited },
+    environment: { around: 0 },
+    loopStart: { around: inited },
+    loopExit: { around: performance.now() },
+    thirdPartyMainStart: -1,
+    thirdPartyMainEnd: -1,
+    clusterSetupStart: -1,
+    clusterSetupEnd: -1,
+    moduleLoadStart: { around: inited },
+    moduleLoadEnd: { around: inited },
+    preloadModuleLoadStart: { around: inited },
+    preloadModuleLoadEnd: { around: inited },
+  });
 });