LCOV - code coverage report
Current view: top level - src/heap - gc-tracer.cc (source / functions) Hit Total Coverage
Test: app.info Lines: 236 336 70.2 %
Date: 2017-04-26 Functions: 34 40 85.0 %

          Line data    Source code
       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             : #include "src/heap/gc-tracer.h"
       6             : 
       7             : #include <cstdarg>
       8             : 
       9             : #include "src/counters.h"
      10             : #include "src/heap/heap-inl.h"
      11             : #include "src/isolate.h"
      12             : 
      13             : namespace v8 {
      14             : namespace internal {
      15             : 
      16      245014 : static size_t CountTotalHolesSize(Heap* heap) {
      17             :   size_t holes_size = 0;
      18             :   OldSpaces spaces(heap);
      19      735042 :   for (OldSpace* space = spaces.next(); space != NULL; space = spaces.next()) {
      20             :     DCHECK_GE(holes_size + space->Waste() + space->Available(), holes_size);
      21      490028 :     holes_size += space->Waste() + space->Available();
      22             :   }
      23      245014 :   return holes_size;
      24             : }
      25             : 
      26             : 
      27     3094966 : GCTracer::Scope::Scope(GCTracer* tracer, ScopeId scope)
      28     3094966 :     : tracer_(tracer), scope_(scope) {
      29             :   // All accesses to incremental_marking_scope assume that incremental marking
      30             :   // scopes come first.
      31             :   STATIC_ASSERT(FIRST_INCREMENTAL_SCOPE == 0);
      32     3094966 :   start_time_ = tracer_->heap_->MonotonicallyIncreasingTimeInMs();
      33             :   // TODO(cbruni): remove once we fully moved to a trace-based system.
      34     3094966 :   if (V8_UNLIKELY(FLAG_runtime_stats)) {
      35             :     RuntimeCallStats::Enter(
      36             :         tracer_->heap_->isolate()->counters()->runtime_call_stats(), &timer_,
      37           0 :         &RuntimeCallStats::GC);
      38             :   }
      39     3094966 : }
      40             : 
      41     3094966 : GCTracer::Scope::~Scope() {
      42             :   tracer_->AddScopeSample(
      43     3094966 :       scope_, tracer_->heap_->MonotonicallyIncreasingTimeInMs() - start_time_);
      44             :   // TODO(cbruni): remove once we fully moved to a trace-based system.
      45     3094966 :   if (V8_UNLIKELY(FLAG_runtime_stats)) {
      46             :     RuntimeCallStats::Leave(
      47           0 :         tracer_->heap_->isolate()->counters()->runtime_call_stats(), &timer_);
      48             :   }
      49     3094966 : }
      50             : 
      51           0 : const char* GCTracer::Scope::Name(ScopeId id) {
      52             : #define CASE(scope)  \
      53             :   case Scope::scope: \
      54             :     return "V8.GC_" #scope;
      55           0 :   switch (id) {
      56             :     TRACER_SCOPES(CASE)
      57             :     case Scope::NUMBER_OF_SCOPES:
      58             :       break;
      59             :   }
      60             : #undef CASE
      61             :   return "(unknown)";
      62             : }
      63             : 
      64      183297 : GCTracer::Event::Event(Type type, GarbageCollectionReason gc_reason,
      65             :                        const char* collector_reason)
      66             :     : type(type),
      67             :       gc_reason(gc_reason),
      68             :       collector_reason(collector_reason),
      69             :       start_time(0.0),
      70             :       end_time(0.0),
      71             :       reduce_memory(false),
      72             :       start_object_size(0),
      73             :       end_object_size(0),
      74             :       start_memory_size(0),
      75             :       end_memory_size(0),
      76             :       start_holes_size(0),
      77             :       end_holes_size(0),
      78             :       new_space_object_size(0),
      79             :       survived_new_space_object_size(0),
      80             :       incremental_marking_bytes(0),
      81     1649673 :       incremental_marking_duration(0.0) {
      82    12464196 :   for (int i = 0; i < Scope::NUMBER_OF_SCOPES; i++) {
      83    12464196 :     scopes[i] = 0;
      84             :   }
      85      183297 : }
      86             : 
      87      122543 : const char* GCTracer::Event::TypeName(bool short_name) const {
      88      122543 :   switch (type) {
      89             :     case SCAVENGER:
      90       69167 :       return (short_name) ? "s" : "Scavenge";
      91             :     case MARK_COMPACTOR:
      92             :     case INCREMENTAL_MARK_COMPACTOR:
      93       53376 :       return (short_name) ? "ms" : "Mark-sweep";
      94             :     case MINOR_MARK_COMPACTOR:
      95           0 :       return (short_name) ? "mmc" : "Minor Mark-Compact";
      96             :     case START:
      97           0 :       return (short_name) ? "st" : "Start";
      98             :   }
      99             :   return "Unknown Event Type";
     100             : }
     101             : 
     102       60782 : GCTracer::GCTracer(Heap* heap)
     103             :     : heap_(heap),
     104             :       current_(Event::START, GarbageCollectionReason::kUnknown, nullptr),
     105             :       previous_(current_),
     106             :       incremental_marking_bytes_(0),
     107             :       incremental_marking_duration_(0.0),
     108             :       incremental_marking_start_time_(0.0),
     109             :       recorded_incremental_marking_speed_(0.0),
     110             :       allocation_time_ms_(0.0),
     111             :       new_space_allocation_counter_bytes_(0),
     112             :       old_generation_allocation_counter_bytes_(0),
     113             :       allocation_duration_since_gc_(0.0),
     114             :       new_space_allocation_in_bytes_since_gc_(0),
     115             :       old_generation_allocation_in_bytes_since_gc_(0),
     116             :       combined_mark_compact_speed_cache_(0.0),
     117      547038 :       start_counter_(0) {
     118       60782 :   current_.end_time = heap_->MonotonicallyIncreasingTimeInMs();
     119       60782 : }
     120             : 
     121           8 : void GCTracer::ResetForTesting() {
     122           8 :   current_ = Event(Event::START, GarbageCollectionReason::kTesting, nullptr);
     123           8 :   current_.end_time = heap_->MonotonicallyIncreasingTimeInMs();
     124           8 :   previous_ = current_;
     125             :   ResetIncrementalMarkingCounters();
     126           8 :   allocation_time_ms_ = 0.0;
     127           8 :   new_space_allocation_counter_bytes_ = 0.0;
     128           8 :   old_generation_allocation_counter_bytes_ = 0.0;
     129           8 :   allocation_duration_since_gc_ = 0.0;
     130           8 :   new_space_allocation_in_bytes_since_gc_ = 0.0;
     131           8 :   old_generation_allocation_in_bytes_since_gc_ = 0.0;
     132           8 :   combined_mark_compact_speed_cache_ = 0.0;
     133             :   recorded_minor_gcs_total_.Reset();
     134             :   recorded_minor_gcs_survived_.Reset();
     135             :   recorded_compactions_.Reset();
     136             :   recorded_mark_compacts_.Reset();
     137             :   recorded_incremental_mark_compacts_.Reset();
     138             :   recorded_new_generation_allocations_.Reset();
     139             :   recorded_old_generation_allocations_.Reset();
     140             :   recorded_context_disposal_times_.Reset();
     141             :   recorded_survival_ratios_.Reset();
     142           8 :   start_counter_ = 0;
     143           8 : }
     144             : 
     145       69189 : void GCTracer::NotifyYoungGenerationHandling(
     146             :     YoungGenerationHandling young_generation_handling) {
     147             :   DCHECK(current_.type == Event::SCAVENGER || start_counter_ > 1);
     148             :   heap_->isolate()->counters()->young_generation_handling()->AddSample(
     149      138378 :       static_cast<int>(young_generation_handling));
     150       69189 : }
     151             : 
     152      122543 : void GCTracer::Start(GarbageCollector collector,
     153             :                      GarbageCollectionReason gc_reason,
     154             :                      const char* collector_reason) {
     155      122543 :   start_counter_++;
     156      245086 :   if (start_counter_ != 1) return;
     157             : 
     158      122507 :   previous_ = current_;
     159      543368 :   double start_time = heap_->MonotonicallyIncreasingTimeInMs();
     160             :   SampleAllocation(start_time, heap_->NewSpaceAllocationCounter(),
     161      245014 :                    heap_->OldGenerationAllocationCounter());
     162             : 
     163      122507 :   switch (collector) {
     164             :     case SCAVENGER:
     165       69167 :       current_ = Event(Event::SCAVENGER, gc_reason, collector_reason);
     166       69167 :       break;
     167             :     case MINOR_MARK_COMPACTOR:
     168             :       current_ =
     169           0 :           Event(Event::MINOR_MARK_COMPACTOR, gc_reason, collector_reason);
     170           0 :       break;
     171             :     case MARK_COMPACTOR:
     172      106680 :       if (heap_->incremental_marking()->WasActivated()) {
     173             :         current_ = Event(Event::INCREMENTAL_MARK_COMPACTOR, gc_reason,
     174        1202 :                          collector_reason);
     175             :       } else {
     176       52138 :         current_ = Event(Event::MARK_COMPACTOR, gc_reason, collector_reason);
     177             :       }
     178             :       break;
     179             :   }
     180             : 
     181      245014 :   current_.reduce_memory = heap_->ShouldReduceMemory();
     182      122507 :   current_.start_time = start_time;
     183      122507 :   current_.start_object_size = heap_->SizeOfObjects();
     184      245014 :   current_.start_memory_size = heap_->memory_allocator()->Size();
     185      122507 :   current_.start_holes_size = CountTotalHolesSize(heap_);
     186      245014 :   current_.new_space_object_size = heap_->new_space()->Size();
     187             : 
     188      122507 :   current_.incremental_marking_bytes = 0;
     189      122507 :   current_.incremental_marking_duration = 0;
     190             : 
     191     8452983 :   for (int i = 0; i < Scope::NUMBER_OF_SCOPES; i++) {
     192     8330476 :     current_.scopes[i] = 0;
     193             :   }
     194             : 
     195      122507 :   size_t committed_memory = heap_->CommittedMemory() / KB;
     196      122507 :   size_t used_memory = current_.start_object_size / KB;
     197             : 
     198      245014 :   Counters* counters = heap_->isolate()->counters();
     199             : 
     200      122507 :   if (Heap::IsYoungGenerationCollector(collector)) {
     201       69167 :     counters->scavenge_reason()->AddSample(static_cast<int>(gc_reason));
     202             :   } else {
     203       53340 :     counters->mark_compact_reason()->AddSample(static_cast<int>(gc_reason));
     204             :   }
     205             :   counters->aggregated_memory_heap_committed()->AddSample(start_time,
     206      122507 :                                                           committed_memory);
     207      122507 :   counters->aggregated_memory_heap_used()->AddSample(start_time, used_memory);
     208             :   // TODO(cbruni): remove once we fully moved to a trace-based system.
     209      122507 :   if (V8_UNLIKELY(FLAG_runtime_stats)) {
     210             :     RuntimeCallStats::Enter(heap_->isolate()->counters()->runtime_call_stats(),
     211           0 :                             &timer_, &RuntimeCallStats::GC);
     212             :   }
     213             : }
     214             : 
     215           0 : void GCTracer::ResetIncrementalMarkingCounters() {
     216       53348 :   incremental_marking_bytes_ = 0;
     217       53348 :   incremental_marking_duration_ = 0;
     218      426784 :   for (int i = 0; i < Scope::NUMBER_OF_INCREMENTAL_SCOPES; i++) {
     219      426784 :     incremental_marking_scopes_[i].ResetCurrentCycle();
     220             :   }
     221           0 : }
     222             : 
     223      122543 : void GCTracer::Stop(GarbageCollector collector) {
     224      122543 :   start_counter_--;
     225      122543 :   if (start_counter_ != 0) {
     226             :     heap_->isolate()->PrintWithTimestamp("[Finished reentrant %s during %s.]\n",
     227             :                                          Heap::CollectorName(collector),
     228      245086 :                                          current_.TypeName(false));
     229          36 :     return;
     230             :   }
     231             : 
     232             :   DCHECK(start_counter_ >= 0);
     233             :   DCHECK((collector == SCAVENGER && current_.type == Event::SCAVENGER) ||
     234             :          (collector == MINOR_MARK_COMPACTOR &&
     235             :           current_.type == Event::MINOR_MARK_COMPACTOR) ||
     236             :          (collector == MARK_COMPACTOR &&
     237             :           (current_.type == Event::MARK_COMPACTOR ||
     238             :            current_.type == Event::INCREMENTAL_MARK_COMPACTOR)));
     239             : 
     240      122507 :   current_.end_time = heap_->MonotonicallyIncreasingTimeInMs();
     241      122507 :   current_.end_object_size = heap_->SizeOfObjects();
     242      245014 :   current_.end_memory_size = heap_->memory_allocator()->Size();
     243      122507 :   current_.end_holes_size = CountTotalHolesSize(heap_);
     244      245014 :   current_.survived_new_space_object_size = heap_->SurvivedNewSpaceObjectSize();
     245             : 
     246      122507 :   AddAllocation(current_.end_time);
     247             : 
     248      122507 :   size_t committed_memory = heap_->CommittedMemory() / KB;
     249      122507 :   size_t used_memory = current_.end_object_size / KB;
     250             :   heap_->isolate()->counters()->aggregated_memory_heap_committed()->AddSample(
     251      245014 :       current_.end_time, committed_memory);
     252             :   heap_->isolate()->counters()->aggregated_memory_heap_used()->AddSample(
     253      245014 :       current_.end_time, used_memory);
     254             : 
     255      122507 :   double duration = current_.end_time - current_.start_time;
     256             : 
     257      122507 :   switch (current_.type) {
     258             :     case Event::SCAVENGER:
     259             :     case Event::MINOR_MARK_COMPACTOR:
     260             :       recorded_minor_gcs_total_.Push(
     261       69167 :           MakeBytesAndDuration(current_.new_space_object_size, duration));
     262             :       recorded_minor_gcs_survived_.Push(MakeBytesAndDuration(
     263       69167 :           current_.survived_new_space_object_size, duration));
     264       69167 :       break;
     265             :     case Event::INCREMENTAL_MARK_COMPACTOR:
     266        1207 :       current_.incremental_marking_bytes = incremental_marking_bytes_;
     267        1207 :       current_.incremental_marking_duration = incremental_marking_duration_;
     268       10863 :       for (int i = 0; i < Scope::NUMBER_OF_INCREMENTAL_SCOPES; i++) {
     269        9656 :         current_.incremental_marking_scopes[i] = incremental_marking_scopes_[i];
     270        9656 :         current_.scopes[i] = incremental_marking_scopes_[i].duration;
     271             :       }
     272             :       RecordIncrementalMarkingSpeed(current_.incremental_marking_bytes,
     273        1207 :                                     current_.incremental_marking_duration);
     274             :       recorded_incremental_mark_compacts_.Push(
     275        1207 :           MakeBytesAndDuration(current_.start_object_size, duration));
     276             :       ResetIncrementalMarkingCounters();
     277        1207 :       combined_mark_compact_speed_cache_ = 0.0;
     278        1207 :       break;
     279             :     case Event::MARK_COMPACTOR:
     280             :       DCHECK_EQ(0u, current_.incremental_marking_bytes);
     281             :       DCHECK_EQ(0, current_.incremental_marking_duration);
     282             :       recorded_mark_compacts_.Push(
     283       52133 :           MakeBytesAndDuration(current_.start_object_size, duration));
     284             :       ResetIncrementalMarkingCounters();
     285       52133 :       combined_mark_compact_speed_cache_ = 0.0;
     286       52133 :       break;
     287             :     case Event::START:
     288           0 :       UNREACHABLE();
     289             :   }
     290             : 
     291      122507 :   heap_->UpdateTotalGCTime(duration);
     292             : 
     293      245014 :   if ((current_.type == Event::SCAVENGER ||
     294      122507 :        current_.type == Event::MINOR_MARK_COMPACTOR) &&
     295             :       FLAG_trace_gc_ignore_scavenger)
     296             :     return;
     297             : 
     298      122507 :   if (FLAG_trace_gc_nvp) {
     299           0 :     PrintNVP();
     300             :   } else {
     301      122507 :     Print();
     302             :   }
     303             : 
     304      122507 :   if (FLAG_trace_gc) {
     305          30 :     heap_->PrintShortHeapStatistics();
     306             :   }
     307             : 
     308             :   // TODO(cbruni): remove once we fully moved to a trace-based system.
     309      122507 :   if (V8_UNLIKELY(FLAG_runtime_stats)) {
     310             :     RuntimeCallStats::Leave(heap_->isolate()->counters()->runtime_call_stats(),
     311           0 :                             &timer_);
     312             :   }
     313             : }
     314             : 
     315             : 
     316        5473 : void GCTracer::SampleAllocation(double current_ms,
     317             :                                 size_t new_space_counter_bytes,
     318             :                                 size_t old_generation_counter_bytes) {
     319      127980 :   if (allocation_time_ms_ == 0) {
     320             :     // It is the first sample.
     321       12064 :     allocation_time_ms_ = current_ms;
     322       12064 :     new_space_allocation_counter_bytes_ = new_space_counter_bytes;
     323       12064 :     old_generation_allocation_counter_bytes_ = old_generation_counter_bytes;
     324        7648 :     return;
     325             :   }
     326             :   // This assumes that counters are unsigned integers so that the subtraction
     327             :   // below works even if the new counter is less than the old counter.
     328             :   size_t new_space_allocated_bytes =
     329      115916 :       new_space_counter_bytes - new_space_allocation_counter_bytes_;
     330             :   size_t old_generation_allocated_bytes =
     331      115916 :       old_generation_counter_bytes - old_generation_allocation_counter_bytes_;
     332      115916 :   double duration = current_ms - allocation_time_ms_;
     333      115916 :   allocation_time_ms_ = current_ms;
     334      115916 :   new_space_allocation_counter_bytes_ = new_space_counter_bytes;
     335      115916 :   old_generation_allocation_counter_bytes_ = old_generation_counter_bytes;
     336      115916 :   allocation_duration_since_gc_ += duration;
     337      115916 :   new_space_allocation_in_bytes_since_gc_ += new_space_allocated_bytes;
     338             :   old_generation_allocation_in_bytes_since_gc_ +=
     339      115916 :       old_generation_allocated_bytes;
     340             : }
     341             : 
     342             : 
     343      122519 : void GCTracer::AddAllocation(double current_ms) {
     344      122519 :   allocation_time_ms_ = current_ms;
     345      122519 :   if (allocation_duration_since_gc_ > 0) {
     346             :     recorded_new_generation_allocations_.Push(
     347             :         MakeBytesAndDuration(new_space_allocation_in_bytes_since_gc_,
     348      112626 :                              allocation_duration_since_gc_));
     349             :     recorded_old_generation_allocations_.Push(
     350             :         MakeBytesAndDuration(old_generation_allocation_in_bytes_since_gc_,
     351      112626 :                              allocation_duration_since_gc_));
     352             :   }
     353      122519 :   allocation_duration_since_gc_ = 0;
     354      122519 :   new_space_allocation_in_bytes_since_gc_ = 0;
     355      122519 :   old_generation_allocation_in_bytes_since_gc_ = 0;
     356      122519 : }
     357             : 
     358             : 
     359        5720 : void GCTracer::AddContextDisposalTime(double time) {
     360             :   recorded_context_disposal_times_.Push(time);
     361        5720 : }
     362             : 
     363       59260 : void GCTracer::AddCompactionEvent(double duration,
     364             :                                   size_t live_bytes_compacted) {
     365             :   recorded_compactions_.Push(
     366       59260 :       MakeBytesAndDuration(live_bytes_compacted, duration));
     367       59260 : }
     368             : 
     369             : 
     370      110386 : void GCTracer::AddSurvivalRatio(double promotion_ratio) {
     371             :   recorded_survival_ratios_.Push(promotion_ratio);
     372      110386 : }
     373             : 
     374       27295 : void GCTracer::AddIncrementalMarkingStep(double duration, size_t bytes) {
     375       27295 :   if (bytes > 0) {
     376       25398 :     incremental_marking_bytes_ += bytes;
     377       25398 :     incremental_marking_duration_ += duration;
     378             :   }
     379       27295 : }
     380             : 
     381      122507 : void GCTracer::Output(const char* format, ...) const {
     382      122507 :   if (FLAG_trace_gc) {
     383             :     va_list arguments;
     384          30 :     va_start(arguments, format);
     385          30 :     base::OS::VPrint(format, arguments);
     386          30 :     va_end(arguments);
     387             :   }
     388             : 
     389             :   const int kBufferSize = 256;
     390             :   char raw_buffer[kBufferSize];
     391             :   Vector<char> buffer(raw_buffer, kBufferSize);
     392             :   va_list arguments2;
     393      122507 :   va_start(arguments2, format);
     394      122507 :   VSNPrintF(buffer, format, arguments2);
     395      122507 :   va_end(arguments2);
     396             : 
     397      122507 :   heap_->AddToRingBuffer(buffer.start());
     398      122507 : }
     399             : 
     400      122507 : void GCTracer::Print() const {
     401      122507 :   double duration = current_.end_time - current_.start_time;
     402             :   const size_t kIncrementalStatsSize = 128;
     403      122507 :   char incremental_buffer[kIncrementalStatsSize] = {0};
     404             : 
     405      122507 :   if (current_.type == Event::INCREMENTAL_MARK_COMPACTOR) {
     406             :     base::OS::SNPrintF(
     407             :         incremental_buffer, kIncrementalStatsSize,
     408             :         " (+ %.1f ms in %d steps since start of marking, "
     409             :         "biggest step %.1f ms, walltime since start of marking %.f ms)",
     410        1207 :         current_.scopes[Scope::MC_INCREMENTAL],
     411             :         current_.incremental_marking_scopes[Scope::MC_INCREMENTAL].steps,
     412             :         current_.incremental_marking_scopes[Scope::MC_INCREMENTAL].longest_step,
     413        2414 :         current_.end_time - incremental_marking_start_time_);
     414             :   }
     415             : 
     416             :   // Avoid PrintF as Output also appends the string to the tracing ring buffer
     417             :   // that gets printed on OOM failures.
     418             :   Output(
     419             :       "[%d:%p] "
     420             :       "%8.0f ms: "
     421             :       "%s %.1f (%.1f) -> %.1f (%.1f) MB, "
     422             :       "%.1f / %.1f ms %s %s %s\n",
     423             :       base::OS::GetCurrentProcessId(),
     424      122507 :       reinterpret_cast<void*>(heap_->isolate()),
     425             :       heap_->isolate()->time_millis_since_init(), current_.TypeName(false),
     426             :       static_cast<double>(current_.start_object_size) / MB,
     427             :       static_cast<double>(current_.start_memory_size) / MB,
     428             :       static_cast<double>(current_.end_object_size) / MB,
     429             :       static_cast<double>(current_.end_memory_size) / MB, duration,
     430             :       TotalExternalTime(), incremental_buffer,
     431             :       Heap::GarbageCollectionReasonToString(current_.gc_reason),
     432      367521 :       current_.collector_reason != nullptr ? current_.collector_reason : "");
     433      122507 : }
     434             : 
     435             : 
     436           0 : void GCTracer::PrintNVP() const {
     437           0 :   double duration = current_.end_time - current_.start_time;
     438           0 :   double spent_in_mutator = current_.start_time - previous_.end_time;
     439             :   size_t allocated_since_last_gc =
     440           0 :       current_.start_object_size - previous_.end_object_size;
     441             : 
     442             :   double incremental_walltime_duration = 0;
     443             : 
     444           0 :   if (current_.type == Event::INCREMENTAL_MARK_COMPACTOR) {
     445             :     incremental_walltime_duration =
     446           0 :         current_.end_time - incremental_marking_start_time_;
     447             :   }
     448             : 
     449           0 :   switch (current_.type) {
     450             :     case Event::SCAVENGER:
     451             :       heap_->isolate()->PrintWithTimestamp(
     452             :           "pause=%.1f "
     453             :           "mutator=%.1f "
     454             :           "gc=%s "
     455             :           "reduce_memory=%d "
     456             :           "heap.prologue=%.2f "
     457             :           "heap.epilogue=%.2f "
     458             :           "heap.epilogue.reduce_new_space=%.2f "
     459             :           "heap.external.prologue=%.2f "
     460             :           "heap.external.epilogue=%.2f "
     461             :           "heap.external_weak_global_handles=%.2f "
     462             :           "scavenge=%.2f "
     463             :           "evacuate=%.2f "
     464             :           "old_new=%.2f "
     465             :           "weak=%.2f "
     466             :           "roots=%.2f "
     467             :           "code=%.2f "
     468             :           "semispace=%.2f "
     469             :           "steps_count=%d "
     470             :           "steps_took=%.1f "
     471             :           "scavenge_throughput=%.f "
     472             :           "total_size_before=%" PRIuS
     473             :           " "
     474             :           "total_size_after=%" PRIuS
     475             :           " "
     476             :           "holes_size_before=%" PRIuS
     477             :           " "
     478             :           "holes_size_after=%" PRIuS
     479             :           " "
     480             :           "allocated=%" PRIuS
     481             :           " "
     482             :           "promoted=%" PRIuS
     483             :           " "
     484             :           "semi_space_copied=%" PRIuS
     485             :           " "
     486             :           "nodes_died_in_new=%d "
     487             :           "nodes_copied_in_new=%d "
     488             :           "nodes_promoted=%d "
     489             :           "promotion_ratio=%.1f%% "
     490             :           "average_survival_ratio=%.1f%% "
     491             :           "promotion_rate=%.1f%% "
     492             :           "semi_space_copy_rate=%.1f%% "
     493             :           "new_space_allocation_throughput=%.1f "
     494             :           "context_disposal_rate=%.1f\n",
     495             :           duration, spent_in_mutator, current_.TypeName(true),
     496           0 :           current_.reduce_memory, current_.scopes[Scope::HEAP_PROLOGUE],
     497           0 :           current_.scopes[Scope::HEAP_EPILOGUE],
     498           0 :           current_.scopes[Scope::HEAP_EPILOGUE_REDUCE_NEW_SPACE],
     499           0 :           current_.scopes[Scope::HEAP_EXTERNAL_PROLOGUE],
     500           0 :           current_.scopes[Scope::HEAP_EXTERNAL_EPILOGUE],
     501           0 :           current_.scopes[Scope::HEAP_EXTERNAL_WEAK_GLOBAL_HANDLES],
     502           0 :           current_.scopes[Scope::SCAVENGER_SCAVENGE],
     503           0 :           current_.scopes[Scope::SCAVENGER_EVACUATE],
     504           0 :           current_.scopes[Scope::SCAVENGER_OLD_TO_NEW_POINTERS],
     505           0 :           current_.scopes[Scope::SCAVENGER_WEAK],
     506           0 :           current_.scopes[Scope::SCAVENGER_ROOTS],
     507           0 :           current_.scopes[Scope::SCAVENGER_CODE_FLUSH_CANDIDATES],
     508           0 :           current_.scopes[Scope::SCAVENGER_SEMISPACE],
     509             :           current_.incremental_marking_scopes[GCTracer::Scope::MC_INCREMENTAL]
     510             :               .steps,
     511           0 :           current_.scopes[Scope::MC_INCREMENTAL],
     512             :           ScavengeSpeedInBytesPerMillisecond(), current_.start_object_size,
     513             :           current_.end_object_size, current_.start_holes_size,
     514             :           current_.end_holes_size, allocated_since_last_gc,
     515             :           heap_->promoted_objects_size(),
     516             :           heap_->semi_space_copied_object_size(),
     517             :           heap_->nodes_died_in_new_space_, heap_->nodes_copied_in_new_space_,
     518             :           heap_->nodes_promoted_, heap_->promotion_ratio_,
     519             :           AverageSurvivalRatio(), heap_->promotion_rate_,
     520             :           heap_->semi_space_copied_rate_,
     521             :           NewSpaceAllocationThroughputInBytesPerMillisecond(),
     522           0 :           ContextDisposalRateInMilliseconds());
     523           0 :       break;
     524             :     case Event::MINOR_MARK_COMPACTOR:
     525             :       heap_->isolate()->PrintWithTimestamp(
     526             :           "pause=%.1f "
     527             :           "mutator=%.1f "
     528             :           "gc=%s "
     529             :           "reduce_memory=%d "
     530             :           "mark=%.2f "
     531             :           "mark.roots=%.2f "
     532             :           "mark.old_to_new=%.2f\n",
     533             :           duration, spent_in_mutator, "mmc", current_.reduce_memory,
     534           0 :           current_.scopes[Scope::MINOR_MC_MARK],
     535           0 :           current_.scopes[Scope::MINOR_MC_MARK_ROOTS],
     536           0 :           current_.scopes[Scope::MINOR_MC_MARK_OLD_TO_NEW_POINTERS]);
     537           0 :       break;
     538             :     case Event::MARK_COMPACTOR:
     539             :     case Event::INCREMENTAL_MARK_COMPACTOR:
     540             :       heap_->isolate()->PrintWithTimestamp(
     541             :           "pause=%.1f "
     542             :           "mutator=%.1f "
     543             :           "gc=%s "
     544             :           "reduce_memory=%d "
     545             :           "heap.prologue=%.2f "
     546             :           "heap.epilogue=%.2f "
     547             :           "heap.epilogue.reduce_new_space=%.2f "
     548             :           "heap.external.prologue=%.1f "
     549             :           "heap.external.epilogue=%.1f "
     550             :           "heap.external.weak_global_handles=%.1f "
     551             :           "clear=%1.f "
     552             :           "clear.code_flush=%.1f "
     553             :           "clear.dependent_code=%.1f "
     554             :           "clear.maps=%.1f "
     555             :           "clear.slots_buffer=%.1f "
     556             :           "clear.store_buffer=%.1f "
     557             :           "clear.string_table=%.1f "
     558             :           "clear.weak_cells=%.1f "
     559             :           "clear.weak_collections=%.1f "
     560             :           "clear.weak_lists=%.1f "
     561             :           "epilogue=%.1f "
     562             :           "evacuate=%.1f "
     563             :           "evacuate.candidates=%.1f "
     564             :           "evacuate.clean_up=%.1f "
     565             :           "evacuate.copy=%.1f "
     566             :           "evacuate.prologue=%.1f "
     567             :           "evacuate.epilogue=%.1f "
     568             :           "evacuate.rebalance=%.1f "
     569             :           "evacuate.update_pointers=%.1f "
     570             :           "evacuate.update_pointers.to_evacuated=%.1f "
     571             :           "evacuate.update_pointers.to_new=%.1f "
     572             :           "evacuate.update_pointers.weak=%.1f "
     573             :           "finish=%.1f "
     574             :           "mark=%.1f "
     575             :           "mark.finish_incremental=%.1f "
     576             :           "mark.prepare_code_flush=%.1f "
     577             :           "mark.roots=%.1f "
     578             :           "mark.weak_closure=%.1f "
     579             :           "mark.weak_closure.ephemeral=%.1f "
     580             :           "mark.weak_closure.weak_handles=%.1f "
     581             :           "mark.weak_closure.weak_roots=%.1f "
     582             :           "mark.weak_closure.harmony=%.1f "
     583             :           "mark.wrapper_prologue=%.1f "
     584             :           "mark.wrapper_epilogue=%.1f "
     585             :           "mark.wrapper_tracing=%.1f "
     586             :           "prologue=%.1f "
     587             :           "sweep=%.1f "
     588             :           "sweep.code=%.1f "
     589             :           "sweep.map=%.1f "
     590             :           "sweep.old=%.1f "
     591             :           "incremental=%.1f "
     592             :           "incremental.finalize=%.1f "
     593             :           "incremental.finalize.body=%.1f "
     594             :           "incremental.finalize.external.prologue=%.1f "
     595             :           "incremental.finalize.external.epilogue=%.1f "
     596             :           "incremental.sweeping=%.1f "
     597             :           "incremental.wrapper_prologue=%.1f "
     598             :           "incremental.wrapper_tracing=%.1f "
     599             :           "incremental_wrapper_tracing_longest_step=%.1f "
     600             :           "incremental_finalize_longest_step=%.1f "
     601             :           "incremental_finalize_steps_count=%d "
     602             :           "incremental_longest_step=%.1f "
     603             :           "incremental_steps_count=%d "
     604             :           "incremental_marking_throughput=%.f "
     605             :           "incremental_walltime_duration=%.f "
     606             :           "total_size_before=%" PRIuS
     607             :           " "
     608             :           "total_size_after=%" PRIuS
     609             :           " "
     610             :           "holes_size_before=%" PRIuS
     611             :           " "
     612             :           "holes_size_after=%" PRIuS
     613             :           " "
     614             :           "allocated=%" PRIuS
     615             :           " "
     616             :           "promoted=%" PRIuS
     617             :           " "
     618             :           "semi_space_copied=%" PRIuS
     619             :           " "
     620             :           "nodes_died_in_new=%d "
     621             :           "nodes_copied_in_new=%d "
     622             :           "nodes_promoted=%d "
     623             :           "promotion_ratio=%.1f%% "
     624             :           "average_survival_ratio=%.1f%% "
     625             :           "promotion_rate=%.1f%% "
     626             :           "semi_space_copy_rate=%.1f%% "
     627             :           "new_space_allocation_throughput=%.1f "
     628             :           "context_disposal_rate=%.1f "
     629             :           "compaction_speed=%.f\n",
     630             :           duration, spent_in_mutator, current_.TypeName(true),
     631           0 :           current_.reduce_memory, current_.scopes[Scope::HEAP_PROLOGUE],
     632           0 :           current_.scopes[Scope::HEAP_EPILOGUE],
     633           0 :           current_.scopes[Scope::HEAP_EPILOGUE_REDUCE_NEW_SPACE],
     634           0 :           current_.scopes[Scope::HEAP_EXTERNAL_PROLOGUE],
     635           0 :           current_.scopes[Scope::HEAP_EXTERNAL_EPILOGUE],
     636           0 :           current_.scopes[Scope::HEAP_EXTERNAL_WEAK_GLOBAL_HANDLES],
     637           0 :           current_.scopes[Scope::MC_CLEAR],
     638           0 :           current_.scopes[Scope::MC_CLEAR_CODE_FLUSH],
     639           0 :           current_.scopes[Scope::MC_CLEAR_DEPENDENT_CODE],
     640           0 :           current_.scopes[Scope::MC_CLEAR_MAPS],
     641           0 :           current_.scopes[Scope::MC_CLEAR_SLOTS_BUFFER],
     642           0 :           current_.scopes[Scope::MC_CLEAR_STORE_BUFFER],
     643           0 :           current_.scopes[Scope::MC_CLEAR_STRING_TABLE],
     644           0 :           current_.scopes[Scope::MC_CLEAR_WEAK_CELLS],
     645           0 :           current_.scopes[Scope::MC_CLEAR_WEAK_COLLECTIONS],
     646           0 :           current_.scopes[Scope::MC_CLEAR_WEAK_LISTS],
     647           0 :           current_.scopes[Scope::MC_EPILOGUE],
     648           0 :           current_.scopes[Scope::MC_EVACUATE],
     649           0 :           current_.scopes[Scope::MC_EVACUATE_CANDIDATES],
     650           0 :           current_.scopes[Scope::MC_EVACUATE_CLEAN_UP],
     651           0 :           current_.scopes[Scope::MC_EVACUATE_COPY],
     652           0 :           current_.scopes[Scope::MC_EVACUATE_PROLOGUE],
     653           0 :           current_.scopes[Scope::MC_EVACUATE_EPILOGUE],
     654           0 :           current_.scopes[Scope::MC_EVACUATE_REBALANCE],
     655           0 :           current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS],
     656           0 :           current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS_TO_EVACUATED],
     657           0 :           current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS_TO_NEW],
     658           0 :           current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS_WEAK],
     659           0 :           current_.scopes[Scope::MC_FINISH], current_.scopes[Scope::MC_MARK],
     660           0 :           current_.scopes[Scope::MC_MARK_FINISH_INCREMENTAL],
     661           0 :           current_.scopes[Scope::MC_MARK_PREPARE_CODE_FLUSH],
     662           0 :           current_.scopes[Scope::MC_MARK_ROOTS],
     663           0 :           current_.scopes[Scope::MC_MARK_WEAK_CLOSURE],
     664           0 :           current_.scopes[Scope::MC_MARK_WEAK_CLOSURE_EPHEMERAL],
     665           0 :           current_.scopes[Scope::MC_MARK_WEAK_CLOSURE_WEAK_HANDLES],
     666           0 :           current_.scopes[Scope::MC_MARK_WEAK_CLOSURE_WEAK_ROOTS],
     667           0 :           current_.scopes[Scope::MC_MARK_WEAK_CLOSURE_HARMONY],
     668           0 :           current_.scopes[Scope::MC_MARK_WRAPPER_PROLOGUE],
     669           0 :           current_.scopes[Scope::MC_MARK_WRAPPER_EPILOGUE],
     670           0 :           current_.scopes[Scope::MC_MARK_WRAPPER_TRACING],
     671           0 :           current_.scopes[Scope::MC_PROLOGUE], current_.scopes[Scope::MC_SWEEP],
     672           0 :           current_.scopes[Scope::MC_SWEEP_CODE],
     673           0 :           current_.scopes[Scope::MC_SWEEP_MAP],
     674           0 :           current_.scopes[Scope::MC_SWEEP_OLD],
     675           0 :           current_.scopes[Scope::MC_INCREMENTAL],
     676           0 :           current_.scopes[Scope::MC_INCREMENTAL_FINALIZE],
     677           0 :           current_.scopes[Scope::MC_INCREMENTAL_FINALIZE_BODY],
     678           0 :           current_.scopes[Scope::MC_INCREMENTAL_EXTERNAL_PROLOGUE],
     679           0 :           current_.scopes[Scope::MC_INCREMENTAL_EXTERNAL_EPILOGUE],
     680           0 :           current_.scopes[Scope::MC_INCREMENTAL_SWEEPING],
     681           0 :           current_.scopes[Scope::MC_INCREMENTAL_WRAPPER_PROLOGUE],
     682           0 :           current_.scopes[Scope::MC_INCREMENTAL_WRAPPER_TRACING],
     683             :           current_
     684             :               .incremental_marking_scopes[Scope::MC_INCREMENTAL_WRAPPER_TRACING]
     685             :               .longest_step,
     686             :           current_
     687             :               .incremental_marking_scopes[Scope::MC_INCREMENTAL_FINALIZE_BODY]
     688             :               .longest_step,
     689             :           current_
     690             :               .incremental_marking_scopes[Scope::MC_INCREMENTAL_FINALIZE_BODY]
     691             :               .steps,
     692             :           current_.incremental_marking_scopes[Scope::MC_INCREMENTAL]
     693             :               .longest_step,
     694             :           current_.incremental_marking_scopes[Scope::MC_INCREMENTAL].steps,
     695             :           IncrementalMarkingSpeedInBytesPerMillisecond(),
     696             :           incremental_walltime_duration, current_.start_object_size,
     697             :           current_.end_object_size, current_.start_holes_size,
     698             :           current_.end_holes_size, allocated_since_last_gc,
     699             :           heap_->promoted_objects_size(),
     700             :           heap_->semi_space_copied_object_size(),
     701             :           heap_->nodes_died_in_new_space_, heap_->nodes_copied_in_new_space_,
     702             :           heap_->nodes_promoted_, heap_->promotion_ratio_,
     703             :           AverageSurvivalRatio(), heap_->promotion_rate_,
     704             :           heap_->semi_space_copied_rate_,
     705             :           NewSpaceAllocationThroughputInBytesPerMillisecond(),
     706             :           ContextDisposalRateInMilliseconds(),
     707           0 :           CompactionSpeedInBytesPerMillisecond());
     708           0 :       break;
     709             :     case Event::START:
     710             :       break;
     711             :     default:
     712           0 :       UNREACHABLE();
     713             :   }
     714           0 : }
     715             : 
     716      860815 : double GCTracer::AverageSpeed(const base::RingBuffer<BytesAndDuration>& buffer,
     717             :                               const BytesAndDuration& initial, double time_ms) {
     718             :   BytesAndDuration sum = buffer.Sum(
     719             :       [time_ms](BytesAndDuration a, BytesAndDuration b) {
     720     4670269 :         if (time_ms != 0 && a.second >= time_ms) return a;
     721     4668765 :         return std::make_pair(a.first + b.first, a.second + b.second);
     722             :       },
     723      860815 :       initial);
     724      860815 :   uint64_t bytes = sum.first;
     725      860815 :   double durations = sum.second;
     726      860815 :   if (durations == 0.0) return 0;
     727      625269 :   double speed = bytes / durations;
     728             :   const int max_speed = 1024 * MB;
     729             :   const int min_speed = 1;
     730      625269 :   if (speed >= max_speed) return max_speed;
     731      625268 :   if (speed <= min_speed) return min_speed;
     732      497771 :   return speed;
     733             : }
     734             : 
     735           0 : double GCTracer::AverageSpeed(
     736             :     const base::RingBuffer<BytesAndDuration>& buffer) {
     737      423994 :   return AverageSpeed(buffer, MakeBytesAndDuration(0, 0), 0);
     738             : }
     739             : 
     740           0 : void GCTracer::RecordIncrementalMarkingSpeed(size_t bytes, double duration) {
     741        1207 :   if (duration == 0 || bytes == 0) return;
     742        1118 :   double current_speed = bytes / duration;
     743        1118 :   if (recorded_incremental_marking_speed_ == 0) {
     744         625 :     recorded_incremental_marking_speed_ = current_speed;
     745             :   } else {
     746             :     recorded_incremental_marking_speed_ =
     747         493 :         (recorded_incremental_marking_speed_ + current_speed) / 2;
     748             :   }
     749             : }
     750             : 
     751       21015 : double GCTracer::IncrementalMarkingSpeedInBytesPerMillisecond() const {
     752             :   const int kConservativeSpeedInBytesPerMillisecond = 128 * KB;
     753      131398 :   if (recorded_incremental_marking_speed_ != 0) {
     754             :     return recorded_incremental_marking_speed_;
     755             :   }
     756      122450 :   if (incremental_marking_duration_ != 0.0) {
     757       13564 :     return incremental_marking_bytes_ / incremental_marking_duration_;
     758             :   }
     759             :   return kConservativeSpeedInBytesPerMillisecond;
     760             : }
     761             : 
     762       78281 : double GCTracer::ScavengeSpeedInBytesPerMillisecond(
     763             :     ScavengeSpeedMode mode) const {
     764       78281 :   if (mode == kForAllObjects) {
     765       18164 :     return AverageSpeed(recorded_minor_gcs_total_);
     766             :   } else {
     767      138398 :     return AverageSpeed(recorded_minor_gcs_survived_);
     768             :   }
     769             : }
     770             : 
     771      126065 : double GCTracer::CompactionSpeedInBytesPerMillisecond() const {
     772      252130 :   return AverageSpeed(recorded_compactions_);
     773             : }
     774             : 
     775           0 : double GCTracer::MarkCompactSpeedInBytesPerMillisecond() const {
     776      109245 :   return AverageSpeed(recorded_mark_compacts_);
     777             : }
     778             : 
     779          20 : double GCTracer::FinalIncrementalMarkCompactSpeedInBytesPerMillisecond() const {
     780      110423 :   return AverageSpeed(recorded_incremental_mark_compacts_);
     781             : }
     782             : 
     783      122535 : double GCTracer::CombinedMarkCompactSpeedInBytesPerMillisecond() {
     784      122535 :   if (combined_mark_compact_speed_cache_ > 0)
     785             :     return combined_mark_compact_speed_cache_;
     786             :   const double kMinimumMarkingSpeed = 0.5;
     787             :   double speed1 = IncrementalMarkingSpeedInBytesPerMillisecond();
     788             :   double speed2 = FinalIncrementalMarkCompactSpeedInBytesPerMillisecond();
     789      110383 :   if (speed1 < kMinimumMarkingSpeed || speed2 < kMinimumMarkingSpeed) {
     790             :     // No data for the incremental marking speed.
     791             :     // Return the non-incremental mark-compact speed.
     792             :     combined_mark_compact_speed_cache_ =
     793      109245 :         MarkCompactSpeedInBytesPerMillisecond();
     794             :   } else {
     795             :     // Combine the speed of incremental step and the speed of the final step.
     796             :     // 1 / (1 / speed1 + 1 / speed2) = speed1 * speed2 / (speed1 + speed2).
     797        1138 :     combined_mark_compact_speed_cache_ = speed1 * speed2 / (speed1 + speed2);
     798             :   }
     799      110383 :   return combined_mark_compact_speed_cache_;
     800             : }
     801             : 
     802       69203 : double GCTracer::NewSpaceAllocationThroughputInBytesPerMillisecond(
     803             :     double time_ms) const {
     804      191740 :   size_t bytes = new_space_allocation_in_bytes_since_gc_;
     805      191740 :   double durations = allocation_duration_since_gc_;
     806             :   return AverageSpeed(recorded_new_generation_allocations_,
     807      191740 :                       MakeBytesAndDuration(bytes, durations), time_ms);
     808             : }
     809             : 
     810           2 : double GCTracer::OldGenerationAllocationThroughputInBytesPerMillisecond(
     811             :     double time_ms) const {
     812      245074 :   size_t bytes = old_generation_allocation_in_bytes_since_gc_;
     813      245074 :   double durations = allocation_duration_since_gc_;
     814             :   return AverageSpeed(recorded_old_generation_allocations_,
     815      245074 :                       MakeBytesAndDuration(bytes, durations), time_ms);
     816             : }
     817             : 
     818      122537 : double GCTracer::AllocationThroughputInBytesPerMillisecond(
     819             :     double time_ms) const {
     820             :   return NewSpaceAllocationThroughputInBytesPerMillisecond(time_ms) +
     821      122537 :          OldGenerationAllocationThroughputInBytesPerMillisecond(time_ms);
     822             : }
     823             : 
     824      122535 : double GCTracer::CurrentAllocationThroughputInBytesPerMillisecond() const {
     825      122535 :   return AllocationThroughputInBytesPerMillisecond(kThroughputTimeFrameMs);
     826             : }
     827             : 
     828      122535 : double GCTracer::CurrentOldGenerationAllocationThroughputInBytesPerMillisecond()
     829             :     const {
     830             :   return OldGenerationAllocationThroughputInBytesPerMillisecond(
     831      122535 :       kThroughputTimeFrameMs);
     832             : }
     833             : 
     834        5450 : double GCTracer::ContextDisposalRateInMilliseconds() const {
     835        5450 :   if (recorded_context_disposal_times_.Count() <
     836             :       recorded_context_disposal_times_.kSize)
     837             :     return 0.0;
     838         358 :   double begin = heap_->MonotonicallyIncreasingTimeInMs();
     839             :   double end = recorded_context_disposal_times_.Sum(
     840             :       [](double a, double b) { return b; }, 0.0);
     841         358 :   return (begin - end) / recorded_context_disposal_times_.Count();
     842             : }
     843             : 
     844       56476 : double GCTracer::AverageSurvivalRatio() const {
     845       56476 :   if (recorded_survival_ratios_.Count() == 0) return 0.0;
     846             :   double sum = recorded_survival_ratios_.Sum(
     847      493026 :       [](double a, double b) { return a + b; }, 0.0);
     848       56476 :   return sum / recorded_survival_ratios_.Count();
     849             : }
     850             : 
     851       56476 : bool GCTracer::SurvivalEventsRecorded() const {
     852       56476 :   return recorded_survival_ratios_.Count() > 0;
     853             : }
     854             : 
     855          24 : void GCTracer::ResetSurvivalEvents() { recorded_survival_ratios_.Reset(); }
     856             : 
     857        1229 : void GCTracer::NotifyIncrementalMarkingStart() {
     858        1229 :   incremental_marking_start_time_ = heap_->MonotonicallyIncreasingTimeInMs();
     859        1229 : }
     860             : 
     861             : }  // namespace internal
     862             : }  // namespace v8

Generated by: LCOV version 1.10