Skip to content

Commit 1a1288d

Browse files
TimothyGuMylesBorins
authored andcommitted
perf_hooks: fix timing
Fixes: #17892 Fixes: #17893 Fixes: #18992 Backport-PR-URL: #22380 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>
1 parent f33f323 commit 1a1288d

File tree

6 files changed

+182
-52
lines changed

6 files changed

+182
-52
lines changed

doc/api/perf_hooks.md

Lines changed: 20 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -181,7 +181,8 @@ added: v8.5.0
181181

182182
* Returns: {number}
183183

184-
Returns the current high resolution millisecond timestamp.
184+
Returns the current high resolution millisecond timestamp, where 0 represents
185+
the start of the current `node` process.
185186

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

191192
* {number}
192193

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

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

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

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

312314
* {number}
313315

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

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

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

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

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

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

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

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

396402
* {number}
397403

398-
The high resolution millisecond timestamp at which third_party_main processing
399-
ended.
404+
The high resolution millisecond timestamp at which third\_party\_main
405+
processing ended. If third\_party\_main processing has not yet ended, the
406+
property has the value of -1.
400407

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

406413
* {number}
407414

408-
The high resolution millisecond timestamp at which third_party_main processing
409-
started.
415+
The high resolution millisecond timestamp at which third\_party\_main
416+
processing started. If third\_party\_main processing has not yet started, the
417+
property has the value of -1.
410418

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

653+
[`'exit'`]: process.html#process_event_exit
645654
[`timeOrigin`]: https://w3c.github.io/hr-time/#dom-performance-timeorigin
646655
[Async Hooks]: async_hooks.html
647656
[W3C Performance Timeline]: https://w3c.github.io/performance-timeline/

lib/perf_hooks.js

Lines changed: 33 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -8,6 +8,7 @@ const {
88
observerCounts,
99
setupObservers,
1010
timeOrigin,
11+
timeOriginTimestamp,
1112
timerify,
1213
constants
1314
} = process.binding('performance');
@@ -145,6 +146,13 @@ function now() {
145146
return hr[0] * 1000 + hr[1] / 1e6;
146147
}
147148

149+
function getMilestoneTimestamp(milestoneIdx) {
150+
const ns = milestones[milestoneIdx];
151+
if (ns === -1)
152+
return ns;
153+
return ns / 1e6 - timeOrigin;
154+
}
155+
148156
class PerformanceNodeTiming {
149157
constructor() {}
150158

@@ -157,67 +165,72 @@ class PerformanceNodeTiming {
157165
}
158166

159167
get startTime() {
160-
return timeOrigin;
168+
return 0;
161169
}
162170

163171
get duration() {
164172
return now() - timeOrigin;
165173
}
166174

167175
get nodeStart() {
168-
return milestones[NODE_PERFORMANCE_MILESTONE_NODE_START];
176+
return getMilestoneTimestamp(NODE_PERFORMANCE_MILESTONE_NODE_START);
169177
}
170178

171179
get v8Start() {
172-
return milestones[NODE_PERFORMANCE_MILESTONE_V8_START];
180+
return getMilestoneTimestamp(NODE_PERFORMANCE_MILESTONE_V8_START);
173181
}
174182

175183
get environment() {
176-
return milestones[NODE_PERFORMANCE_MILESTONE_ENVIRONMENT];
184+
return getMilestoneTimestamp(NODE_PERFORMANCE_MILESTONE_ENVIRONMENT);
177185
}
178186

179187
get loopStart() {
180-
return milestones[NODE_PERFORMANCE_MILESTONE_LOOP_START];
188+
return getMilestoneTimestamp(NODE_PERFORMANCE_MILESTONE_LOOP_START);
181189
}
182190

183191
get loopExit() {
184-
return milestones[NODE_PERFORMANCE_MILESTONE_LOOP_EXIT];
192+
return getMilestoneTimestamp(NODE_PERFORMANCE_MILESTONE_LOOP_EXIT);
185193
}
186194

187195
get bootstrapComplete() {
188-
return milestones[NODE_PERFORMANCE_MILESTONE_BOOTSTRAP_COMPLETE];
196+
return getMilestoneTimestamp(NODE_PERFORMANCE_MILESTONE_BOOTSTRAP_COMPLETE);
189197
}
190198

191199
get thirdPartyMainStart() {
192-
return milestones[NODE_PERFORMANCE_MILESTONE_THIRD_PARTY_MAIN_START];
200+
return getMilestoneTimestamp(
201+
NODE_PERFORMANCE_MILESTONE_THIRD_PARTY_MAIN_START);
193202
}
194203

195204
get thirdPartyMainEnd() {
196-
return milestones[NODE_PERFORMANCE_MILESTONE_THIRD_PARTY_MAIN_END];
205+
return getMilestoneTimestamp(
206+
NODE_PERFORMANCE_MILESTONE_THIRD_PARTY_MAIN_END);
197207
}
198208

199209
get clusterSetupStart() {
200-
return milestones[NODE_PERFORMANCE_MILESTONE_CLUSTER_SETUP_START];
210+
return getMilestoneTimestamp(
211+
NODE_PERFORMANCE_MILESTONE_CLUSTER_SETUP_START);
201212
}
202213

203214
get clusterSetupEnd() {
204-
return milestones[NODE_PERFORMANCE_MILESTONE_CLUSTER_SETUP_END];
215+
return getMilestoneTimestamp(NODE_PERFORMANCE_MILESTONE_CLUSTER_SETUP_END);
205216
}
206217

207218
get moduleLoadStart() {
208-
return milestones[NODE_PERFORMANCE_MILESTONE_MODULE_LOAD_START];
219+
return getMilestoneTimestamp(NODE_PERFORMANCE_MILESTONE_MODULE_LOAD_START);
209220
}
210221

211222
get moduleLoadEnd() {
212-
return milestones[NODE_PERFORMANCE_MILESTONE_MODULE_LOAD_END];
223+
return getMilestoneTimestamp(NODE_PERFORMANCE_MILESTONE_MODULE_LOAD_END);
213224
}
214225

215226
get preloadModuleLoadStart() {
216-
return milestones[NODE_PERFORMANCE_MILESTONE_PRELOAD_MODULE_LOAD_START];
227+
return getMilestoneTimestamp(
228+
NODE_PERFORMANCE_MILESTONE_PRELOAD_MODULE_LOAD_START);
217229
}
218230

219231
get preloadModuleLoadEnd() {
220-
return milestones[NODE_PERFORMANCE_MILESTONE_PRELOAD_MODULE_LOAD_END];
232+
return getMilestoneTimestamp(
233+
NODE_PERFORMANCE_MILESTONE_PRELOAD_MODULE_LOAD_END);
221234
}
222235

223236
[kInspect]() {
@@ -466,11 +479,11 @@ class Performance extends PerformanceObserverEntryList {
466479
}
467480

468481
get timeOrigin() {
469-
return timeOrigin;
482+
return timeOriginTimestamp;
470483
}
471484

472485
now() {
473-
return now();
486+
return now() - timeOrigin;
474487
}
475488

476489
mark(name) {
@@ -549,8 +562,9 @@ class Performance extends PerformanceObserverEntryList {
549562

550563
[kInspect]() {
551564
return {
552-
timeOrigin,
553-
nodeTiming
565+
maxEntries: this.maxEntries,
566+
nodeTiming: this.nodeTiming,
567+
timeOrigin: this.timeOrigin
554568
};
555569
}
556570
}

src/node_perf.cc

Lines changed: 35 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,10 @@
33

44
#include <vector>
55

6+
#ifdef __POSIX__
7+
#include <sys/time.h> // gettimeofday
8+
#endif
9+
610
namespace node {
711
namespace performance {
812

@@ -22,13 +26,38 @@ using v8::Object;
2226
using v8::String;
2327
using v8::Value;
2428

29+
// Microseconds in a second, as a float.
30+
#define MICROS_PER_SEC 1e6
31+
// Microseconds in a millisecond, as a float.
32+
#define MICROS_PER_MILLIS 1e3
33+
34+
// https://w3c.github.io/hr-time/#dfn-time-origin
2535
const uint64_t timeOrigin = PERFORMANCE_NOW();
36+
// https://w3c.github.io/hr-time/#dfn-time-origin-timestamp
37+
const double timeOriginTimestamp = GetCurrentTimeInMicroseconds();
2638
uint64_t performance_node_start;
2739
uint64_t performance_v8_start;
2840

2941
uint64_t performance_last_gc_start_mark_ = 0;
3042
v8::GCType performance_last_gc_type_ = v8::GCType::kGCTypeAll;
3143

44+
double GetCurrentTimeInMicroseconds() {
45+
#ifdef _WIN32
46+
// The difference between the Unix Epoch and the Windows Epoch in 100-ns ticks.
47+
#define TICKS_TO_UNIX_EPOCH 116444736000000000LL
48+
FILETIME ft;
49+
GetSystemTimeAsFileTime(&ft);
50+
uint64_t filetime_int = static_cast<uint64_t>(ft.dwHighDateTime) << 32 |
51+
ft.dwLowDateTime;
52+
// FILETIME is measured in terms of 100 ns. Convert that to 1 us (1000 ns).
53+
return (filetime_int - TICKS_TO_UNIX_EPOCH) / 10.;
54+
#else
55+
struct timeval tp;
56+
gettimeofday(&tp, nullptr);
57+
return MICROS_PER_SEC * tp.tv_sec + tp.tv_usec;
58+
#endif
59+
}
60+
3261
// Initialize the performance entry object properties
3362
inline void InitObject(const PerformanceEntry& entry, Local<Object> obj) {
3463
Environment* env = entry.env();
@@ -382,6 +411,12 @@ void Init(Local<Object> target,
382411
v8::Number::New(isolate, timeOrigin / 1e6),
383412
attr).ToChecked();
384413

414+
target->DefineOwnProperty(
415+
context,
416+
FIXED_ONE_BYTE_STRING(isolate, "timeOriginTimestamp"),
417+
v8::Number::New(isolate, timeOriginTimestamp / MICROS_PER_MILLIS),
418+
attr).ToChecked();
419+
385420
target->DefineOwnProperty(context,
386421
env->constants_string(),
387422
constants,

src/node_perf.h

Lines changed: 6 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -22,6 +22,10 @@ using v8::Local;
2222
using v8::Object;
2323
using v8::Value;
2424

25+
extern const uint64_t timeOrigin;
26+
27+
double GetCurrentTimeInMicroseconds();
28+
2529
static inline PerformanceMilestone ToPerformanceMilestoneEnum(const char* str) {
2630
#define V(name, label) \
2731
if (strcmp(str, label) == 0) return NODE_PERFORMANCE_MILESTONE_##name;
@@ -77,11 +81,11 @@ class PerformanceEntry {
7781
return ToPerformanceEntryTypeEnum(type().c_str());
7882
}
7983

80-
double startTime() const { return startTime_ / 1e6; }
84+
double startTime() const { return startTimeNano() / 1e6; }
8185

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

84-
uint64_t startTimeNano() const { return startTime_; }
88+
uint64_t startTimeNano() const { return startTime_ - timeOrigin; }
8589

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

src/node_perf_common.h

Lines changed: 5 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,7 @@
44
#include "node.h"
55
#include "v8.h"
66

7+
#include <algorithm>
78
#include <map>
89
#include <string>
910

@@ -76,7 +77,10 @@ class performance_state {
7677
isolate,
7778
offsetof(performance_state_internal, observers),
7879
NODE_PERFORMANCE_ENTRY_TYPE_INVALID,
79-
root) {}
80+
root) {
81+
for (size_t i = 0; i < milestones.Length(); i++)
82+
milestones[i] = -1.;
83+
}
8084

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

0 commit comments

Comments
 (0)