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/base/atomic-utils.h"
10 : #include "src/counters-inl.h"
11 : #include "src/heap/heap-inl.h"
12 : #include "src/heap/incremental-marking.h"
13 : #include "src/heap/spaces.h"
14 : #include "src/isolate.h"
15 :
16 : namespace v8 {
17 : namespace internal {
18 :
19 195960 : static size_t CountTotalHolesSize(Heap* heap) {
20 : size_t holes_size = 0;
21 : PagedSpaces spaces(heap);
22 783840 : for (PagedSpace* space = spaces.next(); space != nullptr;
23 : space = spaces.next()) {
24 : DCHECK_GE(holes_size + space->Waste() + space->Available(), holes_size);
25 587880 : holes_size += space->Waste() + space->Available();
26 : }
27 195960 : return holes_size;
28 : }
29 :
30 0 : RuntimeCallCounterId GCTracer::RCSCounterFromScope(Scope::ScopeId id) {
31 : STATIC_ASSERT(Scope::FIRST_SCOPE == Scope::MC_INCREMENTAL);
32 : return static_cast<RuntimeCallCounterId>(
33 : static_cast<int>(RuntimeCallCounterId::kGC_MC_INCREMENTAL) +
34 0 : static_cast<int>(id));
35 : }
36 :
37 8401625 : GCTracer::Scope::Scope(GCTracer* tracer, ScopeId scope)
38 16803250 : : tracer_(tracer), scope_(scope) {
39 8401625 : start_time_ = tracer_->heap_->MonotonicallyIncreasingTimeInMs();
40 : // TODO(cbruni): remove once we fully moved to a trace-based system.
41 16803252 : if (V8_LIKELY(!FLAG_runtime_stats)) return;
42 0 : runtime_stats_ = tracer_->heap_->isolate()->counters()->runtime_call_stats();
43 0 : runtime_stats_->Enter(&timer_, GCTracer::RCSCounterFromScope(scope));
44 : }
45 :
46 8401627 : GCTracer::Scope::~Scope() {
47 : tracer_->AddScopeSample(
48 8401627 : scope_, tracer_->heap_->MonotonicallyIncreasingTimeInMs() - start_time_);
49 : // TODO(cbruni): remove once we fully moved to a trace-based system.
50 8401625 : if (V8_LIKELY(runtime_stats_ == nullptr)) return;
51 0 : runtime_stats_->Leave(&timer_);
52 8401625 : }
53 :
54 1414909 : GCTracer::BackgroundScope::BackgroundScope(GCTracer* tracer, ScopeId scope)
55 2829818 : : tracer_(tracer), scope_(scope), runtime_stats_enabled_(false) {
56 1414909 : start_time_ = tracer_->heap_->MonotonicallyIncreasingTimeInMs();
57 : // TODO(cbruni): remove once we fully moved to a trace-based system.
58 2831434 : if (V8_LIKELY(!base::AsAtomic32::Relaxed_Load(&FLAG_runtime_stats))) return;
59 0 : timer_.Start(&counter_, nullptr);
60 0 : runtime_stats_enabled_ = true;
61 : }
62 :
63 1414774 : GCTracer::BackgroundScope::~BackgroundScope() {
64 : double duration_ms =
65 1414774 : tracer_->heap_->MonotonicallyIncreasingTimeInMs() - start_time_;
66 : // TODO(cbruni): remove once we fully moved to a trace-based system.
67 1414652 : if (V8_LIKELY(!runtime_stats_enabled_)) {
68 1414652 : tracer_->AddBackgroundScopeSample(scope_, duration_ms, nullptr);
69 : } else {
70 0 : timer_.Stop();
71 0 : tracer_->AddBackgroundScopeSample(scope_, duration_ms, &counter_);
72 : }
73 1416814 : }
74 :
75 0 : const char* GCTracer::Scope::Name(ScopeId id) {
76 : #define CASE(scope) \
77 : case Scope::scope: \
78 : return "V8.GC_" #scope;
79 0 : switch (id) {
80 0 : TRACER_SCOPES(CASE)
81 0 : TRACER_BACKGROUND_SCOPES(CASE)
82 : case Scope::NUMBER_OF_SCOPES:
83 : break;
84 : }
85 : #undef CASE
86 0 : UNREACHABLE();
87 : return nullptr;
88 : }
89 :
90 0 : const char* GCTracer::BackgroundScope::Name(ScopeId id) {
91 : #define CASE(scope) \
92 : case BackgroundScope::scope: \
93 : return "V8.GC_" #scope;
94 0 : switch (id) {
95 0 : TRACER_BACKGROUND_SCOPES(CASE)
96 : case BackgroundScope::NUMBER_OF_SCOPES:
97 : break;
98 : }
99 : #undef CASE
100 0 : UNREACHABLE();
101 : return nullptr;
102 : }
103 :
104 159045 : GCTracer::Event::Event(Type type, GarbageCollectionReason gc_reason,
105 : const char* collector_reason)
106 : : type(type),
107 : gc_reason(gc_reason),
108 : collector_reason(collector_reason),
109 : start_time(0.0),
110 : end_time(0.0),
111 : reduce_memory(false),
112 : start_object_size(0),
113 : end_object_size(0),
114 : start_memory_size(0),
115 : end_memory_size(0),
116 : start_holes_size(0),
117 : end_holes_size(0),
118 : young_object_size(0),
119 : survived_young_object_size(0),
120 : incremental_marking_bytes(0),
121 1749495 : incremental_marking_duration(0.0) {
122 16540680 : for (int i = 0; i < Scope::NUMBER_OF_SCOPES; i++) {
123 16540680 : scopes[i] = 0;
124 : }
125 159045 : }
126 :
127 97980 : const char* GCTracer::Event::TypeName(bool short_name) const {
128 97980 : switch (type) {
129 : case SCAVENGER:
130 23474 : return (short_name) ? "s" : "Scavenge";
131 : case MARK_COMPACTOR:
132 : case INCREMENTAL_MARK_COMPACTOR:
133 74505 : return (short_name) ? "ms" : "Mark-sweep";
134 : case MINOR_MARK_COMPACTOR:
135 1 : return (short_name) ? "mmc" : "Minor Mark-Compact";
136 : case START:
137 0 : return (short_name) ? "st" : "Start";
138 : }
139 : return "Unknown Event Type";
140 : }
141 :
142 61049 : GCTracer::GCTracer(Heap* heap)
143 : : heap_(heap),
144 : current_(Event::START, GarbageCollectionReason::kUnknown, nullptr),
145 : previous_(current_),
146 : incremental_marking_bytes_(0),
147 : incremental_marking_duration_(0.0),
148 : incremental_marking_start_time_(0.0),
149 : recorded_incremental_marking_speed_(0.0),
150 : allocation_time_ms_(0.0),
151 : new_space_allocation_counter_bytes_(0),
152 : old_generation_allocation_counter_bytes_(0),
153 : allocation_duration_since_gc_(0.0),
154 : new_space_allocation_in_bytes_since_gc_(0),
155 : old_generation_allocation_in_bytes_since_gc_(0),
156 : combined_mark_compact_speed_cache_(0.0),
157 : start_counter_(0),
158 : average_mutator_duration_(0),
159 : average_mark_compact_duration_(0),
160 : current_mark_compact_mutator_utilization_(1.0),
161 1404127 : previous_mark_compact_end_time_(0) {
162 : // All accesses to incremental_marking_scope assume that incremental marking
163 : // scopes come first.
164 : STATIC_ASSERT(0 == Scope::FIRST_INCREMENTAL_SCOPE);
165 : // We assume that MC_INCREMENTAL is the first scope so that we can properly
166 : // map it to RuntimeCallStats.
167 : STATIC_ASSERT(0 == Scope::MC_INCREMENTAL);
168 61049 : current_.end_time = heap_->MonotonicallyIncreasingTimeInMs();
169 732588 : for (int i = 0; i < BackgroundScope::NUMBER_OF_SCOPES; i++) {
170 671539 : background_counter_[i].total_duration_ms = 0;
171 671539 : background_counter_[i].runtime_call_counter = RuntimeCallCounter(nullptr);
172 : }
173 61049 : }
174 :
175 16 : void GCTracer::ResetForTesting() {
176 16 : current_ = Event(Event::START, GarbageCollectionReason::kTesting, nullptr);
177 16 : current_.end_time = heap_->MonotonicallyIncreasingTimeInMs();
178 16 : previous_ = current_;
179 16 : ResetIncrementalMarkingCounters();
180 16 : allocation_time_ms_ = 0.0;
181 16 : new_space_allocation_counter_bytes_ = 0.0;
182 16 : old_generation_allocation_counter_bytes_ = 0.0;
183 16 : allocation_duration_since_gc_ = 0.0;
184 16 : new_space_allocation_in_bytes_since_gc_ = 0.0;
185 16 : old_generation_allocation_in_bytes_since_gc_ = 0.0;
186 16 : combined_mark_compact_speed_cache_ = 0.0;
187 : recorded_minor_gcs_total_.Reset();
188 : recorded_minor_gcs_survived_.Reset();
189 : recorded_compactions_.Reset();
190 : recorded_mark_compacts_.Reset();
191 : recorded_incremental_mark_compacts_.Reset();
192 : recorded_new_generation_allocations_.Reset();
193 : recorded_old_generation_allocations_.Reset();
194 : recorded_context_disposal_times_.Reset();
195 : recorded_survival_ratios_.Reset();
196 16 : start_counter_ = 0;
197 16 : average_mutator_duration_ = 0;
198 16 : average_mark_compact_duration_ = 0;
199 16 : current_mark_compact_mutator_utilization_ = 1.0;
200 16 : previous_mark_compact_end_time_ = 0;
201 16 : base::MutexGuard guard(&background_counter_mutex_);
202 192 : for (int i = 0; i < BackgroundScope::NUMBER_OF_SCOPES; i++) {
203 176 : background_counter_[i].total_duration_ms = 0;
204 176 : background_counter_[i].runtime_call_counter.Reset();
205 : }
206 16 : }
207 :
208 23490 : void GCTracer::NotifyYoungGenerationHandling(
209 : YoungGenerationHandling young_generation_handling) {
210 : DCHECK(current_.type == Event::SCAVENGER || start_counter_ > 1);
211 : heap_->isolate()->counters()->young_generation_handling()->AddSample(
212 46980 : static_cast<int>(young_generation_handling));
213 23490 : }
214 :
215 98012 : void GCTracer::Start(GarbageCollector collector,
216 : GarbageCollectionReason gc_reason,
217 : const char* collector_reason) {
218 98012 : start_counter_++;
219 196024 : if (start_counter_ != 1) return;
220 :
221 97980 : previous_ = current_;
222 391920 : double start_time = heap_->MonotonicallyIncreasingTimeInMs();
223 : SampleAllocation(start_time, heap_->NewSpaceAllocationCounter(),
224 195960 : heap_->OldGenerationAllocationCounter());
225 :
226 97980 : switch (collector) {
227 : case SCAVENGER:
228 23474 : current_ = Event(Event::SCAVENGER, gc_reason, collector_reason);
229 23474 : break;
230 : case MINOR_MARK_COMPACTOR:
231 : current_ =
232 1 : Event(Event::MINOR_MARK_COMPACTOR, gc_reason, collector_reason);
233 1 : break;
234 : case MARK_COMPACTOR:
235 149010 : if (heap_->incremental_marking()->WasActivated()) {
236 : current_ = Event(Event::INCREMENTAL_MARK_COMPACTOR, gc_reason,
237 24862 : collector_reason);
238 : } else {
239 49643 : current_ = Event(Event::MARK_COMPACTOR, gc_reason, collector_reason);
240 : }
241 : break;
242 : }
243 :
244 195960 : current_.reduce_memory = heap_->ShouldReduceMemory();
245 97980 : current_.start_time = start_time;
246 97980 : current_.start_object_size = heap_->SizeOfObjects();
247 195960 : current_.start_memory_size = heap_->memory_allocator()->Size();
248 97980 : current_.start_holes_size = CountTotalHolesSize(heap_);
249 : current_.young_object_size =
250 293940 : heap_->new_space()->Size() + heap_->new_lo_space()->SizeOfObjects();
251 :
252 97980 : current_.incremental_marking_bytes = 0;
253 97980 : current_.incremental_marking_duration = 0;
254 :
255 10287900 : for (int i = 0; i < Scope::NUMBER_OF_SCOPES; i++) {
256 10189920 : current_.scopes[i] = 0;
257 : }
258 :
259 97980 : Counters* counters = heap_->isolate()->counters();
260 :
261 97980 : if (Heap::IsYoungGenerationCollector(collector)) {
262 23475 : counters->scavenge_reason()->AddSample(static_cast<int>(gc_reason));
263 : } else {
264 74505 : counters->mark_compact_reason()->AddSample(static_cast<int>(gc_reason));
265 : }
266 : }
267 :
268 74521 : void GCTracer::ResetIncrementalMarkingCounters() {
269 74521 : if (incremental_marking_duration_ > 0) {
270 : heap_->isolate()->counters()->incremental_marking_sum()->AddSample(
271 41380 : static_cast<int>(incremental_marking_duration_));
272 : }
273 74521 : incremental_marking_bytes_ = 0;
274 74521 : incremental_marking_duration_ = 0;
275 819731 : for (int i = 0; i < Scope::NUMBER_OF_INCREMENTAL_SCOPES; i++) {
276 745210 : incremental_marking_scopes_[i].ResetCurrentCycle();
277 : }
278 74521 : }
279 :
280 98012 : void GCTracer::Stop(GarbageCollector collector) {
281 98012 : start_counter_--;
282 98012 : if (start_counter_ != 0) {
283 32 : if (FLAG_trace_gc_verbose) {
284 : heap_->isolate()->PrintWithTimestamp(
285 : "[Finished reentrant %s during %s.]\n",
286 97980 : Heap::CollectorName(collector), current_.TypeName(false));
287 : }
288 : return;
289 : }
290 :
291 : DCHECK_LE(0, start_counter_);
292 : DCHECK((collector == SCAVENGER && current_.type == Event::SCAVENGER) ||
293 : (collector == MINOR_MARK_COMPACTOR &&
294 : current_.type == Event::MINOR_MARK_COMPACTOR) ||
295 : (collector == MARK_COMPACTOR &&
296 : (current_.type == Event::MARK_COMPACTOR ||
297 : current_.type == Event::INCREMENTAL_MARK_COMPACTOR)));
298 :
299 97980 : current_.end_time = heap_->MonotonicallyIncreasingTimeInMs();
300 97980 : current_.end_object_size = heap_->SizeOfObjects();
301 195960 : current_.end_memory_size = heap_->memory_allocator()->Size();
302 97980 : current_.end_holes_size = CountTotalHolesSize(heap_);
303 195960 : current_.survived_young_object_size = heap_->SurvivedYoungObjectSize();
304 :
305 97980 : AddAllocation(current_.end_time);
306 :
307 97980 : double duration = current_.end_time - current_.start_time;
308 :
309 97980 : switch (current_.type) {
310 : case Event::SCAVENGER:
311 : case Event::MINOR_MARK_COMPACTOR:
312 : recorded_minor_gcs_total_.Push(
313 23475 : MakeBytesAndDuration(current_.young_object_size, duration));
314 : recorded_minor_gcs_survived_.Push(
315 23475 : MakeBytesAndDuration(current_.survived_young_object_size, duration));
316 23475 : FetchBackgroundMinorGCCounters();
317 23475 : break;
318 : case Event::INCREMENTAL_MARK_COMPACTOR:
319 24867 : current_.incremental_marking_bytes = incremental_marking_bytes_;
320 24867 : current_.incremental_marking_duration = incremental_marking_duration_;
321 273537 : for (int i = 0; i < Scope::NUMBER_OF_INCREMENTAL_SCOPES; i++) {
322 248670 : current_.incremental_marking_scopes[i] = incremental_marking_scopes_[i];
323 248670 : current_.scopes[i] = incremental_marking_scopes_[i].duration;
324 : }
325 :
326 : RecordMutatorUtilization(
327 24867 : current_.end_time, duration + current_.incremental_marking_duration);
328 : RecordIncrementalMarkingSpeed(current_.incremental_marking_bytes,
329 24867 : current_.incremental_marking_duration);
330 : recorded_incremental_mark_compacts_.Push(
331 24867 : MakeBytesAndDuration(current_.end_object_size, duration));
332 24867 : RecordGCSumCounters(duration);
333 24867 : ResetIncrementalMarkingCounters();
334 24867 : combined_mark_compact_speed_cache_ = 0.0;
335 24867 : FetchBackgroundMarkCompactCounters();
336 24867 : break;
337 : case Event::MARK_COMPACTOR:
338 : DCHECK_EQ(0u, current_.incremental_marking_bytes);
339 : DCHECK_EQ(0, current_.incremental_marking_duration);
340 : RecordMutatorUtilization(
341 49638 : current_.end_time, duration + current_.incremental_marking_duration);
342 : recorded_mark_compacts_.Push(
343 49638 : MakeBytesAndDuration(current_.end_object_size, duration));
344 49638 : RecordGCSumCounters(duration);
345 49638 : ResetIncrementalMarkingCounters();
346 49638 : combined_mark_compact_speed_cache_ = 0.0;
347 49638 : FetchBackgroundMarkCompactCounters();
348 49638 : break;
349 : case Event::START:
350 0 : UNREACHABLE();
351 : }
352 : FetchBackgroundGeneralCounters();
353 :
354 97980 : heap_->UpdateTotalGCTime(duration);
355 :
356 195960 : if ((current_.type == Event::SCAVENGER ||
357 97980 : current_.type == Event::MINOR_MARK_COMPACTOR) &&
358 : FLAG_trace_gc_ignore_scavenger)
359 : return;
360 :
361 97980 : if (FLAG_trace_gc_nvp) {
362 0 : PrintNVP();
363 : } else {
364 97980 : Print();
365 : }
366 :
367 97980 : if (FLAG_trace_gc) {
368 35 : heap_->PrintShortHeapStatistics();
369 : }
370 : }
371 :
372 :
373 529 : void GCTracer::SampleAllocation(double current_ms,
374 : size_t new_space_counter_bytes,
375 : size_t old_generation_counter_bytes) {
376 98509 : if (allocation_time_ms_ == 0) {
377 : // It is the first sample.
378 16053 : allocation_time_ms_ = current_ms;
379 16053 : new_space_allocation_counter_bytes_ = new_space_counter_bytes;
380 16053 : old_generation_allocation_counter_bytes_ = old_generation_counter_bytes;
381 579 : return;
382 : }
383 : // This assumes that counters are unsigned integers so that the subtraction
384 : // below works even if the new counter is less than the old counter.
385 : size_t new_space_allocated_bytes =
386 82456 : new_space_counter_bytes - new_space_allocation_counter_bytes_;
387 : size_t old_generation_allocated_bytes =
388 82456 : old_generation_counter_bytes - old_generation_allocation_counter_bytes_;
389 82456 : double duration = current_ms - allocation_time_ms_;
390 82456 : allocation_time_ms_ = current_ms;
391 82456 : new_space_allocation_counter_bytes_ = new_space_counter_bytes;
392 82456 : old_generation_allocation_counter_bytes_ = old_generation_counter_bytes;
393 82456 : allocation_duration_since_gc_ += duration;
394 82456 : new_space_allocation_in_bytes_since_gc_ += new_space_allocated_bytes;
395 : old_generation_allocation_in_bytes_since_gc_ +=
396 82456 : old_generation_allocated_bytes;
397 : }
398 :
399 :
400 97992 : void GCTracer::AddAllocation(double current_ms) {
401 97992 : allocation_time_ms_ = current_ms;
402 97992 : if (allocation_duration_since_gc_ > 0) {
403 : recorded_new_generation_allocations_.Push(
404 : MakeBytesAndDuration(new_space_allocation_in_bytes_since_gc_,
405 81985 : allocation_duration_since_gc_));
406 : recorded_old_generation_allocations_.Push(
407 : MakeBytesAndDuration(old_generation_allocation_in_bytes_since_gc_,
408 81985 : allocation_duration_since_gc_));
409 : }
410 97992 : allocation_duration_since_gc_ = 0;
411 97992 : new_space_allocation_in_bytes_since_gc_ = 0;
412 97992 : old_generation_allocation_in_bytes_since_gc_ = 0;
413 97992 : }
414 :
415 :
416 650 : void GCTracer::AddContextDisposalTime(double time) {
417 : recorded_context_disposal_times_.Push(time);
418 650 : }
419 :
420 77254 : void GCTracer::AddCompactionEvent(double duration,
421 : size_t live_bytes_compacted) {
422 : recorded_compactions_.Push(
423 77254 : MakeBytesAndDuration(live_bytes_compacted, duration));
424 77254 : }
425 :
426 :
427 84661 : void GCTracer::AddSurvivalRatio(double promotion_ratio) {
428 : recorded_survival_ratios_.Push(promotion_ratio);
429 84661 : }
430 :
431 1080881 : void GCTracer::AddIncrementalMarkingStep(double duration, size_t bytes) {
432 1080881 : if (bytes > 0) {
433 1025217 : incremental_marking_bytes_ += bytes;
434 1025217 : incremental_marking_duration_ += duration;
435 : }
436 1080881 : }
437 :
438 97980 : void GCTracer::Output(const char* format, ...) const {
439 97980 : if (FLAG_trace_gc) {
440 : va_list arguments;
441 35 : va_start(arguments, format);
442 35 : base::OS::VPrint(format, arguments);
443 35 : va_end(arguments);
444 : }
445 :
446 : const int kBufferSize = 256;
447 : char raw_buffer[kBufferSize];
448 : Vector<char> buffer(raw_buffer, kBufferSize);
449 : va_list arguments2;
450 97980 : va_start(arguments2, format);
451 97980 : VSNPrintF(buffer, format, arguments2);
452 97980 : va_end(arguments2);
453 :
454 97980 : heap_->AddToRingBuffer(buffer.start());
455 97980 : }
456 :
457 97980 : void GCTracer::Print() const {
458 97980 : double duration = current_.end_time - current_.start_time;
459 : const size_t kIncrementalStatsSize = 128;
460 97980 : char incremental_buffer[kIncrementalStatsSize] = {0};
461 :
462 97980 : if (current_.type == Event::INCREMENTAL_MARK_COMPACTOR) {
463 : base::OS::SNPrintF(
464 : incremental_buffer, kIncrementalStatsSize,
465 : " (+ %.1f ms in %d steps since start of marking, "
466 : "biggest step %.1f ms, walltime since start of marking %.f ms)",
467 24867 : current_.scopes[Scope::MC_INCREMENTAL],
468 : current_.incremental_marking_scopes[Scope::MC_INCREMENTAL].steps,
469 : current_.incremental_marking_scopes[Scope::MC_INCREMENTAL].longest_step,
470 49734 : current_.end_time - incremental_marking_start_time_);
471 : }
472 :
473 : // Avoid PrintF as Output also appends the string to the tracing ring buffer
474 : // that gets printed on OOM failures.
475 : Output(
476 : "[%d:%p] "
477 : "%8.0f ms: "
478 : "%s %.1f (%.1f) -> %.1f (%.1f) MB, "
479 : "%.1f / %.1f ms %s (average mu = %.3f, current mu = %.3f) %s %s\n",
480 : base::OS::GetCurrentProcessId(),
481 97980 : reinterpret_cast<void*>(heap_->isolate()),
482 : heap_->isolate()->time_millis_since_init(), current_.TypeName(false),
483 : static_cast<double>(current_.start_object_size) / MB,
484 : static_cast<double>(current_.start_memory_size) / MB,
485 : static_cast<double>(current_.end_object_size) / MB,
486 : static_cast<double>(current_.end_memory_size) / MB, duration,
487 : TotalExternalTime(), incremental_buffer,
488 : AverageMarkCompactMutatorUtilization(),
489 : CurrentMarkCompactMutatorUtilization(),
490 : Heap::GarbageCollectionReasonToString(current_.gc_reason),
491 293940 : current_.collector_reason != nullptr ? current_.collector_reason : "");
492 97980 : }
493 :
494 :
495 0 : void GCTracer::PrintNVP() const {
496 0 : double duration = current_.end_time - current_.start_time;
497 0 : double spent_in_mutator = current_.start_time - previous_.end_time;
498 : size_t allocated_since_last_gc =
499 0 : current_.start_object_size - previous_.end_object_size;
500 :
501 : double incremental_walltime_duration = 0;
502 :
503 0 : if (current_.type == Event::INCREMENTAL_MARK_COMPACTOR) {
504 : incremental_walltime_duration =
505 0 : current_.end_time - incremental_marking_start_time_;
506 : }
507 :
508 0 : switch (current_.type) {
509 : case Event::SCAVENGER:
510 : heap_->isolate()->PrintWithTimestamp(
511 : "pause=%.1f "
512 : "mutator=%.1f "
513 : "gc=%s "
514 : "reduce_memory=%d "
515 : "heap.prologue=%.2f "
516 : "heap.epilogue=%.2f "
517 : "heap.epilogue.reduce_new_space=%.2f "
518 : "heap.external.prologue=%.2f "
519 : "heap.external.epilogue=%.2f "
520 : "heap.external_weak_global_handles=%.2f "
521 : "fast_promote=%.2f "
522 : "scavenge=%.2f "
523 : "scavenge.process_array_buffers=%.2f "
524 : "scavenge.roots=%.2f "
525 : "scavenge.weak=%.2f "
526 : "scavenge.weak_global_handles.identify=%.2f "
527 : "scavenge.weak_global_handles.process=%.2f "
528 : "scavenge.parallel=%.2f "
529 : "scavenge.update_refs=%.2f "
530 : "background.scavenge.parallel=%.2f "
531 : "background.array_buffer_free=%.2f "
532 : "background.store_buffer=%.2f "
533 : "background.unmapper=%.2f "
534 : "incremental.steps_count=%d "
535 : "incremental.steps_took=%.1f "
536 : "scavenge_throughput=%.f "
537 : "total_size_before=%" PRIuS
538 : " "
539 : "total_size_after=%" PRIuS
540 : " "
541 : "holes_size_before=%" PRIuS
542 : " "
543 : "holes_size_after=%" PRIuS
544 : " "
545 : "allocated=%" PRIuS
546 : " "
547 : "promoted=%" PRIuS
548 : " "
549 : "semi_space_copied=%" PRIuS
550 : " "
551 : "nodes_died_in_new=%d "
552 : "nodes_copied_in_new=%d "
553 : "nodes_promoted=%d "
554 : "promotion_ratio=%.1f%% "
555 : "average_survival_ratio=%.1f%% "
556 : "promotion_rate=%.1f%% "
557 : "semi_space_copy_rate=%.1f%% "
558 : "new_space_allocation_throughput=%.1f "
559 : "unmapper_chunks=%d "
560 : "context_disposal_rate=%.1f\n",
561 : duration, spent_in_mutator, current_.TypeName(true),
562 0 : current_.reduce_memory, current_.scopes[Scope::HEAP_PROLOGUE],
563 0 : current_.scopes[Scope::HEAP_EPILOGUE],
564 0 : current_.scopes[Scope::HEAP_EPILOGUE_REDUCE_NEW_SPACE],
565 0 : current_.scopes[Scope::HEAP_EXTERNAL_PROLOGUE],
566 0 : current_.scopes[Scope::HEAP_EXTERNAL_EPILOGUE],
567 0 : current_.scopes[Scope::HEAP_EXTERNAL_WEAK_GLOBAL_HANDLES],
568 0 : current_.scopes[Scope::SCAVENGER_FAST_PROMOTE],
569 0 : current_.scopes[Scope::SCAVENGER_SCAVENGE],
570 0 : current_.scopes[Scope::SCAVENGER_PROCESS_ARRAY_BUFFERS],
571 0 : current_.scopes[Scope::SCAVENGER_SCAVENGE_ROOTS],
572 0 : current_.scopes[Scope::SCAVENGER_SCAVENGE_WEAK],
573 : current_
574 0 : .scopes[Scope::SCAVENGER_SCAVENGE_WEAK_GLOBAL_HANDLES_IDENTIFY],
575 : current_
576 0 : .scopes[Scope::SCAVENGER_SCAVENGE_WEAK_GLOBAL_HANDLES_PROCESS],
577 0 : current_.scopes[Scope::SCAVENGER_SCAVENGE_PARALLEL],
578 0 : current_.scopes[Scope::SCAVENGER_SCAVENGE_UPDATE_REFS],
579 0 : current_.scopes[Scope::SCAVENGER_BACKGROUND_SCAVENGE_PARALLEL],
580 0 : current_.scopes[Scope::BACKGROUND_ARRAY_BUFFER_FREE],
581 0 : current_.scopes[Scope::BACKGROUND_STORE_BUFFER],
582 0 : current_.scopes[Scope::BACKGROUND_UNMAPPER],
583 : current_.incremental_marking_scopes[GCTracer::Scope::MC_INCREMENTAL]
584 : .steps,
585 0 : current_.scopes[Scope::MC_INCREMENTAL],
586 : ScavengeSpeedInBytesPerMillisecond(), current_.start_object_size,
587 : current_.end_object_size, current_.start_holes_size,
588 : current_.end_holes_size, allocated_since_last_gc,
589 : heap_->promoted_objects_size(),
590 : heap_->semi_space_copied_object_size(),
591 : heap_->nodes_died_in_new_space_, heap_->nodes_copied_in_new_space_,
592 : heap_->nodes_promoted_, heap_->promotion_ratio_,
593 : AverageSurvivalRatio(), heap_->promotion_rate_,
594 : heap_->semi_space_copied_rate_,
595 : NewSpaceAllocationThroughputInBytesPerMillisecond(),
596 : heap_->memory_allocator()->unmapper()->NumberOfChunks(),
597 0 : ContextDisposalRateInMilliseconds());
598 0 : break;
599 : case Event::MINOR_MARK_COMPACTOR:
600 : heap_->isolate()->PrintWithTimestamp(
601 : "pause=%.1f "
602 : "mutator=%.1f "
603 : "gc=%s "
604 : "reduce_memory=%d "
605 : "minor_mc=%.2f "
606 : "finish_sweeping=%.2f "
607 : "mark=%.2f "
608 : "mark.seed=%.2f "
609 : "mark.roots=%.2f "
610 : "mark.weak=%.2f "
611 : "mark.global_handles=%.2f "
612 : "clear=%.2f "
613 : "clear.string_table=%.2f "
614 : "clear.weak_lists=%.2f "
615 : "evacuate=%.2f "
616 : "evacuate.copy=%.2f "
617 : "evacuate.update_pointers=%.2f "
618 : "evacuate.update_pointers.to_new_roots=%.2f "
619 : "evacuate.update_pointers.slots=%.2f "
620 : "background.mark=%.2f "
621 : "background.evacuate.copy=%.2f "
622 : "background.evacuate.update_pointers=%.2f "
623 : "background.array_buffer_free=%.2f "
624 : "background.store_buffer=%.2f "
625 : "background.unmapper=%.2f "
626 : "update_marking_deque=%.2f "
627 : "reset_liveness=%.2f\n",
628 : duration, spent_in_mutator, "mmc", current_.reduce_memory,
629 0 : current_.scopes[Scope::MINOR_MC],
630 0 : current_.scopes[Scope::MINOR_MC_SWEEPING],
631 0 : current_.scopes[Scope::MINOR_MC_MARK],
632 0 : current_.scopes[Scope::MINOR_MC_MARK_SEED],
633 0 : current_.scopes[Scope::MINOR_MC_MARK_ROOTS],
634 0 : current_.scopes[Scope::MINOR_MC_MARK_WEAK],
635 0 : current_.scopes[Scope::MINOR_MC_MARK_GLOBAL_HANDLES],
636 0 : current_.scopes[Scope::MINOR_MC_CLEAR],
637 0 : current_.scopes[Scope::MINOR_MC_CLEAR_STRING_TABLE],
638 0 : current_.scopes[Scope::MINOR_MC_CLEAR_WEAK_LISTS],
639 0 : current_.scopes[Scope::MINOR_MC_EVACUATE],
640 0 : current_.scopes[Scope::MINOR_MC_EVACUATE_COPY],
641 0 : current_.scopes[Scope::MINOR_MC_EVACUATE_UPDATE_POINTERS],
642 : current_
643 0 : .scopes[Scope::MINOR_MC_EVACUATE_UPDATE_POINTERS_TO_NEW_ROOTS],
644 0 : current_.scopes[Scope::MINOR_MC_EVACUATE_UPDATE_POINTERS_SLOTS],
645 0 : current_.scopes[Scope::MINOR_MC_BACKGROUND_MARKING],
646 0 : current_.scopes[Scope::MINOR_MC_BACKGROUND_EVACUATE_COPY],
647 0 : current_.scopes[Scope::MINOR_MC_BACKGROUND_EVACUATE_UPDATE_POINTERS],
648 0 : current_.scopes[Scope::BACKGROUND_ARRAY_BUFFER_FREE],
649 0 : current_.scopes[Scope::BACKGROUND_STORE_BUFFER],
650 0 : current_.scopes[Scope::BACKGROUND_UNMAPPER],
651 0 : current_.scopes[Scope::MINOR_MC_MARKING_DEQUE],
652 0 : current_.scopes[Scope::MINOR_MC_RESET_LIVENESS]);
653 0 : break;
654 : case Event::MARK_COMPACTOR:
655 : case Event::INCREMENTAL_MARK_COMPACTOR:
656 : heap_->isolate()->PrintWithTimestamp(
657 : "pause=%.1f "
658 : "mutator=%.1f "
659 : "gc=%s "
660 : "reduce_memory=%d "
661 : "heap.prologue=%.2f "
662 : "heap.embedder_tracing_epilogue=%.2f "
663 : "heap.epilogue=%.2f "
664 : "heap.epilogue.reduce_new_space=%.2f "
665 : "heap.external.prologue=%.1f "
666 : "heap.external.epilogue=%.1f "
667 : "heap.external.weak_global_handles=%.1f "
668 : "clear=%1.f "
669 : "clear.dependent_code=%.1f "
670 : "clear.maps=%.1f "
671 : "clear.slots_buffer=%.1f "
672 : "clear.store_buffer=%.1f "
673 : "clear.string_table=%.1f "
674 : "clear.weak_collections=%.1f "
675 : "clear.weak_lists=%.1f "
676 : "clear.weak_references=%.1f "
677 : "epilogue=%.1f "
678 : "evacuate=%.1f "
679 : "evacuate.candidates=%.1f "
680 : "evacuate.clean_up=%.1f "
681 : "evacuate.copy=%.1f "
682 : "evacuate.prologue=%.1f "
683 : "evacuate.epilogue=%.1f "
684 : "evacuate.rebalance=%.1f "
685 : "evacuate.update_pointers=%.1f "
686 : "evacuate.update_pointers.to_new_roots=%.1f "
687 : "evacuate.update_pointers.slots.main=%.1f "
688 : "evacuate.update_pointers.slots.map_space=%.1f "
689 : "evacuate.update_pointers.weak=%.1f "
690 : "finish=%.1f "
691 : "mark=%.1f "
692 : "mark.finish_incremental=%.1f "
693 : "mark.roots=%.1f "
694 : "mark.main=%.1f "
695 : "mark.weak_closure=%.1f "
696 : "mark.weak_closure.ephemeron=%.1f "
697 : "mark.weak_closure.ephemeron.marking=%.1f "
698 : "mark.weak_closure.ephemeron.linear=%.1f "
699 : "mark.weak_closure.weak_handles=%.1f "
700 : "mark.weak_closure.weak_roots=%.1f "
701 : "mark.weak_closure.harmony=%.1f "
702 : "mark.embedder_prologue=%.1f "
703 : "mark.embedder_tracing=%.1f "
704 : "prologue=%.1f "
705 : "sweep=%.1f "
706 : "sweep.code=%.1f "
707 : "sweep.map=%.1f "
708 : "sweep.old=%.1f "
709 : "incremental=%.1f "
710 : "incremental.finalize=%.1f "
711 : "incremental.finalize.body=%.1f "
712 : "incremental.finalize.external.prologue=%.1f "
713 : "incremental.finalize.external.epilogue=%.1f "
714 : "incremental.layout_change=%.1f "
715 : "incremental.start=%.1f "
716 : "incremental.sweeping=%.1f "
717 : "incremental.embedder_prologue=%.1f "
718 : "incremental.embedder_tracing=%.1f "
719 : "incremental_wrapper_tracing_longest_step=%.1f "
720 : "incremental_finalize_longest_step=%.1f "
721 : "incremental_finalize_steps_count=%d "
722 : "incremental_longest_step=%.1f "
723 : "incremental_steps_count=%d "
724 : "incremental_marking_throughput=%.f "
725 : "incremental_walltime_duration=%.f "
726 : "background.mark=%.1f "
727 : "background.sweep=%.1f "
728 : "background.evacuate.copy=%.1f "
729 : "background.evacuate.update_pointers=%.1f "
730 : "background.array_buffer_free=%.2f "
731 : "background.store_buffer=%.2f "
732 : "background.unmapper=%.1f "
733 : "total_size_before=%" PRIuS
734 : " "
735 : "total_size_after=%" PRIuS
736 : " "
737 : "holes_size_before=%" PRIuS
738 : " "
739 : "holes_size_after=%" PRIuS
740 : " "
741 : "allocated=%" PRIuS
742 : " "
743 : "promoted=%" PRIuS
744 : " "
745 : "semi_space_copied=%" PRIuS
746 : " "
747 : "nodes_died_in_new=%d "
748 : "nodes_copied_in_new=%d "
749 : "nodes_promoted=%d "
750 : "promotion_ratio=%.1f%% "
751 : "average_survival_ratio=%.1f%% "
752 : "promotion_rate=%.1f%% "
753 : "semi_space_copy_rate=%.1f%% "
754 : "new_space_allocation_throughput=%.1f "
755 : "unmapper_chunks=%d "
756 : "context_disposal_rate=%.1f "
757 : "compaction_speed=%.f\n",
758 : duration, spent_in_mutator, current_.TypeName(true),
759 0 : current_.reduce_memory, current_.scopes[Scope::HEAP_PROLOGUE],
760 0 : current_.scopes[Scope::HEAP_EMBEDDER_TRACING_EPILOGUE],
761 0 : current_.scopes[Scope::HEAP_EPILOGUE],
762 0 : current_.scopes[Scope::HEAP_EPILOGUE_REDUCE_NEW_SPACE],
763 0 : current_.scopes[Scope::HEAP_EXTERNAL_PROLOGUE],
764 0 : current_.scopes[Scope::HEAP_EXTERNAL_EPILOGUE],
765 0 : current_.scopes[Scope::HEAP_EXTERNAL_WEAK_GLOBAL_HANDLES],
766 0 : current_.scopes[Scope::MC_CLEAR],
767 0 : current_.scopes[Scope::MC_CLEAR_DEPENDENT_CODE],
768 0 : current_.scopes[Scope::MC_CLEAR_MAPS],
769 0 : current_.scopes[Scope::MC_CLEAR_SLOTS_BUFFER],
770 0 : current_.scopes[Scope::MC_CLEAR_STORE_BUFFER],
771 0 : current_.scopes[Scope::MC_CLEAR_STRING_TABLE],
772 0 : current_.scopes[Scope::MC_CLEAR_WEAK_COLLECTIONS],
773 0 : current_.scopes[Scope::MC_CLEAR_WEAK_LISTS],
774 0 : current_.scopes[Scope::MC_CLEAR_WEAK_REFERENCES],
775 0 : current_.scopes[Scope::MC_EPILOGUE],
776 0 : current_.scopes[Scope::MC_EVACUATE],
777 0 : current_.scopes[Scope::MC_EVACUATE_CANDIDATES],
778 0 : current_.scopes[Scope::MC_EVACUATE_CLEAN_UP],
779 0 : current_.scopes[Scope::MC_EVACUATE_COPY],
780 0 : current_.scopes[Scope::MC_EVACUATE_PROLOGUE],
781 0 : current_.scopes[Scope::MC_EVACUATE_EPILOGUE],
782 0 : current_.scopes[Scope::MC_EVACUATE_REBALANCE],
783 0 : current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS],
784 0 : current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS_TO_NEW_ROOTS],
785 0 : current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS_SLOTS_MAIN],
786 0 : current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS_SLOTS_MAP_SPACE],
787 0 : current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS_WEAK],
788 0 : current_.scopes[Scope::MC_FINISH], current_.scopes[Scope::MC_MARK],
789 0 : current_.scopes[Scope::MC_MARK_FINISH_INCREMENTAL],
790 0 : current_.scopes[Scope::MC_MARK_ROOTS],
791 0 : current_.scopes[Scope::MC_MARK_MAIN],
792 0 : current_.scopes[Scope::MC_MARK_WEAK_CLOSURE],
793 0 : current_.scopes[Scope::MC_MARK_WEAK_CLOSURE_EPHEMERON],
794 0 : current_.scopes[Scope::MC_MARK_WEAK_CLOSURE_EPHEMERON_MARKING],
795 0 : current_.scopes[Scope::MC_MARK_WEAK_CLOSURE_EPHEMERON_LINEAR],
796 0 : current_.scopes[Scope::MC_MARK_WEAK_CLOSURE_WEAK_HANDLES],
797 0 : current_.scopes[Scope::MC_MARK_WEAK_CLOSURE_WEAK_ROOTS],
798 0 : current_.scopes[Scope::MC_MARK_WEAK_CLOSURE_HARMONY],
799 0 : current_.scopes[Scope::MC_MARK_EMBEDDER_PROLOGUE],
800 0 : current_.scopes[Scope::MC_MARK_EMBEDDER_TRACING],
801 0 : current_.scopes[Scope::MC_PROLOGUE], current_.scopes[Scope::MC_SWEEP],
802 0 : current_.scopes[Scope::MC_SWEEP_CODE],
803 0 : current_.scopes[Scope::MC_SWEEP_MAP],
804 0 : current_.scopes[Scope::MC_SWEEP_OLD],
805 0 : current_.scopes[Scope::MC_INCREMENTAL],
806 0 : current_.scopes[Scope::MC_INCREMENTAL_FINALIZE],
807 0 : current_.scopes[Scope::MC_INCREMENTAL_FINALIZE_BODY],
808 0 : current_.scopes[Scope::MC_INCREMENTAL_EXTERNAL_PROLOGUE],
809 0 : current_.scopes[Scope::MC_INCREMENTAL_EXTERNAL_EPILOGUE],
810 0 : current_.scopes[Scope::MC_INCREMENTAL_LAYOUT_CHANGE],
811 0 : current_.scopes[Scope::MC_INCREMENTAL_START],
812 0 : current_.scopes[Scope::MC_INCREMENTAL_SWEEPING],
813 0 : current_.scopes[Scope::MC_INCREMENTAL_EMBEDDER_PROLOGUE],
814 0 : current_.scopes[Scope::MC_INCREMENTAL_EMBEDDER_TRACING],
815 : current_
816 : .incremental_marking_scopes
817 : [Scope::MC_INCREMENTAL_EMBEDDER_TRACING]
818 : .longest_step,
819 : current_
820 : .incremental_marking_scopes[Scope::MC_INCREMENTAL_FINALIZE_BODY]
821 : .longest_step,
822 : current_
823 : .incremental_marking_scopes[Scope::MC_INCREMENTAL_FINALIZE_BODY]
824 : .steps,
825 : current_.incremental_marking_scopes[Scope::MC_INCREMENTAL]
826 : .longest_step,
827 : current_.incremental_marking_scopes[Scope::MC_INCREMENTAL].steps,
828 : IncrementalMarkingSpeedInBytesPerMillisecond(),
829 : incremental_walltime_duration,
830 0 : current_.scopes[Scope::MC_BACKGROUND_MARKING],
831 0 : current_.scopes[Scope::MC_BACKGROUND_SWEEPING],
832 0 : current_.scopes[Scope::MC_BACKGROUND_EVACUATE_COPY],
833 0 : current_.scopes[Scope::MC_BACKGROUND_EVACUATE_UPDATE_POINTERS],
834 0 : current_.scopes[Scope::BACKGROUND_ARRAY_BUFFER_FREE],
835 0 : current_.scopes[Scope::BACKGROUND_STORE_BUFFER],
836 0 : current_.scopes[Scope::BACKGROUND_UNMAPPER],
837 : current_.start_object_size, current_.end_object_size,
838 : current_.start_holes_size, current_.end_holes_size,
839 : allocated_since_last_gc, heap_->promoted_objects_size(),
840 : heap_->semi_space_copied_object_size(),
841 : heap_->nodes_died_in_new_space_, heap_->nodes_copied_in_new_space_,
842 : heap_->nodes_promoted_, heap_->promotion_ratio_,
843 : AverageSurvivalRatio(), heap_->promotion_rate_,
844 : heap_->semi_space_copied_rate_,
845 : NewSpaceAllocationThroughputInBytesPerMillisecond(),
846 : heap_->memory_allocator()->unmapper()->NumberOfChunks(),
847 : ContextDisposalRateInMilliseconds(),
848 0 : CompactionSpeedInBytesPerMillisecond());
849 0 : break;
850 : case Event::START:
851 : break;
852 : default:
853 0 : UNREACHABLE();
854 : }
855 0 : }
856 :
857 645671 : double GCTracer::AverageSpeed(const base::RingBuffer<BytesAndDuration>& buffer,
858 : const BytesAndDuration& initial, double time_ms) {
859 : BytesAndDuration sum = buffer.Sum(
860 : [time_ms](BytesAndDuration a, BytesAndDuration b) {
861 3158762 : if (time_ms != 0 && a.second >= time_ms) return a;
862 3156754 : return std::make_pair(a.first + b.first, a.second + b.second);
863 : },
864 645671 : initial);
865 645671 : uint64_t bytes = sum.first;
866 645671 : double durations = sum.second;
867 645671 : if (durations == 0.0) return 0;
868 453923 : double speed = bytes / durations;
869 : const int max_speed = 1024 * MB;
870 : const int min_speed = 1;
871 453923 : if (speed >= max_speed) return max_speed;
872 453919 : if (speed <= min_speed) return min_speed;
873 414064 : return speed;
874 : }
875 :
876 0 : double GCTracer::AverageSpeed(
877 : const base::RingBuffer<BytesAndDuration>& buffer) {
878 328109 : return AverageSpeed(buffer, MakeBytesAndDuration(0, 0), 0);
879 : }
880 :
881 0 : void GCTracer::RecordIncrementalMarkingSpeed(size_t bytes, double duration) {
882 24867 : if (duration == 0 || bytes == 0) return;
883 20690 : double current_speed = bytes / duration;
884 20690 : if (recorded_incremental_marking_speed_ == 0) {
885 9567 : recorded_incremental_marking_speed_ = current_speed;
886 : } else {
887 : recorded_incremental_marking_speed_ =
888 11123 : (recorded_incremental_marking_speed_ + current_speed) / 2;
889 : }
890 : }
891 :
892 74509 : void GCTracer::RecordMutatorUtilization(double mark_compact_end_time,
893 : double mark_compact_duration) {
894 74509 : if (previous_mark_compact_end_time_ == 0) {
895 : // The first event only contributes to previous_mark_compact_end_time_,
896 : // because we cannot compute the mutator duration.
897 14343 : previous_mark_compact_end_time_ = mark_compact_end_time;
898 : } else {
899 : double total_duration =
900 60166 : mark_compact_end_time - previous_mark_compact_end_time_;
901 60166 : double mutator_duration = total_duration - mark_compact_duration;
902 60166 : if (average_mark_compact_duration_ == 0 && average_mutator_duration_ == 0) {
903 : // This is the first event with mutator and mark-compact durations.
904 7152 : average_mark_compact_duration_ = mark_compact_duration;
905 7152 : average_mutator_duration_ = mutator_duration;
906 : } else {
907 : average_mark_compact_duration_ =
908 53014 : (average_mark_compact_duration_ + mark_compact_duration) / 2;
909 : average_mutator_duration_ =
910 53014 : (average_mutator_duration_ + mutator_duration) / 2;
911 : }
912 : current_mark_compact_mutator_utilization_ =
913 60166 : total_duration ? mutator_duration / total_duration : 0;
914 60166 : previous_mark_compact_end_time_ = mark_compact_end_time;
915 : }
916 74509 : }
917 :
918 74514 : double GCTracer::AverageMarkCompactMutatorUtilization() const {
919 : double average_total_duration =
920 172494 : average_mark_compact_duration_ + average_mutator_duration_;
921 172494 : if (average_total_duration == 0) return 1.0;
922 117532 : return average_mutator_duration_ / average_total_duration;
923 : }
924 :
925 4 : double GCTracer::CurrentMarkCompactMutatorUtilization() const {
926 97984 : return current_mark_compact_mutator_utilization_;
927 : }
928 :
929 1073364 : double GCTracer::IncrementalMarkingSpeedInBytesPerMillisecond() const {
930 : const int kConservativeSpeedInBytesPerMillisecond = 128 * KB;
931 1115733 : if (recorded_incremental_marking_speed_ != 0) {
932 : return recorded_incremental_marking_speed_;
933 : }
934 194948 : if (incremental_marking_duration_ != 0.0) {
935 159707 : return incremental_marking_bytes_ / incremental_marking_duration_;
936 : }
937 : return kConservativeSpeedInBytesPerMillisecond;
938 : }
939 :
940 27472 : double GCTracer::ScavengeSpeedInBytesPerMillisecond(
941 : ScavengeSpeedMode mode) const {
942 27472 : if (mode == kForAllObjects) {
943 7890 : return AverageSpeed(recorded_minor_gcs_total_);
944 : } else {
945 47054 : return AverageSpeed(recorded_minor_gcs_survived_);
946 : }
947 : }
948 :
949 133238 : double GCTracer::CompactionSpeedInBytesPerMillisecond() const {
950 266476 : return AverageSpeed(recorded_compactions_);
951 : }
952 :
953 0 : double GCTracer::MarkCompactSpeedInBytesPerMillisecond() const {
954 92729 : return AverageSpeed(recorded_mark_compacts_);
955 : }
956 :
957 0 : double GCTracer::FinalIncrementalMarkCompactSpeedInBytesPerMillisecond() const {
958 42369 : return AverageSpeed(recorded_incremental_mark_compacts_);
959 : }
960 :
961 98018 : double GCTracer::CombinedMarkCompactSpeedInBytesPerMillisecond() {
962 : const double kMinimumMarkingSpeed = 0.5;
963 98018 : if (combined_mark_compact_speed_cache_ > 0)
964 : return combined_mark_compact_speed_cache_;
965 : // MarkCompact speed is more stable than incremental marking speed, because
966 : // there might not be many incremental marking steps because of concurrent
967 : // marking.
968 92729 : combined_mark_compact_speed_cache_ = MarkCompactSpeedInBytesPerMillisecond();
969 92729 : if (combined_mark_compact_speed_cache_ > 0)
970 : return combined_mark_compact_speed_cache_;
971 : double speed1 = IncrementalMarkingSpeedInBytesPerMillisecond();
972 : double speed2 = FinalIncrementalMarkCompactSpeedInBytesPerMillisecond();
973 42369 : if (speed1 < kMinimumMarkingSpeed || speed2 < kMinimumMarkingSpeed) {
974 : // No data for the incremental marking speed.
975 : // Return the non-incremental mark-compact speed.
976 : combined_mark_compact_speed_cache_ =
977 32301 : MarkCompactSpeedInBytesPerMillisecond();
978 : } else {
979 : // Combine the speed of incremental step and the speed of the final step.
980 : // 1 / (1 / speed1 + 1 / speed2) = speed1 * speed2 / (speed1 + speed2).
981 10068 : combined_mark_compact_speed_cache_ = speed1 * speed2 / (speed1 + speed2);
982 : }
983 42369 : return combined_mark_compact_speed_cache_;
984 : }
985 :
986 23531 : double GCTracer::NewSpaceAllocationThroughputInBytesPerMillisecond(
987 : double time_ms) const {
988 121533 : size_t bytes = new_space_allocation_in_bytes_since_gc_;
989 121533 : double durations = allocation_duration_since_gc_;
990 : return AverageSpeed(recorded_new_generation_allocations_,
991 121533 : MakeBytesAndDuration(bytes, durations), time_ms);
992 : }
993 :
994 20 : double GCTracer::OldGenerationAllocationThroughputInBytesPerMillisecond(
995 : double time_ms) const {
996 196022 : size_t bytes = old_generation_allocation_in_bytes_since_gc_;
997 196022 : double durations = allocation_duration_since_gc_;
998 : return AverageSpeed(recorded_old_generation_allocations_,
999 196022 : MakeBytesAndDuration(bytes, durations), time_ms);
1000 : }
1001 :
1002 98002 : double GCTracer::AllocationThroughputInBytesPerMillisecond(
1003 : double time_ms) const {
1004 : return NewSpaceAllocationThroughputInBytesPerMillisecond(time_ms) +
1005 98002 : OldGenerationAllocationThroughputInBytesPerMillisecond(time_ms);
1006 : }
1007 :
1008 98000 : double GCTracer::CurrentAllocationThroughputInBytesPerMillisecond() const {
1009 98000 : return AllocationThroughputInBytesPerMillisecond(kThroughputTimeFrameMs);
1010 : }
1011 :
1012 98000 : double GCTracer::CurrentOldGenerationAllocationThroughputInBytesPerMillisecond()
1013 : const {
1014 : return OldGenerationAllocationThroughputInBytesPerMillisecond(
1015 98000 : kThroughputTimeFrameMs);
1016 : }
1017 :
1018 479 : double GCTracer::ContextDisposalRateInMilliseconds() const {
1019 479 : if (recorded_context_disposal_times_.Count() <
1020 : recorded_context_disposal_times_.kSize)
1021 : return 0.0;
1022 198 : double begin = heap_->MonotonicallyIncreasingTimeInMs();
1023 : double end = recorded_context_disposal_times_.Sum(
1024 : [](double a, double b) { return b; }, 0.0);
1025 198 : return (begin - end) / recorded_context_disposal_times_.Count();
1026 : }
1027 :
1028 7276 : double GCTracer::AverageSurvivalRatio() const {
1029 7276 : if (recorded_survival_ratios_.Count() == 0) return 0.0;
1030 : double sum = recorded_survival_ratios_.Sum(
1031 22981 : [](double a, double b) { return a + b; }, 0.0);
1032 7276 : return sum / recorded_survival_ratios_.Count();
1033 : }
1034 :
1035 7306 : bool GCTracer::SurvivalEventsRecorded() const {
1036 7306 : return recorded_survival_ratios_.Count() > 0;
1037 : }
1038 :
1039 20 : void GCTracer::ResetSurvivalEvents() { recorded_survival_ratios_.Reset(); }
1040 :
1041 30410 : void GCTracer::NotifyIncrementalMarkingStart() {
1042 30410 : incremental_marking_start_time_ = heap_->MonotonicallyIncreasingTimeInMs();
1043 30410 : }
1044 :
1045 74507 : void GCTracer::FetchBackgroundMarkCompactCounters() {
1046 : FetchBackgroundCounters(Scope::FIRST_MC_BACKGROUND_SCOPE,
1047 : Scope::LAST_MC_BACKGROUND_SCOPE,
1048 : BackgroundScope::FIRST_MC_BACKGROUND_SCOPE,
1049 74507 : BackgroundScope::LAST_MC_BACKGROUND_SCOPE);
1050 : heap_->isolate()->counters()->background_marking()->AddSample(
1051 149014 : static_cast<int>(current_.scopes[Scope::MC_BACKGROUND_MARKING]));
1052 : heap_->isolate()->counters()->background_sweeping()->AddSample(
1053 149014 : static_cast<int>(current_.scopes[Scope::MC_BACKGROUND_SWEEPING]));
1054 74507 : }
1055 :
1056 23475 : void GCTracer::FetchBackgroundMinorGCCounters() {
1057 : FetchBackgroundCounters(Scope::FIRST_MINOR_GC_BACKGROUND_SCOPE,
1058 : Scope::LAST_MINOR_GC_BACKGROUND_SCOPE,
1059 : BackgroundScope::FIRST_MINOR_GC_BACKGROUND_SCOPE,
1060 23475 : BackgroundScope::LAST_MINOR_GC_BACKGROUND_SCOPE);
1061 : heap_->isolate()->counters()->background_scavenger()->AddSample(
1062 : static_cast<int>(
1063 46950 : current_.scopes[Scope::SCAVENGER_BACKGROUND_SCAVENGE_PARALLEL]));
1064 23475 : }
1065 :
1066 0 : void GCTracer::FetchBackgroundGeneralCounters() {
1067 : FetchBackgroundCounters(Scope::FIRST_GENERAL_BACKGROUND_SCOPE,
1068 : Scope::LAST_GENERAL_BACKGROUND_SCOPE,
1069 : BackgroundScope::FIRST_GENERAL_BACKGROUND_SCOPE,
1070 97980 : BackgroundScope::LAST_GENERAL_BACKGROUND_SCOPE);
1071 0 : }
1072 :
1073 195962 : void GCTracer::FetchBackgroundCounters(int first_global_scope,
1074 : int last_global_scope,
1075 : int first_background_scope,
1076 : int last_background_scope) {
1077 : DCHECK_EQ(last_global_scope - first_global_scope,
1078 : last_background_scope - first_background_scope);
1079 195962 : base::MutexGuard guard(&background_counter_mutex_);
1080 195962 : int background_mc_scopes = last_background_scope - first_background_scope + 1;
1081 881830 : for (int i = 0; i < background_mc_scopes; i++) {
1082 : current_.scopes[first_global_scope + i] +=
1083 685868 : background_counter_[first_background_scope + i].total_duration_ms;
1084 685868 : background_counter_[first_background_scope + i].total_duration_ms = 0;
1085 : }
1086 195962 : if (V8_LIKELY(!FLAG_runtime_stats)) return;
1087 : RuntimeCallStats* runtime_stats =
1088 0 : heap_->isolate()->counters()->runtime_call_stats();
1089 0 : if (!runtime_stats) return;
1090 0 : for (int i = 0; i < background_mc_scopes; i++) {
1091 : runtime_stats
1092 : ->GetCounter(GCTracer::RCSCounterFromScope(
1093 0 : static_cast<Scope::ScopeId>(first_global_scope + i)))
1094 0 : ->Add(&background_counter_[first_background_scope + i]
1095 0 : .runtime_call_counter);
1096 : background_counter_[first_background_scope + i]
1097 0 : .runtime_call_counter.Reset();
1098 : }
1099 : }
1100 :
1101 1414171 : void GCTracer::AddBackgroundScopeSample(
1102 : BackgroundScope::ScopeId scope, double duration,
1103 : RuntimeCallCounter* runtime_call_counter) {
1104 1414171 : base::MutexGuard guard(&background_counter_mutex_);
1105 1416957 : BackgroundCounter& counter = background_counter_[scope];
1106 1416957 : counter.total_duration_ms += duration;
1107 1416957 : if (runtime_call_counter) {
1108 0 : counter.runtime_call_counter.Add(runtime_call_counter);
1109 : }
1110 1416831 : }
1111 :
1112 98002 : void GCTracer::RecordGCPhasesHistograms(TimedHistogram* gc_timer) {
1113 98002 : Counters* counters = heap_->isolate()->counters();
1114 98002 : if (gc_timer == counters->gc_finalize()) {
1115 : DCHECK_EQ(Scope::FIRST_TOP_MC_SCOPE, Scope::MC_CLEAR);
1116 : counters->gc_finalize_clear()->AddSample(
1117 22305 : static_cast<int>(current_.scopes[Scope::MC_CLEAR]));
1118 : counters->gc_finalize_epilogue()->AddSample(
1119 22305 : static_cast<int>(current_.scopes[Scope::MC_EPILOGUE]));
1120 : counters->gc_finalize_evacuate()->AddSample(
1121 22305 : static_cast<int>(current_.scopes[Scope::MC_EVACUATE]));
1122 : counters->gc_finalize_finish()->AddSample(
1123 22305 : static_cast<int>(current_.scopes[Scope::MC_FINISH]));
1124 : counters->gc_finalize_mark()->AddSample(
1125 22305 : static_cast<int>(current_.scopes[Scope::MC_MARK]));
1126 : counters->gc_finalize_prologue()->AddSample(
1127 22305 : static_cast<int>(current_.scopes[Scope::MC_PROLOGUE]));
1128 : counters->gc_finalize_sweep()->AddSample(
1129 22305 : static_cast<int>(current_.scopes[Scope::MC_SWEEP]));
1130 : DCHECK_EQ(Scope::LAST_TOP_MC_SCOPE, Scope::MC_SWEEP);
1131 75697 : } else if (gc_timer == counters->gc_scavenger()) {
1132 : counters->gc_scavenger_scavenge_main()->AddSample(
1133 23491 : static_cast<int>(current_.scopes[Scope::SCAVENGER_SCAVENGE_PARALLEL]));
1134 : counters->gc_scavenger_scavenge_roots()->AddSample(
1135 23491 : static_cast<int>(current_.scopes[Scope::SCAVENGER_SCAVENGE_ROOTS]));
1136 : }
1137 98002 : }
1138 :
1139 74506 : void GCTracer::RecordGCSumCounters(double atomic_pause_duration) {
1140 74506 : base::MutexGuard guard(&background_counter_mutex_);
1141 :
1142 : const double overall_duration =
1143 : current_.incremental_marking_scopes[Scope::MC_INCREMENTAL_LAYOUT_CHANGE]
1144 74506 : .duration +
1145 : current_.incremental_marking_scopes[Scope::MC_INCREMENTAL_START]
1146 74506 : .duration +
1147 : current_.incremental_marking_scopes[Scope::MC_INCREMENTAL_SWEEPING]
1148 74506 : .duration +
1149 74506 : incremental_marking_duration_ +
1150 : current_.incremental_marking_scopes[Scope::MC_INCREMENTAL_FINALIZE]
1151 74506 : .duration +
1152 74506 : atomic_pause_duration;
1153 : const double background_duration =
1154 : background_counter_[BackgroundScope::MC_BACKGROUND_EVACUATE_COPY]
1155 74506 : .total_duration_ms +
1156 : background_counter_
1157 : [BackgroundScope::MC_BACKGROUND_EVACUATE_UPDATE_POINTERS]
1158 74506 : .total_duration_ms +
1159 : background_counter_[BackgroundScope::MC_BACKGROUND_MARKING]
1160 74506 : .total_duration_ms +
1161 : background_counter_[BackgroundScope::MC_BACKGROUND_SWEEPING]
1162 74506 : .total_duration_ms;
1163 :
1164 : const double marking_duration =
1165 : current_.incremental_marking_scopes[Scope::MC_INCREMENTAL_LAYOUT_CHANGE]
1166 : .duration +
1167 : current_.incremental_marking_scopes[Scope::MC_INCREMENTAL_START]
1168 74506 : .duration +
1169 74506 : incremental_marking_duration_ +
1170 : current_.incremental_marking_scopes[Scope::MC_INCREMENTAL_FINALIZE]
1171 74506 : .duration +
1172 149012 : current_.scopes[Scope::MC_MARK];
1173 : const double marking_background_duration =
1174 : background_counter_[BackgroundScope::MC_BACKGROUND_MARKING]
1175 74506 : .total_duration_ms;
1176 :
1177 : // UMA.
1178 : heap_->isolate()->counters()->gc_mark_compactor()->AddSample(
1179 149012 : static_cast<int>(overall_duration));
1180 :
1181 : // Emit trace event counters.
1182 149012 : TRACE_EVENT_INSTANT2(TRACE_DISABLED_BY_DEFAULT("v8.gc"),
1183 : "V8.GCMarkCompactorSummary", TRACE_EVENT_SCOPE_THREAD,
1184 : "duration", overall_duration, "background_duration",
1185 : background_duration);
1186 149012 : TRACE_EVENT_INSTANT2(TRACE_DISABLED_BY_DEFAULT("v8.gc"),
1187 : "V8.GCMarkCompactorMarkingSummary",
1188 : TRACE_EVENT_SCOPE_THREAD, "duration", marking_duration,
1189 : "background_duration", marking_background_duration);
1190 74506 : }
1191 :
1192 : } // namespace internal
1193 178779 : } // namespace v8
|
