Home | History | Annotate | Download | only in heap
      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/counters.h"
     11 #include "src/globals.h"
     12 
     13 namespace v8 {
     14 namespace internal {
     15 
     16 template <typename T>
     17 class RingBuffer {
     18  public:
     19   RingBuffer() { Reset(); }
     20   static const int kSize = 10;
     21   void Push(const T& value) {
     22     if (count_ == kSize) {
     23       elements_[start_++] = value;
     24       if (start_ == kSize) start_ = 0;
     25     } else {
     26       DCHECK_EQ(start_, 0);
     27       elements_[count_++] = value;
     28     }
     29   }
     30 
     31   int Count() const { return count_; }
     32 
     33   template <typename Callback>
     34   T Sum(Callback callback, const T& initial) const {
     35     int j = start_ + count_ - 1;
     36     if (j >= kSize) j -= kSize;
     37     T result = initial;
     38     for (int i = 0; i < count_; i++) {
     39       result = callback(result, elements_[j]);
     40       if (--j == -1) j += kSize;
     41     }
     42     return result;
     43   }
     44 
     45   void Reset() { start_ = count_ = 0; }
     46 
     47  private:
     48   T elements_[kSize];
     49   int start_;
     50   int count_;
     51   DISALLOW_COPY_AND_ASSIGN(RingBuffer);
     52 };
     53 
     54 typedef std::pair<uint64_t, double> BytesAndDuration;
     55 
     56 inline BytesAndDuration MakeBytesAndDuration(uint64_t bytes, double duration) {
     57   return std::make_pair(bytes, duration);
     58 }
     59 
     60 enum ScavengeSpeedMode { kForAllObjects, kForSurvivedObjects };
     61 
     62 #define TRACER_SCOPES(F)                           \
     63   F(EXTERNAL_WEAK_GLOBAL_HANDLES)                  \
     64   F(MC_CLEAR)                                      \
     65   F(MC_CLEAR_CODE_FLUSH)                           \
     66   F(MC_CLEAR_DEPENDENT_CODE)                       \
     67   F(MC_CLEAR_GLOBAL_HANDLES)                       \
     68   F(MC_CLEAR_MAPS)                                 \
     69   F(MC_CLEAR_SLOTS_BUFFER)                         \
     70   F(MC_CLEAR_STORE_BUFFER)                         \
     71   F(MC_CLEAR_STRING_TABLE)                         \
     72   F(MC_CLEAR_WEAK_CELLS)                           \
     73   F(MC_CLEAR_WEAK_COLLECTIONS)                     \
     74   F(MC_CLEAR_WEAK_LISTS)                           \
     75   F(MC_EVACUATE)                                   \
     76   F(MC_EVACUATE_CANDIDATES)                        \
     77   F(MC_EVACUATE_CLEAN_UP)                          \
     78   F(MC_EVACUATE_COPY)                              \
     79   F(MC_EVACUATE_UPDATE_POINTERS)                   \
     80   F(MC_EVACUATE_UPDATE_POINTERS_TO_EVACUATED)      \
     81   F(MC_EVACUATE_UPDATE_POINTERS_TO_NEW)            \
     82   F(MC_EVACUATE_UPDATE_POINTERS_WEAK)              \
     83   F(MC_EXTERNAL_EPILOGUE)                          \
     84   F(MC_EXTERNAL_PROLOGUE)                          \
     85   F(MC_FINISH)                                     \
     86   F(MC_INCREMENTAL_FINALIZE)                       \
     87   F(MC_INCREMENTAL_EXTERNAL_EPILOGUE)              \
     88   F(MC_INCREMENTAL_EXTERNAL_PROLOGUE)              \
     89   F(MC_MARK)                                       \
     90   F(MC_MARK_FINISH_INCREMENTAL)                    \
     91   F(MC_MARK_PREPARE_CODE_FLUSH)                    \
     92   F(MC_MARK_ROOTS)                                 \
     93   F(MC_MARK_WEAK_CLOSURE)                          \
     94   F(MC_MARK_WEAK_CLOSURE_EPHEMERAL)                \
     95   F(MC_MARK_WEAK_CLOSURE_WEAK_HANDLES)             \
     96   F(MC_MARK_WEAK_CLOSURE_WEAK_ROOTS)               \
     97   F(MC_MARK_WEAK_CLOSURE_HARMONY)                  \
     98   F(MC_SWEEP)                                      \
     99   F(MC_SWEEP_CODE)                                 \
    100   F(MC_SWEEP_MAP)                                  \
    101   F(MC_SWEEP_OLD)                                  \
    102   F(SCAVENGER_CODE_FLUSH_CANDIDATES)               \
    103   F(SCAVENGER_EXTERNAL_EPILOGUE)                   \
    104   F(SCAVENGER_EXTERNAL_PROLOGUE)                   \
    105   F(SCAVENGER_OBJECT_GROUPS)                       \
    106   F(SCAVENGER_OLD_TO_NEW_POINTERS)                 \
    107   F(SCAVENGER_ROOTS)                               \
    108   F(SCAVENGER_SCAVENGE)                            \
    109   F(SCAVENGER_SEMISPACE)                           \
    110   F(SCAVENGER_WEAK)
    111 
    112 #define TRACE_GC(tracer, scope_id)                             \
    113   GCTracer::Scope::ScopeId gc_tracer_scope_id(scope_id);       \
    114   GCTracer::Scope gc_tracer_scope(tracer, gc_tracer_scope_id); \
    115   TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("v8.gc"),             \
    116                GCTracer::Scope::Name(gc_tracer_scope_id))
    117 
    118 // GCTracer collects and prints ONE line after each garbage collector
    119 // invocation IFF --trace_gc is used.
    120 // TODO(ernstm): Unit tests.
    121 class GCTracer {
    122  public:
    123   class Scope {
    124    public:
    125     enum ScopeId {
    126 #define DEFINE_SCOPE(scope) scope,
    127       TRACER_SCOPES(DEFINE_SCOPE)
    128 #undef DEFINE_SCOPE
    129           NUMBER_OF_SCOPES
    130     };
    131 
    132     Scope(GCTracer* tracer, ScopeId scope);
    133     ~Scope();
    134     static const char* Name(ScopeId id);
    135 
    136    private:
    137     GCTracer* tracer_;
    138     ScopeId scope_;
    139     double start_time_;
    140     RuntimeCallTimer timer_;
    141 
    142     DISALLOW_COPY_AND_ASSIGN(Scope);
    143   };
    144 
    145 
    146   class Event {
    147    public:
    148     enum Type {
    149       SCAVENGER = 0,
    150       MARK_COMPACTOR = 1,
    151       INCREMENTAL_MARK_COMPACTOR = 2,
    152       START = 3
    153     };
    154 
    155     // Default constructor leaves the event uninitialized.
    156     Event() {}
    157 
    158     Event(Type type, const char* gc_reason, const char* collector_reason);
    159 
    160     // Returns a string describing the event type.
    161     const char* TypeName(bool short_name) const;
    162 
    163     // Type of event
    164     Type type;
    165 
    166     const char* gc_reason;
    167     const char* collector_reason;
    168 
    169     // Timestamp set in the constructor.
    170     double start_time;
    171 
    172     // Timestamp set in the destructor.
    173     double end_time;
    174 
    175     // Memory reduction flag set.
    176     bool reduce_memory;
    177 
    178     // Size of objects in heap set in constructor.
    179     intptr_t start_object_size;
    180 
    181     // Size of objects in heap set in destructor.
    182     intptr_t end_object_size;
    183 
    184     // Size of memory allocated from OS set in constructor.
    185     intptr_t start_memory_size;
    186 
    187     // Size of memory allocated from OS set in destructor.
    188     intptr_t end_memory_size;
    189 
    190     // Total amount of space either wasted or contained in one of free lists
    191     // before the current GC.
    192     intptr_t start_holes_size;
    193 
    194     // Total amount of space either wasted or contained in one of free lists
    195     // after the current GC.
    196     intptr_t end_holes_size;
    197 
    198     // Size of new space objects in constructor.
    199     intptr_t new_space_object_size;
    200     // Size of survived new space objects in desctructor.
    201     intptr_t survived_new_space_object_size;
    202 
    203     // Number of incremental marking steps since creation of tracer.
    204     // (value at start of event)
    205     int cumulative_incremental_marking_steps;
    206 
    207     // Incremental marking steps since
    208     // - last event for SCAVENGER events
    209     // - last INCREMENTAL_MARK_COMPACTOR event for INCREMENTAL_MARK_COMPACTOR
    210     // events
    211     int incremental_marking_steps;
    212 
    213     // Bytes marked since creation of tracer (value at start of event).
    214     intptr_t cumulative_incremental_marking_bytes;
    215 
    216     // Bytes marked since
    217     // - last event for SCAVENGER events
    218     // - last INCREMENTAL_MARK_COMPACTOR event for INCREMENTAL_MARK_COMPACTOR
    219     // events
    220     intptr_t incremental_marking_bytes;
    221 
    222     // Cumulative duration of incremental marking steps since creation of
    223     // tracer. (value at start of event)
    224     double cumulative_incremental_marking_duration;
    225 
    226     // Duration of incremental marking steps since
    227     // - last event for SCAVENGER events
    228     // - last INCREMENTAL_MARK_COMPACTOR event for INCREMENTAL_MARK_COMPACTOR
    229     // events
    230     double incremental_marking_duration;
    231 
    232     // Cumulative pure duration of incremental marking steps since creation of
    233     // tracer. (value at start of event)
    234     double cumulative_pure_incremental_marking_duration;
    235 
    236     // Duration of pure incremental marking steps since
    237     // - last event for SCAVENGER events
    238     // - last INCREMENTAL_MARK_COMPACTOR event for INCREMENTAL_MARK_COMPACTOR
    239     // events
    240     double pure_incremental_marking_duration;
    241 
    242     // Longest incremental marking step since start of marking.
    243     // (value at start of event)
    244     double longest_incremental_marking_step;
    245 
    246     // Amounts of time spent in different scopes during GC.
    247     double scopes[Scope::NUMBER_OF_SCOPES];
    248   };
    249 
    250   static const int kThroughputTimeFrameMs = 5000;
    251 
    252   explicit GCTracer(Heap* heap);
    253 
    254   // Start collecting data.
    255   void Start(GarbageCollector collector, const char* gc_reason,
    256              const char* collector_reason);
    257 
    258   // Stop collecting data and print results.
    259   void Stop(GarbageCollector collector);
    260 
    261   // Sample and accumulate bytes allocated since the last GC.
    262   void SampleAllocation(double current_ms, size_t new_space_counter_bytes,
    263                         size_t old_generation_counter_bytes);
    264 
    265   // Log the accumulated new space allocation bytes.
    266   void AddAllocation(double current_ms);
    267 
    268   void AddContextDisposalTime(double time);
    269 
    270   void AddCompactionEvent(double duration, intptr_t live_bytes_compacted);
    271 
    272   void AddSurvivalRatio(double survival_ratio);
    273 
    274   // Log an incremental marking step.
    275   void AddIncrementalMarkingStep(double duration, intptr_t bytes);
    276 
    277   void AddIncrementalMarkingFinalizationStep(double duration);
    278 
    279   // Log time spent in marking.
    280   void AddMarkingTime(double duration) {
    281     cumulative_marking_duration_ += duration;
    282   }
    283 
    284   // Time spent in marking.
    285   double cumulative_marking_duration() const {
    286     return cumulative_marking_duration_;
    287   }
    288 
    289   // Log time spent in sweeping on main thread.
    290   void AddSweepingTime(double duration) {
    291     cumulative_sweeping_duration_ += duration;
    292   }
    293 
    294   // Time spent in sweeping on main thread.
    295   double cumulative_sweeping_duration() const {
    296     return cumulative_sweeping_duration_;
    297   }
    298 
    299   // Compute the average incremental marking speed in bytes/millisecond.
    300   // Returns 0 if no events have been recorded.
    301   double IncrementalMarkingSpeedInBytesPerMillisecond() const;
    302 
    303   // Compute the average scavenge speed in bytes/millisecond.
    304   // Returns 0 if no events have been recorded.
    305   double ScavengeSpeedInBytesPerMillisecond(
    306       ScavengeSpeedMode mode = kForAllObjects) const;
    307 
    308   // Compute the average compaction speed in bytes/millisecond.
    309   // Returns 0 if not enough events have been recorded.
    310   double CompactionSpeedInBytesPerMillisecond() const;
    311 
    312   // Compute the average mark-sweep speed in bytes/millisecond.
    313   // Returns 0 if no events have been recorded.
    314   double MarkCompactSpeedInBytesPerMillisecond() const;
    315 
    316   // Compute the average incremental mark-sweep finalize speed in
    317   // bytes/millisecond.
    318   // Returns 0 if no events have been recorded.
    319   double FinalIncrementalMarkCompactSpeedInBytesPerMillisecond() const;
    320 
    321   // Compute the overall mark compact speed including incremental steps
    322   // and the final mark-compact step.
    323   double CombinedMarkCompactSpeedInBytesPerMillisecond();
    324 
    325   // Allocation throughput in the new space in bytes/millisecond.
    326   // Returns 0 if no allocation events have been recorded.
    327   double NewSpaceAllocationThroughputInBytesPerMillisecond(
    328       double time_ms = 0) const;
    329 
    330   // Allocation throughput in the old generation in bytes/millisecond in the
    331   // last time_ms milliseconds.
    332   // Returns 0 if no allocation events have been recorded.
    333   double OldGenerationAllocationThroughputInBytesPerMillisecond(
    334       double time_ms = 0) const;
    335 
    336   // Allocation throughput in heap in bytes/millisecond in the last time_ms
    337   // milliseconds.
    338   // Returns 0 if no allocation events have been recorded.
    339   double AllocationThroughputInBytesPerMillisecond(double time_ms) const;
    340 
    341   // Allocation throughput in heap in bytes/milliseconds in the last
    342   // kThroughputTimeFrameMs seconds.
    343   // Returns 0 if no allocation events have been recorded.
    344   double CurrentAllocationThroughputInBytesPerMillisecond() const;
    345 
    346   // Allocation throughput in old generation in bytes/milliseconds in the last
    347   // kThroughputTimeFrameMs seconds.
    348   // Returns 0 if no allocation events have been recorded.
    349   double CurrentOldGenerationAllocationThroughputInBytesPerMillisecond() const;
    350 
    351   // Computes the context disposal rate in milliseconds. It takes the time
    352   // frame of the first recorded context disposal to the current time and
    353   // divides it by the number of recorded events.
    354   // Returns 0 if no events have been recorded.
    355   double ContextDisposalRateInMilliseconds() const;
    356 
    357   // Computes the average survival ratio based on the last recorded survival
    358   // events.
    359   // Returns 0 if no events have been recorded.
    360   double AverageSurvivalRatio() const;
    361 
    362   // Returns true if at least one survival event was recorded.
    363   bool SurvivalEventsRecorded() const;
    364 
    365   // Discard all recorded survival events.
    366   void ResetSurvivalEvents();
    367 
    368   // Returns the average speed of the events in the buffer.
    369   // If the buffer is empty, the result is 0.
    370   // Otherwise, the result is between 1 byte/ms and 1 GB/ms.
    371   static double AverageSpeed(const RingBuffer<BytesAndDuration>& buffer);
    372   static double AverageSpeed(const RingBuffer<BytesAndDuration>& buffer,
    373                              const BytesAndDuration& initial, double time_ms);
    374 
    375   void ResetForTesting();
    376 
    377  private:
    378   // Print one detailed trace line in name=value format.
    379   // TODO(ernstm): Move to Heap.
    380   void PrintNVP() const;
    381 
    382   // Print one trace line.
    383   // TODO(ernstm): Move to Heap.
    384   void Print() const;
    385 
    386   // Prints a line and also adds it to the heap's ring buffer so that
    387   // it can be included in later crash dumps.
    388   void PRINTF_FORMAT(2, 3) Output(const char* format, ...) const;
    389 
    390   void ClearMarkCompactStatistics() {
    391     cumulative_incremental_marking_steps_ = 0;
    392     cumulative_incremental_marking_bytes_ = 0;
    393     cumulative_incremental_marking_duration_ = 0;
    394     cumulative_pure_incremental_marking_duration_ = 0;
    395     longest_incremental_marking_step_ = 0;
    396     cumulative_incremental_marking_finalization_steps_ = 0;
    397     cumulative_incremental_marking_finalization_duration_ = 0;
    398     longest_incremental_marking_finalization_step_ = 0;
    399     cumulative_marking_duration_ = 0;
    400     cumulative_sweeping_duration_ = 0;
    401   }
    402 
    403   double TotalExternalTime() const {
    404     return current_.scopes[Scope::EXTERNAL_WEAK_GLOBAL_HANDLES] +
    405            current_.scopes[Scope::MC_EXTERNAL_EPILOGUE] +
    406            current_.scopes[Scope::MC_EXTERNAL_PROLOGUE] +
    407            current_.scopes[Scope::MC_INCREMENTAL_EXTERNAL_EPILOGUE] +
    408            current_.scopes[Scope::MC_INCREMENTAL_EXTERNAL_PROLOGUE] +
    409            current_.scopes[Scope::SCAVENGER_EXTERNAL_EPILOGUE] +
    410            current_.scopes[Scope::SCAVENGER_EXTERNAL_PROLOGUE];
    411   }
    412 
    413   // Pointer to the heap that owns this tracer.
    414   Heap* heap_;
    415 
    416   // Current tracer event. Populated during Start/Stop cycle. Valid after Stop()
    417   // has returned.
    418   Event current_;
    419 
    420   // Previous tracer event.
    421   Event previous_;
    422 
    423   // Previous INCREMENTAL_MARK_COMPACTOR event.
    424   Event previous_incremental_mark_compactor_event_;
    425 
    426   // Cumulative number of incremental marking steps since creation of tracer.
    427   int cumulative_incremental_marking_steps_;
    428 
    429   // Cumulative size of incremental marking steps (in bytes) since creation of
    430   // tracer.
    431   intptr_t cumulative_incremental_marking_bytes_;
    432 
    433   // Cumulative duration of incremental marking steps since creation of tracer.
    434   double cumulative_incremental_marking_duration_;
    435 
    436   // Cumulative duration of pure incremental marking steps since creation of
    437   // tracer.
    438   double cumulative_pure_incremental_marking_duration_;
    439 
    440   // Longest incremental marking step since start of marking.
    441   double longest_incremental_marking_step_;
    442 
    443   // Cumulative number of incremental marking finalization steps since creation
    444   // of tracer.
    445   int cumulative_incremental_marking_finalization_steps_;
    446 
    447   // Cumulative duration of incremental marking finalization steps since
    448   // creation of tracer.
    449   double cumulative_incremental_marking_finalization_duration_;
    450 
    451   // Longest incremental marking finalization step since start of marking.
    452   double longest_incremental_marking_finalization_step_;
    453 
    454   // Total marking time.
    455   // This timer is precise when run with --print-cumulative-gc-stat
    456   double cumulative_marking_duration_;
    457 
    458   // Total sweeping time on the main thread.
    459   // This timer is precise when run with --print-cumulative-gc-stat
    460   // TODO(hpayer): Account for sweeping time on sweeper threads. Add a
    461   // different field for that.
    462   // TODO(hpayer): This timer right now just holds the sweeping time
    463   // of the initial atomic sweeping pause. Make sure that it accumulates
    464   // all sweeping operations performed on the main thread.
    465   double cumulative_sweeping_duration_;
    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 
    472   // Accumulated duration and allocated bytes since the last GC.
    473   double allocation_duration_since_gc_;
    474   size_t new_space_allocation_in_bytes_since_gc_;
    475   size_t old_generation_allocation_in_bytes_since_gc_;
    476 
    477   double combined_mark_compact_speed_cache_;
    478 
    479   // Counts how many tracers were started without stopping.
    480   int start_counter_;
    481 
    482   // Separate timer used for --runtime_call_stats
    483   RuntimeCallTimer timer_;
    484 
    485   RingBuffer<BytesAndDuration> recorded_incremental_marking_steps_;
    486   RingBuffer<BytesAndDuration> recorded_scavenges_total_;
    487   RingBuffer<BytesAndDuration> recorded_scavenges_survived_;
    488   RingBuffer<BytesAndDuration> recorded_compactions_;
    489   RingBuffer<BytesAndDuration> recorded_mark_compacts_;
    490   RingBuffer<BytesAndDuration> recorded_incremental_mark_compacts_;
    491   RingBuffer<BytesAndDuration> recorded_new_generation_allocations_;
    492   RingBuffer<BytesAndDuration> recorded_old_generation_allocations_;
    493   RingBuffer<double> recorded_context_disposal_times_;
    494   RingBuffer<double> recorded_survival_ratios_;
    495 
    496   DISALLOW_COPY_AND_ASSIGN(GCTracer);
    497 };
    498 }  // namespace internal
    499 }  // namespace v8
    500 
    501 #endif  // V8_HEAP_GC_TRACER_H_
    502