• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
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