/src/node/src/node_perf.cc
Line | Count | Source (jump to first uncovered line) |
1 | | #include "node_perf.h" |
2 | | #include "aliased_buffer-inl.h" |
3 | | #include "env-inl.h" |
4 | | #include "histogram-inl.h" |
5 | | #include "memory_tracker-inl.h" |
6 | | #include "node_buffer.h" |
7 | | #include "node_external_reference.h" |
8 | | #include "node_internals.h" |
9 | | #include "node_process-inl.h" |
10 | | #include "util-inl.h" |
11 | | |
12 | | #include <cinttypes> |
13 | | |
14 | | namespace node { |
15 | | namespace performance { |
16 | | |
17 | | using v8::Context; |
18 | | using v8::DontDelete; |
19 | | using v8::Function; |
20 | | using v8::FunctionCallbackInfo; |
21 | | using v8::GCCallbackFlags; |
22 | | using v8::GCType; |
23 | | using v8::Integer; |
24 | | using v8::Isolate; |
25 | | using v8::Local; |
26 | | using v8::MaybeLocal; |
27 | | using v8::Object; |
28 | | using v8::ObjectTemplate; |
29 | | using v8::PropertyAttribute; |
30 | | using v8::ReadOnly; |
31 | | using v8::Value; |
32 | | |
33 | | // Microseconds in a millisecond, as a float. |
34 | | #define MICROS_PER_MILLIS 1e3 |
35 | | // Nanoseconds in a millisecond, as a float. |
36 | 0 | #define NANOS_PER_MILLIS 1e6 |
37 | | |
38 | | const uint64_t performance_process_start = PERFORMANCE_NOW(); |
39 | | const double performance_process_start_timestamp = |
40 | | GetCurrentTimeInMicroseconds(); |
41 | | uint64_t performance_v8_start; |
42 | | |
43 | | PerformanceState::PerformanceState(Isolate* isolate, |
44 | | uint64_t time_origin, |
45 | | double time_origin_timestamp, |
46 | | const PerformanceState::SerializeInfo* info) |
47 | 134k | : root(isolate, |
48 | 134k | sizeof(performance_state_internal), |
49 | 134k | MAYBE_FIELD_PTR(info, root)), |
50 | 134k | milestones(isolate, |
51 | 134k | offsetof(performance_state_internal, milestones), |
52 | 134k | NODE_PERFORMANCE_MILESTONE_INVALID, |
53 | 134k | root, |
54 | 134k | MAYBE_FIELD_PTR(info, milestones)), |
55 | 134k | observers(isolate, |
56 | 134k | offsetof(performance_state_internal, observers), |
57 | 134k | NODE_PERFORMANCE_ENTRY_TYPE_INVALID, |
58 | 134k | root, |
59 | 134k | MAYBE_FIELD_PTR(info, observers)) { |
60 | 134k | if (info == nullptr) { |
61 | | // For performance states initialized from scratch, reset |
62 | | // all the milestones and initialize the time origin. |
63 | | // For deserialized performance states, we will do the |
64 | | // initialization in the deserialize callback. |
65 | 134k | ResetMilestones(); |
66 | 134k | Initialize(time_origin, time_origin_timestamp); |
67 | 134k | } |
68 | 134k | } |
69 | | |
70 | 134k | void PerformanceState::ResetMilestones() { |
71 | 134k | size_t milestones_length = milestones.Length(); |
72 | 1.21M | for (size_t i = 0; i < milestones_length; ++i) { |
73 | 1.07M | milestones[i] = -1; |
74 | 1.07M | } |
75 | 134k | } |
76 | | |
77 | | PerformanceState::SerializeInfo PerformanceState::Serialize( |
78 | 0 | v8::Local<v8::Context> context, v8::SnapshotCreator* creator) { |
79 | | // Reset all the milestones to improve determinism in the snapshot. |
80 | | // We'll re-initialize them after deserialization. |
81 | 0 | ResetMilestones(); |
82 | |
|
83 | 0 | SerializeInfo info{root.Serialize(context, creator), |
84 | 0 | milestones.Serialize(context, creator), |
85 | 0 | observers.Serialize(context, creator)}; |
86 | 0 | return info; |
87 | 0 | } |
88 | | |
89 | | void PerformanceState::Initialize(uint64_t time_origin, |
90 | 134k | double time_origin_timestamp) { |
91 | | // We are only reusing the milestone array to store the time origin |
92 | | // and time origin timestamp, so do not use the Mark() method. |
93 | | // The time origin milestone is not exposed to user land. |
94 | 134k | this->milestones[NODE_PERFORMANCE_MILESTONE_TIME_ORIGIN] = |
95 | 134k | static_cast<double>(time_origin); |
96 | 134k | this->milestones[NODE_PERFORMANCE_MILESTONE_TIME_ORIGIN_TIMESTAMP] = |
97 | 134k | time_origin_timestamp; |
98 | 134k | } |
99 | | |
100 | | void PerformanceState::Deserialize(v8::Local<v8::Context> context, |
101 | | uint64_t time_origin, |
102 | 0 | double time_origin_timestamp) { |
103 | | // Resets the pointers. |
104 | 0 | root.Deserialize(context); |
105 | 0 | milestones.Deserialize(context); |
106 | 0 | observers.Deserialize(context); |
107 | | |
108 | | // Re-initialize the time origin and timestamp i.e. the process start time. |
109 | 0 | Initialize(time_origin, time_origin_timestamp); |
110 | 0 | } |
111 | | |
112 | | std::ostream& operator<<(std::ostream& o, |
113 | 0 | const PerformanceState::SerializeInfo& i) { |
114 | 0 | o << "{\n" |
115 | 0 | << " " << i.root << ", // root\n" |
116 | 0 | << " " << i.milestones << ", // milestones\n" |
117 | 0 | << " " << i.observers << ", // observers\n" |
118 | 0 | << "}"; |
119 | 0 | return o; |
120 | 0 | } |
121 | | |
122 | 403k | void PerformanceState::Mark(PerformanceMilestone milestone, uint64_t ts) { |
123 | 403k | this->milestones[milestone] = static_cast<double>(ts); |
124 | 403k | TRACE_EVENT_INSTANT_WITH_TIMESTAMP0( |
125 | 403k | TRACING_CATEGORY_NODE1(bootstrap), |
126 | 403k | GetPerformanceMilestoneName(milestone), |
127 | 403k | TRACE_EVENT_SCOPE_THREAD, ts / 1000); |
128 | 403k | } |
129 | | |
130 | 90.4k | void SetupPerformanceObservers(const FunctionCallbackInfo<Value>& args) { |
131 | 90.4k | Realm* realm = Realm::GetCurrent(args); |
132 | | // TODO(legendecas): Remove this check once the sub-realms are supported. |
133 | 90.4k | CHECK_EQ(realm->kind(), Realm::Kind::kPrincipal); |
134 | 90.4k | CHECK(args[0]->IsFunction()); |
135 | 90.4k | realm->set_performance_entry_callback(args[0].As<Function>()); |
136 | 90.4k | } |
137 | | |
138 | | // Marks the start of a GC cycle |
139 | | void MarkGarbageCollectionStart( |
140 | | Isolate* isolate, |
141 | | GCType type, |
142 | | GCCallbackFlags flags, |
143 | 0 | void* data) { |
144 | 0 | Environment* env = static_cast<Environment*>(data); |
145 | | // Prevent gc callback from reentering with different type |
146 | | // See https://github.com/nodejs/node/issues/44046 |
147 | 0 | if (env->performance_state()->current_gc_type != 0) { |
148 | 0 | return; |
149 | 0 | } |
150 | 0 | env->performance_state()->performance_last_gc_start_mark = PERFORMANCE_NOW(); |
151 | 0 | env->performance_state()->current_gc_type = type; |
152 | 0 | } |
153 | | |
154 | | MaybeLocal<Object> GCPerformanceEntryTraits::GetDetails( |
155 | | Environment* env, |
156 | 0 | const GCPerformanceEntry& entry) { |
157 | 0 | Local<Object> obj = Object::New(env->isolate()); |
158 | |
|
159 | 0 | if (!obj->Set( |
160 | 0 | env->context(), |
161 | 0 | env->kind_string(), |
162 | 0 | Integer::NewFromUnsigned( |
163 | 0 | env->isolate(), |
164 | 0 | entry.details.kind)).IsJust()) { |
165 | 0 | return MaybeLocal<Object>(); |
166 | 0 | } |
167 | | |
168 | 0 | if (!obj->Set( |
169 | 0 | env->context(), |
170 | 0 | env->flags_string(), |
171 | 0 | Integer::NewFromUnsigned( |
172 | 0 | env->isolate(), |
173 | 0 | entry.details.flags)).IsJust()) { |
174 | 0 | return MaybeLocal<Object>(); |
175 | 0 | } |
176 | | |
177 | 0 | return obj; |
178 | 0 | } |
179 | | |
180 | | // Marks the end of a GC cycle |
181 | | void MarkGarbageCollectionEnd( |
182 | | Isolate* isolate, |
183 | | GCType type, |
184 | | GCCallbackFlags flags, |
185 | 0 | void* data) { |
186 | 0 | Environment* env = static_cast<Environment*>(data); |
187 | 0 | PerformanceState* state = env->performance_state(); |
188 | 0 | if (type != state->current_gc_type) { |
189 | 0 | return; |
190 | 0 | } |
191 | 0 | env->performance_state()->current_gc_type = 0; |
192 | | // If no one is listening to gc performance entries, do not create them. |
193 | 0 | if (LIKELY(!state->observers[NODE_PERFORMANCE_ENTRY_TYPE_GC])) |
194 | 0 | return; |
195 | | |
196 | 0 | double start_time = |
197 | 0 | (state->performance_last_gc_start_mark - env->time_origin()) / |
198 | 0 | NANOS_PER_MILLIS; |
199 | 0 | double duration = (PERFORMANCE_NOW() / NANOS_PER_MILLIS) - |
200 | 0 | (state->performance_last_gc_start_mark / NANOS_PER_MILLIS); |
201 | |
|
202 | 0 | std::unique_ptr<GCPerformanceEntry> entry = |
203 | 0 | std::make_unique<GCPerformanceEntry>( |
204 | 0 | "gc", |
205 | 0 | start_time, |
206 | 0 | duration, |
207 | 0 | GCPerformanceEntry::Details(static_cast<PerformanceGCKind>(type), |
208 | 0 | static_cast<PerformanceGCFlags>(flags))); |
209 | |
|
210 | 0 | env->SetImmediate([entry = std::move(entry)](Environment* env) { |
211 | 0 | entry->Notify(env); |
212 | 0 | }, CallbackFlags::kUnrefed); |
213 | 0 | } |
214 | | |
215 | 0 | void GarbageCollectionCleanupHook(void* data) { |
216 | 0 | Environment* env = static_cast<Environment*>(data); |
217 | | // Reset current_gc_type to 0 |
218 | 0 | env->performance_state()->current_gc_type = 0; |
219 | 0 | env->isolate()->RemoveGCPrologueCallback(MarkGarbageCollectionStart, data); |
220 | 0 | env->isolate()->RemoveGCEpilogueCallback(MarkGarbageCollectionEnd, data); |
221 | 0 | } |
222 | | |
223 | | static void InstallGarbageCollectionTracking( |
224 | 0 | const FunctionCallbackInfo<Value>& args) { |
225 | 0 | Environment* env = Environment::GetCurrent(args); |
226 | | // Reset current_gc_type to 0 |
227 | 0 | env->performance_state()->current_gc_type = 0; |
228 | 0 | env->isolate()->AddGCPrologueCallback(MarkGarbageCollectionStart, |
229 | 0 | static_cast<void*>(env)); |
230 | 0 | env->isolate()->AddGCEpilogueCallback(MarkGarbageCollectionEnd, |
231 | 0 | static_cast<void*>(env)); |
232 | 0 | env->AddCleanupHook(GarbageCollectionCleanupHook, env); |
233 | 0 | } |
234 | | |
235 | | static void RemoveGarbageCollectionTracking( |
236 | 0 | const FunctionCallbackInfo<Value> &args) { |
237 | 0 | Environment* env = Environment::GetCurrent(args); |
238 | |
|
239 | 0 | env->RemoveCleanupHook(GarbageCollectionCleanupHook, env); |
240 | 0 | GarbageCollectionCleanupHook(env); |
241 | 0 | } |
242 | | |
243 | | // Notify a custom PerformanceEntry to observers |
244 | 0 | void Notify(const FunctionCallbackInfo<Value>& args) { |
245 | 0 | Environment* env = Environment::GetCurrent(args); |
246 | 0 | Utf8Value type(env->isolate(), args[0]); |
247 | 0 | Local<Value> entry = args[1]; |
248 | 0 | PerformanceEntryType entry_type = ToPerformanceEntryTypeEnum(*type); |
249 | 0 | AliasedUint32Array& observers = env->performance_state()->observers; |
250 | 0 | if (entry_type != NODE_PERFORMANCE_ENTRY_TYPE_INVALID && |
251 | 0 | observers[entry_type]) { |
252 | 0 | USE(env->performance_entry_callback()-> |
253 | 0 | Call(env->context(), Undefined(env->isolate()), 1, &entry)); |
254 | 0 | } |
255 | 0 | } |
256 | | |
257 | | // Return idle time of the event loop |
258 | 0 | void LoopIdleTime(const FunctionCallbackInfo<Value>& args) { |
259 | 0 | Environment* env = Environment::GetCurrent(args); |
260 | 0 | uint64_t idle_time = uv_metrics_idle_time(env->event_loop()); |
261 | 0 | args.GetReturnValue().Set(1.0 * idle_time / NANOS_PER_MILLIS); |
262 | 0 | } |
263 | | |
264 | 0 | void CreateELDHistogram(const FunctionCallbackInfo<Value>& args) { |
265 | 0 | Environment* env = Environment::GetCurrent(args); |
266 | 0 | int64_t interval = args[0].As<Integer>()->Value(); |
267 | 0 | CHECK_GT(interval, 0); |
268 | 0 | BaseObjectPtr<IntervalHistogram> histogram = |
269 | 0 | IntervalHistogram::Create(env, interval, [](Histogram& histogram) { |
270 | 0 | uint64_t delta = histogram.RecordDelta(); |
271 | 0 | TRACE_COUNTER1(TRACING_CATEGORY_NODE2(perf, event_loop), |
272 | 0 | "delay", delta); |
273 | 0 | TRACE_COUNTER1(TRACING_CATEGORY_NODE2(perf, event_loop), |
274 | 0 | "min", histogram.Min()); |
275 | 0 | TRACE_COUNTER1(TRACING_CATEGORY_NODE2(perf, event_loop), |
276 | 0 | "max", histogram.Max()); |
277 | 0 | TRACE_COUNTER1(TRACING_CATEGORY_NODE2(perf, event_loop), |
278 | 0 | "mean", histogram.Mean()); |
279 | 0 | TRACE_COUNTER1(TRACING_CATEGORY_NODE2(perf, event_loop), |
280 | 0 | "stddev", histogram.Stddev()); |
281 | 0 | }, Histogram::Options { 1000 }); |
282 | 0 | args.GetReturnValue().Set(histogram->object()); |
283 | 0 | } |
284 | | |
285 | 0 | void MarkBootstrapComplete(const FunctionCallbackInfo<Value>& args) { |
286 | 0 | Realm* realm = Realm::GetCurrent(args); |
287 | 0 | CHECK_EQ(realm->kind(), Realm::Kind::kPrincipal); |
288 | 0 | realm->env()->performance_state()->Mark( |
289 | 0 | performance::NODE_PERFORMANCE_MILESTONE_BOOTSTRAP_COMPLETE); |
290 | 0 | } |
291 | | |
292 | 0 | static double PerformanceNowImpl() { |
293 | 0 | return static_cast<double>(uv_hrtime() - performance_process_start) / |
294 | 0 | NANOS_PER_MILLIS; |
295 | 0 | } |
296 | | |
297 | 0 | static double FastPerformanceNow(v8::Local<v8::Value> receiver) { |
298 | 0 | return PerformanceNowImpl(); |
299 | 0 | } |
300 | | |
301 | 0 | static void SlowPerformanceNow(const FunctionCallbackInfo<Value>& args) { |
302 | 0 | args.GetReturnValue().Set(PerformanceNowImpl()); |
303 | 0 | } |
304 | | |
305 | | static v8::CFunction fast_performance_now( |
306 | | v8::CFunction::Make(FastPerformanceNow)); |
307 | | |
308 | | static void CreatePerIsolateProperties(IsolateData* isolate_data, |
309 | 134k | Local<ObjectTemplate> target) { |
310 | 134k | Isolate* isolate = isolate_data->isolate(); |
311 | | |
312 | 134k | HistogramBase::Initialize(isolate_data, target); |
313 | | |
314 | 134k | SetMethod(isolate, target, "setupObservers", SetupPerformanceObservers); |
315 | 134k | SetMethod(isolate, |
316 | 134k | target, |
317 | 134k | "installGarbageCollectionTracking", |
318 | 134k | InstallGarbageCollectionTracking); |
319 | 134k | SetMethod(isolate, |
320 | 134k | target, |
321 | 134k | "removeGarbageCollectionTracking", |
322 | 134k | RemoveGarbageCollectionTracking); |
323 | 134k | SetMethod(isolate, target, "notify", Notify); |
324 | 134k | SetMethod(isolate, target, "loopIdleTime", LoopIdleTime); |
325 | 134k | SetMethod(isolate, target, "createELDHistogram", CreateELDHistogram); |
326 | 134k | SetMethod(isolate, target, "markBootstrapComplete", MarkBootstrapComplete); |
327 | 134k | SetFastMethodNoSideEffect( |
328 | 134k | isolate, target, "now", SlowPerformanceNow, &fast_performance_now); |
329 | 134k | } |
330 | | |
331 | | void CreatePerContextProperties(Local<Object> target, |
332 | | Local<Value> unused, |
333 | | Local<Context> context, |
334 | 134k | void* priv) { |
335 | 134k | Environment* env = Environment::GetCurrent(context); |
336 | 134k | Isolate* isolate = env->isolate(); |
337 | 134k | PerformanceState* state = env->performance_state(); |
338 | | |
339 | 134k | target->Set(context, |
340 | 134k | FIXED_ONE_BYTE_STRING(isolate, "observerCounts"), |
341 | 134k | state->observers.GetJSArray()).Check(); |
342 | 134k | target->Set(context, |
343 | 134k | FIXED_ONE_BYTE_STRING(isolate, "milestones"), |
344 | 134k | state->milestones.GetJSArray()).Check(); |
345 | | |
346 | 134k | Local<Object> constants = Object::New(isolate); |
347 | | |
348 | 134k | NODE_DEFINE_CONSTANT(constants, NODE_PERFORMANCE_GC_MAJOR); |
349 | 134k | NODE_DEFINE_CONSTANT(constants, NODE_PERFORMANCE_GC_MINOR); |
350 | 134k | NODE_DEFINE_CONSTANT(constants, NODE_PERFORMANCE_GC_INCREMENTAL); |
351 | 134k | NODE_DEFINE_CONSTANT(constants, NODE_PERFORMANCE_GC_WEAKCB); |
352 | | |
353 | 134k | NODE_DEFINE_CONSTANT( |
354 | 134k | constants, NODE_PERFORMANCE_GC_FLAGS_NO); |
355 | 134k | NODE_DEFINE_CONSTANT( |
356 | 134k | constants, NODE_PERFORMANCE_GC_FLAGS_CONSTRUCT_RETAINED); |
357 | 134k | NODE_DEFINE_CONSTANT( |
358 | 134k | constants, NODE_PERFORMANCE_GC_FLAGS_FORCED); |
359 | 134k | NODE_DEFINE_CONSTANT( |
360 | 134k | constants, NODE_PERFORMANCE_GC_FLAGS_SYNCHRONOUS_PHANTOM_PROCESSING); |
361 | 134k | NODE_DEFINE_CONSTANT( |
362 | 134k | constants, NODE_PERFORMANCE_GC_FLAGS_ALL_AVAILABLE_GARBAGE); |
363 | 134k | NODE_DEFINE_CONSTANT( |
364 | 134k | constants, NODE_PERFORMANCE_GC_FLAGS_ALL_EXTERNAL_MEMORY); |
365 | 134k | NODE_DEFINE_CONSTANT( |
366 | 134k | constants, NODE_PERFORMANCE_GC_FLAGS_SCHEDULE_IDLE); |
367 | | |
368 | 134k | #define V(name, _) \ |
369 | 672k | NODE_DEFINE_HIDDEN_CONSTANT(constants, NODE_PERFORMANCE_ENTRY_TYPE_##name); |
370 | 672k | NODE_PERFORMANCE_ENTRY_TYPES(V) |
371 | 134k | #undef V |
372 | | |
373 | 134k | #define V(name, _) \ |
374 | 1.07M | NODE_DEFINE_HIDDEN_CONSTANT(constants, NODE_PERFORMANCE_MILESTONE_##name); |
375 | 1.07M | NODE_PERFORMANCE_MILESTONES(V) |
376 | 134k | #undef V |
377 | | |
378 | 134k | PropertyAttribute attr = |
379 | 134k | static_cast<PropertyAttribute>(ReadOnly | DontDelete); |
380 | | |
381 | 134k | target->DefineOwnProperty(context, env->constants_string(), constants, attr) |
382 | 134k | .ToChecked(); |
383 | 134k | } |
384 | | |
385 | 0 | void RegisterExternalReferences(ExternalReferenceRegistry* registry) { |
386 | 0 | registry->Register(SetupPerformanceObservers); |
387 | 0 | registry->Register(InstallGarbageCollectionTracking); |
388 | 0 | registry->Register(RemoveGarbageCollectionTracking); |
389 | 0 | registry->Register(Notify); |
390 | 0 | registry->Register(LoopIdleTime); |
391 | 0 | registry->Register(CreateELDHistogram); |
392 | 0 | registry->Register(MarkBootstrapComplete); |
393 | 0 | registry->Register(SlowPerformanceNow); |
394 | 0 | registry->Register(FastPerformanceNow); |
395 | 0 | registry->Register(fast_performance_now.GetTypeInfo()); |
396 | 0 | HistogramBase::RegisterExternalReferences(registry); |
397 | 0 | IntervalHistogram::RegisterExternalReferences(registry); |
398 | 0 | } |
399 | | } // namespace performance |
400 | | } // namespace node |
401 | | |
402 | | NODE_BINDING_CONTEXT_AWARE_INTERNAL( |
403 | | performance, node::performance::CreatePerContextProperties) |
404 | | NODE_BINDING_PER_ISOLATE_INIT(performance, |
405 | | node::performance::CreatePerIsolateProperties) |
406 | | NODE_BINDING_EXTERNAL_REFERENCE(performance, |
407 | | node::performance::RegisterExternalReferences) |