perf_hooks: fix timing

Fixes: #17892 Fixes: #17893 Fixes: #18992 PR-URL: #18993 Reviewed-By: James M Snell <[email protected]> Reviewed-By: Anna Henningsen <[email protected]> Reviewed-By: Colin Ihrig <[email protected]> Reviewed-By: Anatoli Papirovski <[email protected]>
nodejs · Mar 7, 2018 · 28880cf · 28880cf
1 parent cc52dae
commit 28880cf
Show file tree

Hide file tree

Showing 6 changed files with 182 additions and 52 deletions.
diff --git a/doc/api/perf_hooks.md b/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
-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/
diff --git a/lib/perf_hooks.js b/lib/perf_hooks.js
@@ -8,6 +8,7 @@ const {
   observerCounts,
   setupObservers,
   timeOrigin,
+  timeOriginTimestamp,
   timerify,
   constants
 } = process.binding('performance');
@@ -145,6 +146,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() {}
 
@@ -157,67 +165,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]() {
@@ -466,11 +479,11 @@ class Performance extends PerformanceObserverEntryList {
   }
 
   get timeOrigin() {
-    return timeOrigin;
+    return timeOriginTimestamp;
   }
 
   now() {
-    return now();
+    return now() - timeOrigin;
   }
 
   mark(name) {
@@ -549,8 +562,9 @@ class Performance extends PerformanceObserverEntryList {
 
   [kInspect]() {
     return {
-      timeOrigin,
-      nodeTiming
+      maxEntries: this.maxEntries,
+      nodeTiming: this.nodeTiming,
+      timeOrigin: this.timeOrigin
     };
   }
 }

diff --git a/src/node_perf.cc b/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();
@@ -372,6 +401,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,

diff --git a/src/node_perf.h b/src/node_perf.h
@@ -22,6 +22,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;
@@ -77,11 +81,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_; }
 

diff --git a/src/node_perf_common.h b/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;