1 // Copyright 2014 the V8 project authors. All rights reserved.
2 // Use of this source code is governed by a BSD-style license that can be
3 // found in the LICENSE file.
4
5 #ifndef V8_HEAP_GC_TRACER_H_
6 #define V8_HEAP_GC_TRACER_H_
7
8 #include "src/base/compiler-specific.h"
9 #include "src/base/platform/platform.h"
10 #include "src/base/ring-buffer.h"
11 #include "src/common/globals.h"
12 #include "src/heap/heap.h"
13 #include "src/init/heap-symbols.h"
14 #include "src/logging/counters.h"
15 #include "testing/gtest/include/gtest/gtest_prod.h" // nogncheck
16
17 namespace v8 {
18 namespace internal {
19
20 using BytesAndDuration = std::pair<uint64_t, double>;
21
MakeBytesAndDuration(uint64_t bytes,double duration)22 inline BytesAndDuration MakeBytesAndDuration(uint64_t bytes, double duration) {
23 return std::make_pair(bytes, duration);
24 }
25
26 enum ScavengeSpeedMode { kForAllObjects, kForSurvivedObjects };
27
28 #define TRACE_GC_CATEGORIES \
29 "devtools.timeline," TRACE_DISABLED_BY_DEFAULT("v8.gc")
30
31 #define TRACE_GC(tracer, scope_id) \
32 GCTracer::Scope::ScopeId gc_tracer_scope_id(scope_id); \
33 GCTracer::Scope gc_tracer_scope(tracer, gc_tracer_scope_id); \
34 TRACE_EVENT0(TRACE_GC_CATEGORIES, GCTracer::Scope::Name(gc_tracer_scope_id))
35
36 #define TRACE_BACKGROUND_GC(tracer, scope_id) \
37 WorkerThreadRuntimeCallStatsScope runtime_call_stats_scope( \
38 tracer->worker_thread_runtime_call_stats()); \
39 GCTracer::BackgroundScope background_scope(tracer, scope_id, \
40 runtime_call_stats_scope.Get()); \
41 TRACE_EVENT0(TRACE_GC_CATEGORIES, GCTracer::BackgroundScope::Name(scope_id))
42
43 // GCTracer collects and prints ONE line after each garbage collector
44 // invocation IFF --trace_gc is used.
45 class V8_EXPORT_PRIVATE GCTracer {
46 public:
47 struct IncrementalMarkingInfos {
IncrementalMarkingInfosIncrementalMarkingInfos48 IncrementalMarkingInfos() : duration(0), longest_step(0), steps(0) {}
49
UpdateIncrementalMarkingInfos50 void Update(double duration) {
51 steps++;
52 this->duration += duration;
53 if (duration > longest_step) {
54 longest_step = duration;
55 }
56 }
57
ResetCurrentCycleIncrementalMarkingInfos58 void ResetCurrentCycle() {
59 duration = 0;
60 longest_step = 0;
61 steps = 0;
62 }
63
64 double duration;
65 double longest_step;
66 int steps;
67 };
68
69 class Scope {
70 public:
71 enum ScopeId {
72 #define DEFINE_SCOPE(scope) scope,
73 TRACER_SCOPES(DEFINE_SCOPE) TRACER_BACKGROUND_SCOPES(DEFINE_SCOPE)
74 #undef DEFINE_SCOPE
75 NUMBER_OF_SCOPES,
76
77 FIRST_INCREMENTAL_SCOPE = MC_INCREMENTAL,
78 LAST_INCREMENTAL_SCOPE = MC_INCREMENTAL_SWEEPING,
79 FIRST_SCOPE = MC_INCREMENTAL,
80 NUMBER_OF_INCREMENTAL_SCOPES =
81 LAST_INCREMENTAL_SCOPE - FIRST_INCREMENTAL_SCOPE + 1,
82 FIRST_GENERAL_BACKGROUND_SCOPE = BACKGROUND_ARRAY_BUFFER_FREE,
83 LAST_GENERAL_BACKGROUND_SCOPE = BACKGROUND_UNMAPPER,
84 FIRST_MC_BACKGROUND_SCOPE = MC_BACKGROUND_EVACUATE_COPY,
85 LAST_MC_BACKGROUND_SCOPE = MC_BACKGROUND_SWEEPING,
86 FIRST_TOP_MC_SCOPE = MC_CLEAR,
87 LAST_TOP_MC_SCOPE = MC_SWEEP,
88 FIRST_MINOR_GC_BACKGROUND_SCOPE = MINOR_MC_BACKGROUND_EVACUATE_COPY,
89 LAST_MINOR_GC_BACKGROUND_SCOPE = SCAVENGER_BACKGROUND_SCAVENGE_PARALLEL,
90 FIRST_BACKGROUND_SCOPE = FIRST_GENERAL_BACKGROUND_SCOPE
91 };
92
93 Scope(GCTracer* tracer, ScopeId scope);
94 ~Scope();
95 static const char* Name(ScopeId id);
96
97 private:
98 GCTracer* tracer_;
99 ScopeId scope_;
100 double start_time_;
101 RuntimeCallTimer timer_;
102 RuntimeCallStats* runtime_stats_ = nullptr;
103
104 DISALLOW_COPY_AND_ASSIGN(Scope);
105 };
106
107 class V8_EXPORT_PRIVATE BackgroundScope {
108 public:
109 enum ScopeId {
110 #define DEFINE_SCOPE(scope) scope,
111 TRACER_BACKGROUND_SCOPES(DEFINE_SCOPE)
112 #undef DEFINE_SCOPE
113 NUMBER_OF_SCOPES,
114 FIRST_GENERAL_BACKGROUND_SCOPE = BACKGROUND_ARRAY_BUFFER_FREE,
115 LAST_GENERAL_BACKGROUND_SCOPE = BACKGROUND_UNMAPPER,
116 FIRST_MC_BACKGROUND_SCOPE = MC_BACKGROUND_EVACUATE_COPY,
117 LAST_MC_BACKGROUND_SCOPE = MC_BACKGROUND_SWEEPING,
118 FIRST_MINOR_GC_BACKGROUND_SCOPE = MINOR_MC_BACKGROUND_EVACUATE_COPY,
119 LAST_MINOR_GC_BACKGROUND_SCOPE = SCAVENGER_BACKGROUND_SCAVENGE_PARALLEL
120 };
121 BackgroundScope(GCTracer* tracer, ScopeId scope,
122 RuntimeCallStats* runtime_stats);
123 ~BackgroundScope();
124
125 static const char* Name(ScopeId id);
126
127 private:
128 GCTracer* tracer_;
129 ScopeId scope_;
130 double start_time_;
131 RuntimeCallTimer timer_;
132 RuntimeCallStats* runtime_stats_;
133 DISALLOW_COPY_AND_ASSIGN(BackgroundScope);
134 };
135
136 class Event {
137 public:
138 enum Type {
139 SCAVENGER = 0,
140 MARK_COMPACTOR = 1,
141 INCREMENTAL_MARK_COMPACTOR = 2,
142 MINOR_MARK_COMPACTOR = 3,
143 START = 4
144 };
145
146 Event(Type type, GarbageCollectionReason gc_reason,
147 const char* collector_reason);
148
149 // Returns a string describing the event type.
150 const char* TypeName(bool short_name) const;
151
152 // Type of event
153 Type type;
154
155 GarbageCollectionReason gc_reason;
156 const char* collector_reason;
157
158 // Timestamp set in the constructor.
159 double start_time;
160
161 // Timestamp set in the destructor.
162 double end_time;
163
164 // Memory reduction flag set.
165 bool reduce_memory;
166
167 // Size of objects in heap set in constructor.
168 size_t start_object_size;
169
170 // Size of objects in heap set in destructor.
171 size_t end_object_size;
172
173 // Size of memory allocated from OS set in constructor.
174 size_t start_memory_size;
175
176 // Size of memory allocated from OS set in destructor.
177 size_t end_memory_size;
178
179 // Total amount of space either wasted or contained in one of free lists
180 // before the current GC.
181 size_t start_holes_size;
182
183 // Total amount of space either wasted or contained in one of free lists
184 // after the current GC.
185 size_t end_holes_size;
186
187 // Size of young objects in constructor.
188 size_t young_object_size;
189
190 // Size of survived young objects in destructor.
191 size_t survived_young_object_size;
192
193 // Bytes marked incrementally for INCREMENTAL_MARK_COMPACTOR
194 size_t incremental_marking_bytes;
195
196 // Duration of incremental marking steps for INCREMENTAL_MARK_COMPACTOR.
197 double incremental_marking_duration;
198
199 // Amounts of time spent in different scopes during GC.
200 double scopes[Scope::NUMBER_OF_SCOPES];
201
202 // Holds details for incremental marking scopes.
203 IncrementalMarkingInfos
204 incremental_marking_scopes[Scope::NUMBER_OF_INCREMENTAL_SCOPES];
205 };
206
207 static const int kThroughputTimeFrameMs = 5000;
208 static constexpr double kConservativeSpeedInBytesPerMillisecond = 128 * KB;
209
210 static double CombineSpeedsInBytesPerMillisecond(double default_speed,
211 double optional_speed);
212
213 static RuntimeCallCounterId RCSCounterFromScope(Scope::ScopeId id);
214 static RuntimeCallCounterId RCSCounterFromBackgroundScope(
215 BackgroundScope::ScopeId id);
216
217 explicit GCTracer(Heap* heap);
218
219 // Start collecting data.
220 void Start(GarbageCollector collector, GarbageCollectionReason gc_reason,
221 const char* collector_reason);
222 void StartInSafepoint();
223
224 // Stop collecting data and print results.
225 void Stop(GarbageCollector collector);
226 void StopInSafepoint();
227
228 void NotifySweepingCompleted();
229
230 void NotifyYoungGenerationHandling(
231 YoungGenerationHandling young_generation_handling);
232
233 // Sample and accumulate bytes allocated since the last GC.
234 void SampleAllocation(double current_ms, size_t new_space_counter_bytes,
235 size_t old_generation_counter_bytes,
236 size_t embedder_counter_bytes);
237
238 // Log the accumulated new space allocation bytes.
239 void AddAllocation(double current_ms);
240
241 void AddContextDisposalTime(double time);
242
243 void AddCompactionEvent(double duration, size_t live_bytes_compacted);
244
245 void AddSurvivalRatio(double survival_ratio);
246
247 // Log an incremental marking step.
248 void AddIncrementalMarkingStep(double duration, size_t bytes);
249
250 // Compute the average incremental marking speed in bytes/millisecond.
251 // Returns a conservative value if no events have been recorded.
252 double IncrementalMarkingSpeedInBytesPerMillisecond() const;
253
254 // Compute the average embedder speed in bytes/millisecond.
255 // Returns a conservative value if no events have been recorded.
256 double EmbedderSpeedInBytesPerMillisecond() const;
257
258 // Compute the average scavenge speed in bytes/millisecond.
259 // Returns 0 if no events have been recorded.
260 double ScavengeSpeedInBytesPerMillisecond(
261 ScavengeSpeedMode mode = kForAllObjects) const;
262
263 // Compute the average compaction speed in bytes/millisecond.
264 // Returns 0 if not enough events have been recorded.
265 double CompactionSpeedInBytesPerMillisecond() const;
266
267 // Compute the average mark-sweep speed in bytes/millisecond.
268 // Returns 0 if no events have been recorded.
269 double MarkCompactSpeedInBytesPerMillisecond() const;
270
271 // Compute the average incremental mark-sweep finalize speed in
272 // bytes/millisecond.
273 // Returns 0 if no events have been recorded.
274 double FinalIncrementalMarkCompactSpeedInBytesPerMillisecond() const;
275
276 // Compute the overall mark compact speed including incremental steps
277 // and the final mark-compact step.
278 double CombinedMarkCompactSpeedInBytesPerMillisecond();
279
280 // Allocation throughput in the new space in bytes/millisecond.
281 // Returns 0 if no allocation events have been recorded.
282 double NewSpaceAllocationThroughputInBytesPerMillisecond(
283 double time_ms = 0) const;
284
285 // Allocation throughput in the old generation in bytes/millisecond in the
286 // last time_ms milliseconds.
287 // Returns 0 if no allocation events have been recorded.
288 double OldGenerationAllocationThroughputInBytesPerMillisecond(
289 double time_ms = 0) const;
290
291 // Allocation throughput in the embedder in bytes/millisecond in the
292 // last time_ms milliseconds. Reported through v8::EmbedderHeapTracer.
293 // Returns 0 if no allocation events have been recorded.
294 double EmbedderAllocationThroughputInBytesPerMillisecond(
295 double time_ms = 0) const;
296
297 // Allocation throughput in heap in bytes/millisecond in the last time_ms
298 // milliseconds.
299 // Returns 0 if no allocation events have been recorded.
300 double AllocationThroughputInBytesPerMillisecond(double time_ms) const;
301
302 // Allocation throughput in heap in bytes/milliseconds in the last
303 // kThroughputTimeFrameMs seconds.
304 // Returns 0 if no allocation events have been recorded.
305 double CurrentAllocationThroughputInBytesPerMillisecond() const;
306
307 // Allocation throughput in old generation in bytes/milliseconds in the last
308 // kThroughputTimeFrameMs seconds.
309 // Returns 0 if no allocation events have been recorded.
310 double CurrentOldGenerationAllocationThroughputInBytesPerMillisecond() const;
311
312 // Allocation throughput in the embedder in bytes/milliseconds in the last
313 // kThroughputTimeFrameMs seconds. Reported through v8::EmbedderHeapTracer.
314 // Returns 0 if no allocation events have been recorded.
315 double CurrentEmbedderAllocationThroughputInBytesPerMillisecond() const;
316
317 // Computes the context disposal rate in milliseconds. It takes the time
318 // frame of the first recorded context disposal to the current time and
319 // divides it by the number of recorded events.
320 // Returns 0 if no events have been recorded.
321 double ContextDisposalRateInMilliseconds() const;
322
323 // Computes the average survival ratio based on the last recorded survival
324 // events.
325 // Returns 0 if no events have been recorded.
326 double AverageSurvivalRatio() const;
327
328 // Returns true if at least one survival event was recorded.
329 bool SurvivalEventsRecorded() const;
330
331 // Discard all recorded survival events.
332 void ResetSurvivalEvents();
333
334 void NotifyIncrementalMarkingStart();
335
336 // Returns average mutator utilization with respect to mark-compact
337 // garbage collections. This ignores scavenger.
338 double AverageMarkCompactMutatorUtilization() const;
339 double CurrentMarkCompactMutatorUtilization() const;
340
AddScopeSample(Scope::ScopeId scope,double duration)341 V8_INLINE void AddScopeSample(Scope::ScopeId scope, double duration) {
342 DCHECK(scope < Scope::NUMBER_OF_SCOPES);
343 if (scope >= Scope::FIRST_INCREMENTAL_SCOPE &&
344 scope <= Scope::LAST_INCREMENTAL_SCOPE) {
345 incremental_marking_scopes_[scope - Scope::FIRST_INCREMENTAL_SCOPE]
346 .Update(duration);
347 } else {
348 current_.scopes[scope] += duration;
349 }
350 }
351
352 void AddBackgroundScopeSample(BackgroundScope::ScopeId scope,
353 double duration);
354
355 void RecordGCPhasesHistograms(TimedHistogram* gc_timer);
356
357 void RecordEmbedderSpeed(size_t bytes, double duration);
358
359 // Returns the average time between scheduling and invocation of an
360 // incremental marking task.
361 double AverageTimeToIncrementalMarkingTask() const;
362 void RecordTimeToIncrementalMarkingTask(double time_to_task);
363
364 WorkerThreadRuntimeCallStats* worker_thread_runtime_call_stats();
365
366 private:
367 FRIEND_TEST(GCTracer, AverageSpeed);
368 FRIEND_TEST(GCTracerTest, AllocationThroughput);
369 FRIEND_TEST(GCTracerTest, BackgroundScavengerScope);
370 FRIEND_TEST(GCTracerTest, BackgroundMinorMCScope);
371 FRIEND_TEST(GCTracerTest, BackgroundMajorMCScope);
372 FRIEND_TEST(GCTracerTest, EmbedderAllocationThroughput);
373 FRIEND_TEST(GCTracerTest, MultithreadedBackgroundScope);
374 FRIEND_TEST(GCTracerTest, NewSpaceAllocationThroughput);
375 FRIEND_TEST(GCTracerTest, PerGenerationAllocationThroughput);
376 FRIEND_TEST(GCTracerTest, PerGenerationAllocationThroughputWithProvidedTime);
377 FRIEND_TEST(GCTracerTest, RegularScope);
378 FRIEND_TEST(GCTracerTest, IncrementalMarkingDetails);
379 FRIEND_TEST(GCTracerTest, IncrementalScope);
380 FRIEND_TEST(GCTracerTest, IncrementalMarkingSpeed);
381 FRIEND_TEST(GCTracerTest, MutatorUtilization);
382 FRIEND_TEST(GCTracerTest, RecordGCSumHistograms);
383 FRIEND_TEST(GCTracerTest, RecordMarkCompactHistograms);
384 FRIEND_TEST(GCTracerTest, RecordScavengerHistograms);
385
386 struct BackgroundCounter {
387 double total_duration_ms;
388 };
389
390 // Returns the average speed of the events in the buffer.
391 // If the buffer is empty, the result is 0.
392 // Otherwise, the result is between 1 byte/ms and 1 GB/ms.
393 static double AverageSpeed(const base::RingBuffer<BytesAndDuration>& buffer);
394 static double AverageSpeed(const base::RingBuffer<BytesAndDuration>& buffer,
395 const BytesAndDuration& initial, double time_ms);
396
397 void ResetForTesting();
398 void ResetIncrementalMarkingCounters();
399 void RecordIncrementalMarkingSpeed(size_t bytes, double duration);
400 void RecordMutatorUtilization(double mark_compactor_end_time,
401 double mark_compactor_duration);
402
403 // Overall time spent in mark compact within a given GC cycle. Exact
404 // accounting of events within a GC is not necessary which is why the
405 // recording takes place at the end of the atomic pause.
406 void RecordGCSumCounters(double atomic_pause_duration);
407
408 // Print one detailed trace line in name=value format.
409 // TODO(ernstm): Move to Heap.
410 void PrintNVP() const;
411
412 // Print one trace line.
413 // TODO(ernstm): Move to Heap.
414 void Print() const;
415
416 // Prints a line and also adds it to the heap's ring buffer so that
417 // it can be included in later crash dumps.
418 void PRINTF_FORMAT(2, 3) Output(const char* format, ...) const;
419
TotalExternalTime()420 double TotalExternalTime() const {
421 return current_.scopes[Scope::HEAP_EXTERNAL_WEAK_GLOBAL_HANDLES] +
422 current_.scopes[Scope::HEAP_EXTERNAL_EPILOGUE] +
423 current_.scopes[Scope::HEAP_EXTERNAL_PROLOGUE] +
424 current_.scopes[Scope::MC_INCREMENTAL_EXTERNAL_EPILOGUE] +
425 current_.scopes[Scope::MC_INCREMENTAL_EXTERNAL_PROLOGUE];
426 }
427
428 void FetchBackgroundCounters(int first_global_scope, int last_global_scope,
429 int first_background_scope,
430 int last_background_scope);
431 void FetchBackgroundMinorGCCounters();
432 void FetchBackgroundMarkCompactCounters();
433 void FetchBackgroundGeneralCounters();
434
435 // Pointer to the heap that owns this tracer.
436 Heap* heap_;
437
438 // Current tracer event. Populated during Start/Stop cycle. Valid after Stop()
439 // has returned.
440 Event current_;
441
442 // Previous tracer event.
443 Event previous_;
444
445 // Size of incremental marking steps (in bytes) accumulated since the end of
446 // the last mark compact GC.
447 size_t incremental_marking_bytes_;
448
449 // Duration of incremental marking steps since the end of the last mark-
450 // compact event.
451 double incremental_marking_duration_;
452
453 double incremental_marking_start_time_;
454
455 double recorded_incremental_marking_speed_;
456
457 double average_time_to_incremental_marking_task_ = 0.0;
458
459 double recorded_embedder_speed_ = 0.0;
460
461 // Incremental scopes carry more information than just the duration. The infos
462 // here are merged back upon starting/stopping the GC tracer.
463 IncrementalMarkingInfos
464 incremental_marking_scopes_[Scope::NUMBER_OF_INCREMENTAL_SCOPES];
465
466
467 // Timestamp and allocation counter at the last sampled allocation event.
468 double allocation_time_ms_;
469 size_t new_space_allocation_counter_bytes_;
470 size_t old_generation_allocation_counter_bytes_;
471 size_t embedder_allocation_counter_bytes_;
472
473 // Accumulated duration and allocated bytes since the last GC.
474 double allocation_duration_since_gc_;
475 size_t new_space_allocation_in_bytes_since_gc_;
476 size_t old_generation_allocation_in_bytes_since_gc_;
477 size_t embedder_allocation_in_bytes_since_gc_;
478
479 double combined_mark_compact_speed_cache_;
480
481 // Counts how many tracers were started without stopping.
482 int start_counter_;
483
484 // Used for computing average mutator utilization.
485 double average_mutator_duration_;
486 double average_mark_compact_duration_;
487 double current_mark_compact_mutator_utilization_;
488 double previous_mark_compact_end_time_;
489
490 base::RingBuffer<BytesAndDuration> recorded_minor_gcs_total_;
491 base::RingBuffer<BytesAndDuration> recorded_minor_gcs_survived_;
492 base::RingBuffer<BytesAndDuration> recorded_compactions_;
493 base::RingBuffer<BytesAndDuration> recorded_incremental_mark_compacts_;
494 base::RingBuffer<BytesAndDuration> recorded_mark_compacts_;
495 base::RingBuffer<BytesAndDuration> recorded_new_generation_allocations_;
496 base::RingBuffer<BytesAndDuration> recorded_old_generation_allocations_;
497 base::RingBuffer<BytesAndDuration> recorded_embedder_generation_allocations_;
498 base::RingBuffer<double> recorded_context_disposal_times_;
499 base::RingBuffer<double> recorded_survival_ratios_;
500
501 base::Mutex background_counter_mutex_;
502 BackgroundCounter background_counter_[BackgroundScope::NUMBER_OF_SCOPES];
503
504 DISALLOW_COPY_AND_ASSIGN(GCTracer);
505 };
506
507 } // namespace internal
508 } // namespace v8
509
510 #endif // V8_HEAP_GC_TRACER_H_
511