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 214132 : static size_t CountTotalHolesSize(Heap* heap) {
20 : size_t holes_size = 0;
21 : PagedSpaces spaces(heap);
22 856528 : for (PagedSpace* space = spaces.next(); space != nullptr;
23 : space = spaces.next()) {
24 : DCHECK_GE(holes_size + space->Waste() + space->Available(), holes_size);
25 642396 : holes_size += space->Waste() + space->Available();
26 : }
27 214132 : 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 8119681 : GCTracer::Scope::Scope(GCTracer* tracer, ScopeId scope)
38 16239362 : : tracer_(tracer), scope_(scope) {
39 8119681 : start_time_ = tracer_->heap_->MonotonicallyIncreasingTimeInMs();
40 : // TODO(cbruni): remove once we fully moved to a trace-based system.
41 16239362 : 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 8119681 : GCTracer::Scope::~Scope() {
47 : tracer_->AddScopeSample(
48 8119681 : scope_, tracer_->heap_->MonotonicallyIncreasingTimeInMs() - start_time_);
49 : // TODO(cbruni): remove once we fully moved to a trace-based system.
50 8119681 : if (V8_LIKELY(runtime_stats_ == nullptr)) return;
51 0 : runtime_stats_->Leave(&timer_);
52 8119681 : }
53 :
54 1506506 : GCTracer::BackgroundScope::BackgroundScope(GCTracer* tracer, ScopeId scope)
55 3013012 : : tracer_(tracer), scope_(scope), runtime_stats_enabled_(false) {
56 1506506 : start_time_ = tracer_->heap_->MonotonicallyIncreasingTimeInMs();
57 : // TODO(cbruni): remove once we fully moved to a trace-based system.
58 3013816 : 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 1506455 : GCTracer::BackgroundScope::~BackgroundScope() {
64 : double duration_ms =
65 1506455 : tracer_->heap_->MonotonicallyIncreasingTimeInMs() - start_time_;
66 : // TODO(cbruni): remove once we fully moved to a trace-based system.
67 1506504 : if (V8_LIKELY(!runtime_stats_enabled_)) {
68 1506504 : tracer_->AddBackgroundScopeSample(scope_, duration_ms, nullptr);
69 : } else {
70 0 : timer_.Stop();
71 0 : tracer_->AddBackgroundScopeSample(scope_, duration_ms, &counter_);
72 : }
73 1508514 : }
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 169965 : 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 : new_space_object_size(0),
119 : survived_new_space_object_size(0),
120 : incremental_marking_bytes(0),
121 1869615 : incremental_marking_duration(0.0) {
122 17506395 : for (int i = 0; i < Scope::NUMBER_OF_SCOPES; i++) {
123 17506395 : scopes[i] = 0;
124 : }
125 169965 : }
126 :
127 107066 : const char* GCTracer::Event::TypeName(bool short_name) const {
128 107066 : switch (type) {
129 : case SCAVENGER:
130 23578 : return (short_name) ? "s" : "Scavenge";
131 : case MARK_COMPACTOR:
132 : case INCREMENTAL_MARK_COMPACTOR:
133 83487 : 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 62883 : 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 1446309 : 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 62883 : current_.end_time = heap_->MonotonicallyIncreasingTimeInMs();
169 754596 : for (int i = 0; i < BackgroundScope::NUMBER_OF_SCOPES; i++) {
170 691713 : background_counter_[i].total_duration_ms = 0;
171 691713 : background_counter_[i].runtime_call_counter = RuntimeCallCounter(nullptr);
172 : }
173 62883 : }
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 23594 : 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 47188 : static_cast<int>(young_generation_handling));
213 23594 : }
214 :
215 107098 : void GCTracer::Start(GarbageCollector collector,
216 : GarbageCollectionReason gc_reason,
217 : const char* collector_reason) {
218 107098 : start_counter_++;
219 214196 : if (start_counter_ != 1) return;
220 :
221 107066 : previous_ = current_;
222 511751 : double start_time = heap_->MonotonicallyIncreasingTimeInMs();
223 : SampleAllocation(start_time, heap_->NewSpaceAllocationCounter(),
224 214132 : heap_->OldGenerationAllocationCounter());
225 :
226 107066 : switch (collector) {
227 : case SCAVENGER:
228 23578 : current_ = Event(Event::SCAVENGER, gc_reason, collector_reason);
229 23578 : 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 166974 : if (heap_->incremental_marking()->WasActivated()) {
236 : current_ = Event(Event::INCREMENTAL_MARK_COMPACTOR, gc_reason,
237 31091 : collector_reason);
238 : } else {
239 52396 : current_ = Event(Event::MARK_COMPACTOR, gc_reason, collector_reason);
240 : }
241 : break;
242 : }
243 :
244 214132 : current_.reduce_memory = heap_->ShouldReduceMemory();
245 107066 : current_.start_time = start_time;
246 107066 : current_.start_object_size = heap_->SizeOfObjects();
247 214132 : current_.start_memory_size = heap_->memory_allocator()->Size();
248 107066 : current_.start_holes_size = CountTotalHolesSize(heap_);
249 214132 : current_.new_space_object_size = heap_->new_space()->Size();
250 :
251 107066 : current_.incremental_marking_bytes = 0;
252 107066 : current_.incremental_marking_duration = 0;
253 :
254 11134864 : for (int i = 0; i < Scope::NUMBER_OF_SCOPES; i++) {
255 11027798 : current_.scopes[i] = 0;
256 : }
257 :
258 107066 : Counters* counters = heap_->isolate()->counters();
259 :
260 107066 : if (Heap::IsYoungGenerationCollector(collector)) {
261 23579 : counters->scavenge_reason()->AddSample(static_cast<int>(gc_reason));
262 : } else {
263 83487 : counters->mark_compact_reason()->AddSample(static_cast<int>(gc_reason));
264 : }
265 : }
266 :
267 83503 : void GCTracer::ResetIncrementalMarkingCounters() {
268 83503 : if (incremental_marking_duration_ > 0) {
269 : heap_->isolate()->counters()->incremental_marking_sum()->AddSample(
270 52884 : static_cast<int>(incremental_marking_duration_));
271 : }
272 83503 : incremental_marking_bytes_ = 0;
273 83503 : incremental_marking_duration_ = 0;
274 918533 : for (int i = 0; i < Scope::NUMBER_OF_INCREMENTAL_SCOPES; i++) {
275 835030 : incremental_marking_scopes_[i].ResetCurrentCycle();
276 : }
277 83503 : }
278 :
279 107098 : void GCTracer::Stop(GarbageCollector collector) {
280 107098 : start_counter_--;
281 107098 : if (start_counter_ != 0) {
282 32 : if (FLAG_trace_gc_verbose) {
283 : heap_->isolate()->PrintWithTimestamp(
284 : "[Finished reentrant %s during %s.]\n",
285 214132 : Heap::CollectorName(collector), current_.TypeName(false));
286 : }
287 : return;
288 : }
289 :
290 : DCHECK_LE(0, start_counter_);
291 : DCHECK((collector == SCAVENGER && current_.type == Event::SCAVENGER) ||
292 : (collector == MINOR_MARK_COMPACTOR &&
293 : current_.type == Event::MINOR_MARK_COMPACTOR) ||
294 : (collector == MARK_COMPACTOR &&
295 : (current_.type == Event::MARK_COMPACTOR ||
296 : current_.type == Event::INCREMENTAL_MARK_COMPACTOR)));
297 :
298 107066 : current_.end_time = heap_->MonotonicallyIncreasingTimeInMs();
299 107066 : current_.end_object_size = heap_->SizeOfObjects();
300 214132 : current_.end_memory_size = heap_->memory_allocator()->Size();
301 107066 : current_.end_holes_size = CountTotalHolesSize(heap_);
302 214132 : current_.survived_new_space_object_size = heap_->SurvivedNewSpaceObjectSize();
303 :
304 107066 : AddAllocation(current_.end_time);
305 :
306 107066 : double duration = current_.end_time - current_.start_time;
307 :
308 107066 : switch (current_.type) {
309 : case Event::SCAVENGER:
310 : case Event::MINOR_MARK_COMPACTOR:
311 : recorded_minor_gcs_total_.Push(
312 23579 : MakeBytesAndDuration(current_.new_space_object_size, duration));
313 : recorded_minor_gcs_survived_.Push(MakeBytesAndDuration(
314 23579 : current_.survived_new_space_object_size, duration));
315 23579 : FetchBackgroundMinorGCCounters();
316 23579 : break;
317 : case Event::INCREMENTAL_MARK_COMPACTOR:
318 31096 : current_.incremental_marking_bytes = incremental_marking_bytes_;
319 31096 : current_.incremental_marking_duration = incremental_marking_duration_;
320 342056 : for (int i = 0; i < Scope::NUMBER_OF_INCREMENTAL_SCOPES; i++) {
321 310960 : current_.incremental_marking_scopes[i] = incremental_marking_scopes_[i];
322 310960 : current_.scopes[i] = incremental_marking_scopes_[i].duration;
323 : }
324 :
325 : RecordMutatorUtilization(
326 31096 : current_.end_time, duration + current_.incremental_marking_duration);
327 : RecordIncrementalMarkingSpeed(current_.incremental_marking_bytes,
328 31096 : current_.incremental_marking_duration);
329 : recorded_incremental_mark_compacts_.Push(
330 31096 : MakeBytesAndDuration(current_.start_object_size, duration));
331 31096 : RecordGCSumCounters(duration);
332 31096 : ResetIncrementalMarkingCounters();
333 31096 : combined_mark_compact_speed_cache_ = 0.0;
334 31096 : FetchBackgroundMarkCompactCounters();
335 31096 : break;
336 : case Event::MARK_COMPACTOR:
337 : DCHECK_EQ(0u, current_.incremental_marking_bytes);
338 : DCHECK_EQ(0, current_.incremental_marking_duration);
339 : RecordMutatorUtilization(
340 52391 : current_.end_time, duration + current_.incremental_marking_duration);
341 : recorded_mark_compacts_.Push(
342 52391 : MakeBytesAndDuration(current_.start_object_size, duration));
343 52391 : RecordGCSumCounters(duration);
344 52391 : ResetIncrementalMarkingCounters();
345 52391 : combined_mark_compact_speed_cache_ = 0.0;
346 52391 : FetchBackgroundMarkCompactCounters();
347 52391 : break;
348 : case Event::START:
349 0 : UNREACHABLE();
350 : }
351 : FetchBackgroundGeneralCounters();
352 :
353 107066 : heap_->UpdateTotalGCTime(duration);
354 :
355 214132 : if ((current_.type == Event::SCAVENGER ||
356 107066 : current_.type == Event::MINOR_MARK_COMPACTOR) &&
357 : FLAG_trace_gc_ignore_scavenger)
358 : return;
359 :
360 107066 : if (FLAG_trace_gc_nvp) {
361 0 : PrintNVP();
362 : } else {
363 107066 : Print();
364 : }
365 :
366 107066 : if (FLAG_trace_gc) {
367 25 : heap_->PrintShortHeapStatistics();
368 : }
369 : }
370 :
371 :
372 494 : void GCTracer::SampleAllocation(double current_ms,
373 : size_t new_space_counter_bytes,
374 : size_t old_generation_counter_bytes) {
375 107560 : if (allocation_time_ms_ == 0) {
376 : // It is the first sample.
377 18020 : allocation_time_ms_ = current_ms;
378 18020 : new_space_allocation_counter_bytes_ = new_space_counter_bytes;
379 18020 : old_generation_allocation_counter_bytes_ = old_generation_counter_bytes;
380 544 : return;
381 : }
382 : // This assumes that counters are unsigned integers so that the subtraction
383 : // below works even if the new counter is less than the old counter.
384 : size_t new_space_allocated_bytes =
385 89540 : new_space_counter_bytes - new_space_allocation_counter_bytes_;
386 : size_t old_generation_allocated_bytes =
387 89540 : old_generation_counter_bytes - old_generation_allocation_counter_bytes_;
388 89540 : double duration = current_ms - allocation_time_ms_;
389 89540 : allocation_time_ms_ = current_ms;
390 89540 : new_space_allocation_counter_bytes_ = new_space_counter_bytes;
391 89540 : old_generation_allocation_counter_bytes_ = old_generation_counter_bytes;
392 89540 : allocation_duration_since_gc_ += duration;
393 89540 : new_space_allocation_in_bytes_since_gc_ += new_space_allocated_bytes;
394 : old_generation_allocation_in_bytes_since_gc_ +=
395 89540 : old_generation_allocated_bytes;
396 : }
397 :
398 :
399 107078 : void GCTracer::AddAllocation(double current_ms) {
400 107078 : allocation_time_ms_ = current_ms;
401 107078 : if (allocation_duration_since_gc_ > 0) {
402 : recorded_new_generation_allocations_.Push(
403 : MakeBytesAndDuration(new_space_allocation_in_bytes_since_gc_,
404 89104 : allocation_duration_since_gc_));
405 : recorded_old_generation_allocations_.Push(
406 : MakeBytesAndDuration(old_generation_allocation_in_bytes_since_gc_,
407 89104 : allocation_duration_since_gc_));
408 : }
409 107078 : allocation_duration_since_gc_ = 0;
410 107078 : new_space_allocation_in_bytes_since_gc_ = 0;
411 107078 : old_generation_allocation_in_bytes_since_gc_ = 0;
412 107078 : }
413 :
414 :
415 656 : void GCTracer::AddContextDisposalTime(double time) {
416 : recorded_context_disposal_times_.Push(time);
417 656 : }
418 :
419 85550 : void GCTracer::AddCompactionEvent(double duration,
420 : size_t live_bytes_compacted) {
421 : recorded_compactions_.Push(
422 85550 : MakeBytesAndDuration(live_bytes_compacted, duration));
423 85550 : }
424 :
425 :
426 93537 : void GCTracer::AddSurvivalRatio(double promotion_ratio) {
427 : recorded_survival_ratios_.Push(promotion_ratio);
428 93537 : }
429 :
430 1302558 : void GCTracer::AddIncrementalMarkingStep(double duration, size_t bytes) {
431 1302558 : if (bytes > 0) {
432 1242236 : incremental_marking_bytes_ += bytes;
433 1242236 : incremental_marking_duration_ += duration;
434 : }
435 1302558 : }
436 :
437 107066 : void GCTracer::Output(const char* format, ...) const {
438 107066 : if (FLAG_trace_gc) {
439 : va_list arguments;
440 25 : va_start(arguments, format);
441 25 : base::OS::VPrint(format, arguments);
442 25 : va_end(arguments);
443 : }
444 :
445 : const int kBufferSize = 256;
446 : char raw_buffer[kBufferSize];
447 : Vector<char> buffer(raw_buffer, kBufferSize);
448 : va_list arguments2;
449 107066 : va_start(arguments2, format);
450 107066 : VSNPrintF(buffer, format, arguments2);
451 107066 : va_end(arguments2);
452 :
453 107066 : heap_->AddToRingBuffer(buffer.start());
454 107066 : }
455 :
456 107066 : void GCTracer::Print() const {
457 107066 : double duration = current_.end_time - current_.start_time;
458 : const size_t kIncrementalStatsSize = 128;
459 107066 : char incremental_buffer[kIncrementalStatsSize] = {0};
460 :
461 107066 : if (current_.type == Event::INCREMENTAL_MARK_COMPACTOR) {
462 : base::OS::SNPrintF(
463 : incremental_buffer, kIncrementalStatsSize,
464 : " (+ %.1f ms in %d steps since start of marking, "
465 : "biggest step %.1f ms, walltime since start of marking %.f ms)",
466 31096 : current_.scopes[Scope::MC_INCREMENTAL],
467 : current_.incremental_marking_scopes[Scope::MC_INCREMENTAL].steps,
468 : current_.incremental_marking_scopes[Scope::MC_INCREMENTAL].longest_step,
469 62192 : current_.end_time - incremental_marking_start_time_);
470 : }
471 :
472 : // Avoid PrintF as Output also appends the string to the tracing ring buffer
473 : // that gets printed on OOM failures.
474 : Output(
475 : "[%d:%p] "
476 : "%8.0f ms: "
477 : "%s %.1f (%.1f) -> %.1f (%.1f) MB, "
478 : "%.1f / %.1f ms %s (average mu = %.3f, current mu = %.3f) %s %s\n",
479 : base::OS::GetCurrentProcessId(),
480 107066 : reinterpret_cast<void*>(heap_->isolate()),
481 : heap_->isolate()->time_millis_since_init(), current_.TypeName(false),
482 : static_cast<double>(current_.start_object_size) / MB,
483 : static_cast<double>(current_.start_memory_size) / MB,
484 : static_cast<double>(current_.end_object_size) / MB,
485 : static_cast<double>(current_.end_memory_size) / MB, duration,
486 : TotalExternalTime(), incremental_buffer,
487 : AverageMarkCompactMutatorUtilization(),
488 : CurrentMarkCompactMutatorUtilization(),
489 : Heap::GarbageCollectionReasonToString(current_.gc_reason),
490 321198 : current_.collector_reason != nullptr ? current_.collector_reason : "");
491 107066 : }
492 :
493 :
494 0 : void GCTracer::PrintNVP() const {
495 0 : double duration = current_.end_time - current_.start_time;
496 0 : double spent_in_mutator = current_.start_time - previous_.end_time;
497 : size_t allocated_since_last_gc =
498 0 : current_.start_object_size - previous_.end_object_size;
499 :
500 : double incremental_walltime_duration = 0;
501 :
502 0 : if (current_.type == Event::INCREMENTAL_MARK_COMPACTOR) {
503 : incremental_walltime_duration =
504 0 : current_.end_time - incremental_marking_start_time_;
505 : }
506 :
507 0 : switch (current_.type) {
508 : case Event::SCAVENGER:
509 : heap_->isolate()->PrintWithTimestamp(
510 : "pause=%.1f "
511 : "mutator=%.1f "
512 : "gc=%s "
513 : "reduce_memory=%d "
514 : "heap.prologue=%.2f "
515 : "heap.epilogue=%.2f "
516 : "heap.epilogue.reduce_new_space=%.2f "
517 : "heap.external.prologue=%.2f "
518 : "heap.external.epilogue=%.2f "
519 : "heap.external_weak_global_handles=%.2f "
520 : "fast_promote=%.2f "
521 : "scavenge=%.2f "
522 : "scavenge.process_array_buffers=%.2f "
523 : "scavenge.roots=%.2f "
524 : "scavenge.weak=%.2f "
525 : "scavenge.weak_global_handles.identify=%.2f "
526 : "scavenge.weak_global_handles.process=%.2f "
527 : "scavenge.parallel=%.2f "
528 : "scavenge.update_refs=%.2f "
529 : "background.scavenge.parallel=%.2f "
530 : "background.array_buffer_free=%.2f "
531 : "background.store_buffer=%.2f "
532 : "background.unmapper=%.2f "
533 : "incremental.steps_count=%d "
534 : "incremental.steps_took=%.1f "
535 : "scavenge_throughput=%.f "
536 : "total_size_before=%" PRIuS
537 : " "
538 : "total_size_after=%" PRIuS
539 : " "
540 : "holes_size_before=%" PRIuS
541 : " "
542 : "holes_size_after=%" PRIuS
543 : " "
544 : "allocated=%" PRIuS
545 : " "
546 : "promoted=%" PRIuS
547 : " "
548 : "semi_space_copied=%" PRIuS
549 : " "
550 : "nodes_died_in_new=%d "
551 : "nodes_copied_in_new=%d "
552 : "nodes_promoted=%d "
553 : "promotion_ratio=%.1f%% "
554 : "average_survival_ratio=%.1f%% "
555 : "promotion_rate=%.1f%% "
556 : "semi_space_copy_rate=%.1f%% "
557 : "new_space_allocation_throughput=%.1f "
558 : "unmapper_chunks=%d "
559 : "context_disposal_rate=%.1f\n",
560 : duration, spent_in_mutator, current_.TypeName(true),
561 0 : current_.reduce_memory, current_.scopes[Scope::HEAP_PROLOGUE],
562 0 : current_.scopes[Scope::HEAP_EPILOGUE],
563 0 : current_.scopes[Scope::HEAP_EPILOGUE_REDUCE_NEW_SPACE],
564 0 : current_.scopes[Scope::HEAP_EXTERNAL_PROLOGUE],
565 0 : current_.scopes[Scope::HEAP_EXTERNAL_EPILOGUE],
566 0 : current_.scopes[Scope::HEAP_EXTERNAL_WEAK_GLOBAL_HANDLES],
567 0 : current_.scopes[Scope::SCAVENGER_FAST_PROMOTE],
568 0 : current_.scopes[Scope::SCAVENGER_SCAVENGE],
569 0 : current_.scopes[Scope::SCAVENGER_PROCESS_ARRAY_BUFFERS],
570 0 : current_.scopes[Scope::SCAVENGER_SCAVENGE_ROOTS],
571 0 : current_.scopes[Scope::SCAVENGER_SCAVENGE_WEAK],
572 : current_
573 0 : .scopes[Scope::SCAVENGER_SCAVENGE_WEAK_GLOBAL_HANDLES_IDENTIFY],
574 : current_
575 0 : .scopes[Scope::SCAVENGER_SCAVENGE_WEAK_GLOBAL_HANDLES_PROCESS],
576 0 : current_.scopes[Scope::SCAVENGER_SCAVENGE_PARALLEL],
577 0 : current_.scopes[Scope::SCAVENGER_SCAVENGE_UPDATE_REFS],
578 0 : current_.scopes[Scope::SCAVENGER_BACKGROUND_SCAVENGE_PARALLEL],
579 0 : current_.scopes[Scope::BACKGROUND_ARRAY_BUFFER_FREE],
580 0 : current_.scopes[Scope::BACKGROUND_STORE_BUFFER],
581 0 : current_.scopes[Scope::BACKGROUND_UNMAPPER],
582 : current_.incremental_marking_scopes[GCTracer::Scope::MC_INCREMENTAL]
583 : .steps,
584 0 : current_.scopes[Scope::MC_INCREMENTAL],
585 : ScavengeSpeedInBytesPerMillisecond(), current_.start_object_size,
586 : current_.end_object_size, current_.start_holes_size,
587 : current_.end_holes_size, allocated_since_last_gc,
588 : heap_->promoted_objects_size(),
589 : heap_->semi_space_copied_object_size(),
590 : heap_->nodes_died_in_new_space_, heap_->nodes_copied_in_new_space_,
591 : heap_->nodes_promoted_, heap_->promotion_ratio_,
592 : AverageSurvivalRatio(), heap_->promotion_rate_,
593 : heap_->semi_space_copied_rate_,
594 : NewSpaceAllocationThroughputInBytesPerMillisecond(),
595 : heap_->memory_allocator()->unmapper()->NumberOfChunks(),
596 0 : ContextDisposalRateInMilliseconds());
597 0 : break;
598 : case Event::MINOR_MARK_COMPACTOR:
599 : heap_->isolate()->PrintWithTimestamp(
600 : "pause=%.1f "
601 : "mutator=%.1f "
602 : "gc=%s "
603 : "reduce_memory=%d "
604 : "minor_mc=%.2f "
605 : "finish_sweeping=%.2f "
606 : "mark=%.2f "
607 : "mark.seed=%.2f "
608 : "mark.roots=%.2f "
609 : "mark.weak=%.2f "
610 : "mark.global_handles=%.2f "
611 : "clear=%.2f "
612 : "clear.string_table=%.2f "
613 : "clear.weak_lists=%.2f "
614 : "evacuate=%.2f "
615 : "evacuate.copy=%.2f "
616 : "evacuate.update_pointers=%.2f "
617 : "evacuate.update_pointers.to_new_roots=%.2f "
618 : "evacuate.update_pointers.slots=%.2f "
619 : "background.mark=%.2f "
620 : "background.evacuate.copy=%.2f "
621 : "background.evacuate.update_pointers=%.2f "
622 : "background.array_buffer_free=%.2f "
623 : "background.store_buffer=%.2f "
624 : "background.unmapper=%.2f "
625 : "update_marking_deque=%.2f "
626 : "reset_liveness=%.2f\n",
627 : duration, spent_in_mutator, "mmc", current_.reduce_memory,
628 0 : current_.scopes[Scope::MINOR_MC],
629 0 : current_.scopes[Scope::MINOR_MC_SWEEPING],
630 0 : current_.scopes[Scope::MINOR_MC_MARK],
631 0 : current_.scopes[Scope::MINOR_MC_MARK_SEED],
632 0 : current_.scopes[Scope::MINOR_MC_MARK_ROOTS],
633 0 : current_.scopes[Scope::MINOR_MC_MARK_WEAK],
634 0 : current_.scopes[Scope::MINOR_MC_MARK_GLOBAL_HANDLES],
635 0 : current_.scopes[Scope::MINOR_MC_CLEAR],
636 0 : current_.scopes[Scope::MINOR_MC_CLEAR_STRING_TABLE],
637 0 : current_.scopes[Scope::MINOR_MC_CLEAR_WEAK_LISTS],
638 0 : current_.scopes[Scope::MINOR_MC_EVACUATE],
639 0 : current_.scopes[Scope::MINOR_MC_EVACUATE_COPY],
640 0 : current_.scopes[Scope::MINOR_MC_EVACUATE_UPDATE_POINTERS],
641 : current_
642 0 : .scopes[Scope::MINOR_MC_EVACUATE_UPDATE_POINTERS_TO_NEW_ROOTS],
643 0 : current_.scopes[Scope::MINOR_MC_EVACUATE_UPDATE_POINTERS_SLOTS],
644 0 : current_.scopes[Scope::MINOR_MC_BACKGROUND_MARKING],
645 0 : current_.scopes[Scope::MINOR_MC_BACKGROUND_EVACUATE_COPY],
646 0 : current_.scopes[Scope::MINOR_MC_BACKGROUND_EVACUATE_UPDATE_POINTERS],
647 0 : current_.scopes[Scope::BACKGROUND_ARRAY_BUFFER_FREE],
648 0 : current_.scopes[Scope::BACKGROUND_STORE_BUFFER],
649 0 : current_.scopes[Scope::BACKGROUND_UNMAPPER],
650 0 : current_.scopes[Scope::MINOR_MC_MARKING_DEQUE],
651 0 : current_.scopes[Scope::MINOR_MC_RESET_LIVENESS]);
652 0 : break;
653 : case Event::MARK_COMPACTOR:
654 : case Event::INCREMENTAL_MARK_COMPACTOR:
655 : heap_->isolate()->PrintWithTimestamp(
656 : "pause=%.1f "
657 : "mutator=%.1f "
658 : "gc=%s "
659 : "reduce_memory=%d "
660 : "heap.prologue=%.2f "
661 : "heap.embedder_tracing_epilogue=%.2f "
662 : "heap.epilogue=%.2f "
663 : "heap.epilogue.reduce_new_space=%.2f "
664 : "heap.external.prologue=%.1f "
665 : "heap.external.epilogue=%.1f "
666 : "heap.external.weak_global_handles=%.1f "
667 : "clear=%1.f "
668 : "clear.dependent_code=%.1f "
669 : "clear.maps=%.1f "
670 : "clear.slots_buffer=%.1f "
671 : "clear.store_buffer=%.1f "
672 : "clear.string_table=%.1f "
673 : "clear.weak_collections=%.1f "
674 : "clear.weak_lists=%.1f "
675 : "clear.weak_references=%.1f "
676 : "epilogue=%.1f "
677 : "evacuate=%.1f "
678 : "evacuate.candidates=%.1f "
679 : "evacuate.clean_up=%.1f "
680 : "evacuate.copy=%.1f "
681 : "evacuate.prologue=%.1f "
682 : "evacuate.epilogue=%.1f "
683 : "evacuate.rebalance=%.1f "
684 : "evacuate.update_pointers=%.1f "
685 : "evacuate.update_pointers.to_new_roots=%.1f "
686 : "evacuate.update_pointers.slots.main=%.1f "
687 : "evacuate.update_pointers.slots.map_space=%.1f "
688 : "evacuate.update_pointers.weak=%.1f "
689 : "finish=%.1f "
690 : "mark=%.1f "
691 : "mark.finish_incremental=%.1f "
692 : "mark.roots=%.1f "
693 : "mark.main=%.1f "
694 : "mark.weak_closure=%.1f "
695 : "mark.weak_closure.ephemeron=%.1f "
696 : "mark.weak_closure.ephemeron.marking=%.1f "
697 : "mark.weak_closure.ephemeron.linear=%.1f "
698 : "mark.weak_closure.weak_handles=%.1f "
699 : "mark.weak_closure.weak_roots=%.1f "
700 : "mark.weak_closure.harmony=%.1f "
701 : "mark.embedder_prologue=%.1f "
702 : "mark.embedder_tracing=%.1f "
703 : "prologue=%.1f "
704 : "sweep=%.1f "
705 : "sweep.code=%.1f "
706 : "sweep.map=%.1f "
707 : "sweep.old=%.1f "
708 : "incremental=%.1f "
709 : "incremental.finalize=%.1f "
710 : "incremental.finalize.body=%.1f "
711 : "incremental.finalize.external.prologue=%.1f "
712 : "incremental.finalize.external.epilogue=%.1f "
713 : "incremental.layout_change=%.1f "
714 : "incremental.start=%.1f "
715 : "incremental.sweeping=%.1f "
716 : "incremental.embedder_prologue=%.1f "
717 : "incremental.embedder_tracing=%.1f "
718 : "incremental_wrapper_tracing_longest_step=%.1f "
719 : "incremental_finalize_longest_step=%.1f "
720 : "incremental_finalize_steps_count=%d "
721 : "incremental_longest_step=%.1f "
722 : "incremental_steps_count=%d "
723 : "incremental_marking_throughput=%.f "
724 : "incremental_walltime_duration=%.f "
725 : "background.mark=%.1f "
726 : "background.sweep=%.1f "
727 : "background.evacuate.copy=%.1f "
728 : "background.evacuate.update_pointers=%.1f "
729 : "background.array_buffer_free=%.2f "
730 : "background.store_buffer=%.2f "
731 : "background.unmapper=%.1f "
732 : "total_size_before=%" PRIuS
733 : " "
734 : "total_size_after=%" PRIuS
735 : " "
736 : "holes_size_before=%" PRIuS
737 : " "
738 : "holes_size_after=%" PRIuS
739 : " "
740 : "allocated=%" PRIuS
741 : " "
742 : "promoted=%" PRIuS
743 : " "
744 : "semi_space_copied=%" PRIuS
745 : " "
746 : "nodes_died_in_new=%d "
747 : "nodes_copied_in_new=%d "
748 : "nodes_promoted=%d "
749 : "promotion_ratio=%.1f%% "
750 : "average_survival_ratio=%.1f%% "
751 : "promotion_rate=%.1f%% "
752 : "semi_space_copy_rate=%.1f%% "
753 : "new_space_allocation_throughput=%.1f "
754 : "unmapper_chunks=%d "
755 : "context_disposal_rate=%.1f "
756 : "compaction_speed=%.f\n",
757 : duration, spent_in_mutator, current_.TypeName(true),
758 0 : current_.reduce_memory, current_.scopes[Scope::HEAP_PROLOGUE],
759 0 : current_.scopes[Scope::HEAP_EMBEDDER_TRACING_EPILOGUE],
760 0 : current_.scopes[Scope::HEAP_EPILOGUE],
761 0 : current_.scopes[Scope::HEAP_EPILOGUE_REDUCE_NEW_SPACE],
762 0 : current_.scopes[Scope::HEAP_EXTERNAL_PROLOGUE],
763 0 : current_.scopes[Scope::HEAP_EXTERNAL_EPILOGUE],
764 0 : current_.scopes[Scope::HEAP_EXTERNAL_WEAK_GLOBAL_HANDLES],
765 0 : current_.scopes[Scope::MC_CLEAR],
766 0 : current_.scopes[Scope::MC_CLEAR_DEPENDENT_CODE],
767 0 : current_.scopes[Scope::MC_CLEAR_MAPS],
768 0 : current_.scopes[Scope::MC_CLEAR_SLOTS_BUFFER],
769 0 : current_.scopes[Scope::MC_CLEAR_STORE_BUFFER],
770 0 : current_.scopes[Scope::MC_CLEAR_STRING_TABLE],
771 0 : current_.scopes[Scope::MC_CLEAR_WEAK_COLLECTIONS],
772 0 : current_.scopes[Scope::MC_CLEAR_WEAK_LISTS],
773 0 : current_.scopes[Scope::MC_CLEAR_WEAK_REFERENCES],
774 0 : current_.scopes[Scope::MC_EPILOGUE],
775 0 : current_.scopes[Scope::MC_EVACUATE],
776 0 : current_.scopes[Scope::MC_EVACUATE_CANDIDATES],
777 0 : current_.scopes[Scope::MC_EVACUATE_CLEAN_UP],
778 0 : current_.scopes[Scope::MC_EVACUATE_COPY],
779 0 : current_.scopes[Scope::MC_EVACUATE_PROLOGUE],
780 0 : current_.scopes[Scope::MC_EVACUATE_EPILOGUE],
781 0 : current_.scopes[Scope::MC_EVACUATE_REBALANCE],
782 0 : current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS],
783 0 : current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS_TO_NEW_ROOTS],
784 0 : current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS_SLOTS_MAIN],
785 0 : current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS_SLOTS_MAP_SPACE],
786 0 : current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS_WEAK],
787 0 : current_.scopes[Scope::MC_FINISH], current_.scopes[Scope::MC_MARK],
788 0 : current_.scopes[Scope::MC_MARK_FINISH_INCREMENTAL],
789 0 : current_.scopes[Scope::MC_MARK_ROOTS],
790 0 : current_.scopes[Scope::MC_MARK_MAIN],
791 0 : current_.scopes[Scope::MC_MARK_WEAK_CLOSURE],
792 0 : current_.scopes[Scope::MC_MARK_WEAK_CLOSURE_EPHEMERON],
793 0 : current_.scopes[Scope::MC_MARK_WEAK_CLOSURE_EPHEMERON_MARKING],
794 0 : current_.scopes[Scope::MC_MARK_WEAK_CLOSURE_EPHEMERON_LINEAR],
795 0 : current_.scopes[Scope::MC_MARK_WEAK_CLOSURE_WEAK_HANDLES],
796 0 : current_.scopes[Scope::MC_MARK_WEAK_CLOSURE_WEAK_ROOTS],
797 0 : current_.scopes[Scope::MC_MARK_WEAK_CLOSURE_HARMONY],
798 0 : current_.scopes[Scope::MC_MARK_EMBEDDER_PROLOGUE],
799 0 : current_.scopes[Scope::MC_MARK_EMBEDDER_TRACING],
800 0 : current_.scopes[Scope::MC_PROLOGUE], current_.scopes[Scope::MC_SWEEP],
801 0 : current_.scopes[Scope::MC_SWEEP_CODE],
802 0 : current_.scopes[Scope::MC_SWEEP_MAP],
803 0 : current_.scopes[Scope::MC_SWEEP_OLD],
804 0 : current_.scopes[Scope::MC_INCREMENTAL],
805 0 : current_.scopes[Scope::MC_INCREMENTAL_FINALIZE],
806 0 : current_.scopes[Scope::MC_INCREMENTAL_FINALIZE_BODY],
807 0 : current_.scopes[Scope::MC_INCREMENTAL_EXTERNAL_PROLOGUE],
808 0 : current_.scopes[Scope::MC_INCREMENTAL_EXTERNAL_EPILOGUE],
809 0 : current_.scopes[Scope::MC_INCREMENTAL_LAYOUT_CHANGE],
810 0 : current_.scopes[Scope::MC_INCREMENTAL_START],
811 0 : current_.scopes[Scope::MC_INCREMENTAL_SWEEPING],
812 0 : current_.scopes[Scope::MC_INCREMENTAL_EMBEDDER_PROLOGUE],
813 0 : current_.scopes[Scope::MC_INCREMENTAL_EMBEDDER_TRACING],
814 : current_
815 : .incremental_marking_scopes
816 : [Scope::MC_INCREMENTAL_EMBEDDER_TRACING]
817 : .longest_step,
818 : current_
819 : .incremental_marking_scopes[Scope::MC_INCREMENTAL_FINALIZE_BODY]
820 : .longest_step,
821 : current_
822 : .incremental_marking_scopes[Scope::MC_INCREMENTAL_FINALIZE_BODY]
823 : .steps,
824 : current_.incremental_marking_scopes[Scope::MC_INCREMENTAL]
825 : .longest_step,
826 : current_.incremental_marking_scopes[Scope::MC_INCREMENTAL].steps,
827 : IncrementalMarkingSpeedInBytesPerMillisecond(),
828 : incremental_walltime_duration,
829 0 : current_.scopes[Scope::MC_BACKGROUND_MARKING],
830 0 : current_.scopes[Scope::MC_BACKGROUND_SWEEPING],
831 0 : current_.scopes[Scope::MC_BACKGROUND_EVACUATE_COPY],
832 0 : current_.scopes[Scope::MC_BACKGROUND_EVACUATE_UPDATE_POINTERS],
833 0 : current_.scopes[Scope::BACKGROUND_ARRAY_BUFFER_FREE],
834 0 : current_.scopes[Scope::BACKGROUND_STORE_BUFFER],
835 0 : current_.scopes[Scope::BACKGROUND_UNMAPPER],
836 : current_.start_object_size, current_.end_object_size,
837 : current_.start_holes_size, current_.end_holes_size,
838 : allocated_since_last_gc, heap_->promoted_objects_size(),
839 : heap_->semi_space_copied_object_size(),
840 : heap_->nodes_died_in_new_space_, heap_->nodes_copied_in_new_space_,
841 : heap_->nodes_promoted_, heap_->promotion_ratio_,
842 : AverageSurvivalRatio(), heap_->promotion_rate_,
843 : heap_->semi_space_copied_rate_,
844 : NewSpaceAllocationThroughputInBytesPerMillisecond(),
845 : heap_->memory_allocator()->unmapper()->NumberOfChunks(),
846 : ContextDisposalRateInMilliseconds(),
847 0 : CompactionSpeedInBytesPerMillisecond());
848 0 : break;
849 : case Event::START:
850 : break;
851 : default:
852 0 : UNREACHABLE();
853 : }
854 0 : }
855 :
856 687912 : double GCTracer::AverageSpeed(const base::RingBuffer<BytesAndDuration>& buffer,
857 : const BytesAndDuration& initial, double time_ms) {
858 : BytesAndDuration sum = buffer.Sum(
859 : [time_ms](BytesAndDuration a, BytesAndDuration b) {
860 3327652 : if (time_ms != 0 && a.second >= time_ms) return a;
861 3326595 : return std::make_pair(a.first + b.first, a.second + b.second);
862 : },
863 687912 : initial);
864 687912 : uint64_t bytes = sum.first;
865 687912 : double durations = sum.second;
866 687912 : if (durations == 0.0) return 0;
867 487982 : double speed = bytes / durations;
868 : const int max_speed = 1024 * MB;
869 : const int min_speed = 1;
870 487982 : if (speed >= max_speed) return max_speed;
871 487974 : if (speed <= min_speed) return min_speed;
872 448274 : return speed;
873 : }
874 :
875 0 : double GCTracer::AverageSpeed(
876 : const base::RingBuffer<BytesAndDuration>& buffer) {
877 343014 : return AverageSpeed(buffer, MakeBytesAndDuration(0, 0), 0);
878 : }
879 :
880 0 : void GCTracer::RecordIncrementalMarkingSpeed(size_t bytes, double duration) {
881 31096 : if (duration == 0 || bytes == 0) return;
882 26442 : double current_speed = bytes / duration;
883 26442 : if (recorded_incremental_marking_speed_ == 0) {
884 11375 : recorded_incremental_marking_speed_ = current_speed;
885 : } else {
886 : recorded_incremental_marking_speed_ =
887 15067 : (recorded_incremental_marking_speed_ + current_speed) / 2;
888 : }
889 : }
890 :
891 83491 : void GCTracer::RecordMutatorUtilization(double mark_compact_end_time,
892 : double mark_compact_duration) {
893 83491 : if (previous_mark_compact_end_time_ == 0) {
894 : // The first event only contributes to previous_mark_compact_end_time_,
895 : // because we cannot compute the mutator duration.
896 16306 : previous_mark_compact_end_time_ = mark_compact_end_time;
897 : } else {
898 : double total_duration =
899 67185 : mark_compact_end_time - previous_mark_compact_end_time_;
900 67185 : double mutator_duration = total_duration - mark_compact_duration;
901 67185 : if (average_mark_compact_duration_ == 0 && average_mutator_duration_ == 0) {
902 : // This is the first event with mutator and mark-compact durations.
903 10140 : average_mark_compact_duration_ = mark_compact_duration;
904 10140 : average_mutator_duration_ = mutator_duration;
905 : } else {
906 : average_mark_compact_duration_ =
907 57045 : (average_mark_compact_duration_ + mark_compact_duration) / 2;
908 : average_mutator_duration_ =
909 57045 : (average_mutator_duration_ + mutator_duration) / 2;
910 : }
911 : current_mark_compact_mutator_utilization_ =
912 67185 : total_duration ? mutator_duration / total_duration : 0;
913 67185 : previous_mark_compact_end_time_ = mark_compact_end_time;
914 : }
915 83491 : }
916 :
917 83496 : double GCTracer::AverageMarkCompactMutatorUtilization() const {
918 : double average_total_duration =
919 190562 : average_mark_compact_duration_ + average_mutator_duration_;
920 190562 : if (average_total_duration == 0) return 1.0;
921 128518 : return average_mutator_duration_ / average_total_duration;
922 : }
923 :
924 4 : double GCTracer::CurrentMarkCompactMutatorUtilization() const {
925 107070 : return current_mark_compact_mutator_utilization_;
926 : }
927 :
928 1300494 : double GCTracer::IncrementalMarkingSpeedInBytesPerMillisecond() const {
929 : const int kConservativeSpeedInBytesPerMillisecond = 128 * KB;
930 1402548 : if (recorded_incremental_marking_speed_ != 0) {
931 : return recorded_incremental_marking_speed_;
932 : }
933 254861 : if (incremental_marking_duration_ != 0.0) {
934 176475 : return incremental_marking_bytes_ / incremental_marking_duration_;
935 : }
936 : return kConservativeSpeedInBytesPerMillisecond;
937 : }
938 :
939 27472 : double GCTracer::ScavengeSpeedInBytesPerMillisecond(
940 : ScavengeSpeedMode mode) const {
941 27472 : if (mode == kForAllObjects) {
942 7714 : return AverageSpeed(recorded_minor_gcs_total_);
943 : } else {
944 47230 : return AverageSpeed(recorded_minor_gcs_survived_);
945 : }
946 : }
947 :
948 138220 : double GCTracer::CompactionSpeedInBytesPerMillisecond() const {
949 276440 : return AverageSpeed(recorded_compactions_);
950 : }
951 :
952 0 : double GCTracer::MarkCompactSpeedInBytesPerMillisecond() const {
953 75268 : return AverageSpeed(recorded_mark_compacts_);
954 : }
955 :
956 0 : double GCTracer::FinalIncrementalMarkCompactSpeedInBytesPerMillisecond() const {
957 102054 : return AverageSpeed(recorded_incremental_mark_compacts_);
958 : }
959 :
960 107094 : double GCTracer::CombinedMarkCompactSpeedInBytesPerMillisecond() {
961 107094 : if (combined_mark_compact_speed_cache_ > 0)
962 : return combined_mark_compact_speed_cache_;
963 : const double kMinimumMarkingSpeed = 0.5;
964 : double speed1 = IncrementalMarkingSpeedInBytesPerMillisecond();
965 : double speed2 = FinalIncrementalMarkCompactSpeedInBytesPerMillisecond();
966 102054 : if (speed1 < kMinimumMarkingSpeed || speed2 < kMinimumMarkingSpeed) {
967 : // No data for the incremental marking speed.
968 : // Return the non-incremental mark-compact speed.
969 : combined_mark_compact_speed_cache_ =
970 75268 : MarkCompactSpeedInBytesPerMillisecond();
971 : } else {
972 : // Combine the speed of incremental step and the speed of the final step.
973 : // 1 / (1 / speed1 + 1 / speed2) = speed1 * speed2 / (speed1 + speed2).
974 26786 : combined_mark_compact_speed_cache_ = speed1 * speed2 / (speed1 + speed2);
975 : }
976 102054 : return combined_mark_compact_speed_cache_;
977 : }
978 :
979 23619 : double GCTracer::NewSpaceAllocationThroughputInBytesPerMillisecond(
980 : double time_ms) const {
981 130707 : size_t bytes = new_space_allocation_in_bytes_since_gc_;
982 130707 : double durations = allocation_duration_since_gc_;
983 : return AverageSpeed(recorded_new_generation_allocations_,
984 130707 : MakeBytesAndDuration(bytes, durations), time_ms);
985 : }
986 :
987 10 : double GCTracer::OldGenerationAllocationThroughputInBytesPerMillisecond(
988 : double time_ms) const {
989 214184 : size_t bytes = old_generation_allocation_in_bytes_since_gc_;
990 214184 : double durations = allocation_duration_since_gc_;
991 : return AverageSpeed(recorded_old_generation_allocations_,
992 214184 : MakeBytesAndDuration(bytes, durations), time_ms);
993 : }
994 :
995 107088 : double GCTracer::AllocationThroughputInBytesPerMillisecond(
996 : double time_ms) const {
997 : return NewSpaceAllocationThroughputInBytesPerMillisecond(time_ms) +
998 107088 : OldGenerationAllocationThroughputInBytesPerMillisecond(time_ms);
999 : }
1000 :
1001 107086 : double GCTracer::CurrentAllocationThroughputInBytesPerMillisecond() const {
1002 107086 : return AllocationThroughputInBytesPerMillisecond(kThroughputTimeFrameMs);
1003 : }
1004 :
1005 107086 : double GCTracer::CurrentOldGenerationAllocationThroughputInBytesPerMillisecond()
1006 : const {
1007 : return OldGenerationAllocationThroughputInBytesPerMillisecond(
1008 107086 : kThroughputTimeFrameMs);
1009 : }
1010 :
1011 460 : double GCTracer::ContextDisposalRateInMilliseconds() const {
1012 460 : if (recorded_context_disposal_times_.Count() <
1013 : recorded_context_disposal_times_.kSize)
1014 : return 0.0;
1015 198 : double begin = heap_->MonotonicallyIncreasingTimeInMs();
1016 : double end = recorded_context_disposal_times_.Sum(
1017 : [](double a, double b) { return b; }, 0.0);
1018 198 : return (begin - end) / recorded_context_disposal_times_.Count();
1019 : }
1020 :
1021 18375 : double GCTracer::AverageSurvivalRatio() const {
1022 18375 : if (recorded_survival_ratios_.Count() == 0) return 0.0;
1023 : double sum = recorded_survival_ratios_.Sum(
1024 127546 : [](double a, double b) { return a + b; }, 0.0);
1025 18375 : return sum / recorded_survival_ratios_.Count();
1026 : }
1027 :
1028 18405 : bool GCTracer::SurvivalEventsRecorded() const {
1029 18405 : return recorded_survival_ratios_.Count() > 0;
1030 : }
1031 :
1032 20 : void GCTracer::ResetSurvivalEvents() { recorded_survival_ratios_.Reset(); }
1033 :
1034 31884 : void GCTracer::NotifyIncrementalMarkingStart() {
1035 31884 : incremental_marking_start_time_ = heap_->MonotonicallyIncreasingTimeInMs();
1036 31884 : }
1037 :
1038 83489 : void GCTracer::FetchBackgroundMarkCompactCounters() {
1039 : FetchBackgroundCounters(Scope::FIRST_MC_BACKGROUND_SCOPE,
1040 : Scope::LAST_MC_BACKGROUND_SCOPE,
1041 : BackgroundScope::FIRST_MC_BACKGROUND_SCOPE,
1042 83489 : BackgroundScope::LAST_MC_BACKGROUND_SCOPE);
1043 : heap_->isolate()->counters()->background_marking()->AddSample(
1044 166978 : static_cast<int>(current_.scopes[Scope::MC_BACKGROUND_MARKING]));
1045 : heap_->isolate()->counters()->background_sweeping()->AddSample(
1046 166978 : static_cast<int>(current_.scopes[Scope::MC_BACKGROUND_SWEEPING]));
1047 83489 : }
1048 :
1049 23579 : void GCTracer::FetchBackgroundMinorGCCounters() {
1050 : FetchBackgroundCounters(Scope::FIRST_MINOR_GC_BACKGROUND_SCOPE,
1051 : Scope::LAST_MINOR_GC_BACKGROUND_SCOPE,
1052 : BackgroundScope::FIRST_MINOR_GC_BACKGROUND_SCOPE,
1053 23579 : BackgroundScope::LAST_MINOR_GC_BACKGROUND_SCOPE);
1054 : heap_->isolate()->counters()->background_scavenger()->AddSample(
1055 : static_cast<int>(
1056 47158 : current_.scopes[Scope::SCAVENGER_BACKGROUND_SCAVENGE_PARALLEL]));
1057 23579 : }
1058 :
1059 0 : void GCTracer::FetchBackgroundGeneralCounters() {
1060 : FetchBackgroundCounters(Scope::FIRST_GENERAL_BACKGROUND_SCOPE,
1061 : Scope::LAST_GENERAL_BACKGROUND_SCOPE,
1062 : BackgroundScope::FIRST_GENERAL_BACKGROUND_SCOPE,
1063 107066 : BackgroundScope::LAST_GENERAL_BACKGROUND_SCOPE);
1064 0 : }
1065 :
1066 214134 : void GCTracer::FetchBackgroundCounters(int first_global_scope,
1067 : int last_global_scope,
1068 : int first_background_scope,
1069 : int last_background_scope) {
1070 : DCHECK_EQ(last_global_scope - first_global_scope,
1071 : last_background_scope - first_background_scope);
1072 214134 : base::MutexGuard guard(&background_counter_mutex_);
1073 214134 : int background_mc_scopes = last_background_scope - first_background_scope + 1;
1074 963604 : for (int i = 0; i < background_mc_scopes; i++) {
1075 : current_.scopes[first_global_scope + i] +=
1076 749470 : background_counter_[first_background_scope + i].total_duration_ms;
1077 749470 : background_counter_[first_background_scope + i].total_duration_ms = 0;
1078 : }
1079 214134 : if (V8_LIKELY(!FLAG_runtime_stats)) return;
1080 : RuntimeCallStats* runtime_stats =
1081 0 : heap_->isolate()->counters()->runtime_call_stats();
1082 0 : if (!runtime_stats) return;
1083 0 : for (int i = 0; i < background_mc_scopes; i++) {
1084 : runtime_stats
1085 : ->GetCounter(GCTracer::RCSCounterFromScope(
1086 0 : static_cast<Scope::ScopeId>(first_global_scope + i)))
1087 0 : ->Add(&background_counter_[first_background_scope + i]
1088 0 : .runtime_call_counter);
1089 : background_counter_[first_background_scope + i]
1090 0 : .runtime_call_counter.Reset();
1091 : }
1092 : }
1093 :
1094 1505999 : void GCTracer::AddBackgroundScopeSample(
1095 : BackgroundScope::ScopeId scope, double duration,
1096 : RuntimeCallCounter* runtime_call_counter) {
1097 1505999 : base::MutexGuard guard(&background_counter_mutex_);
1098 1508676 : BackgroundCounter& counter = background_counter_[scope];
1099 1508676 : counter.total_duration_ms += duration;
1100 1508676 : if (runtime_call_counter) {
1101 0 : counter.runtime_call_counter.Add(runtime_call_counter);
1102 : }
1103 1508537 : }
1104 :
1105 107088 : void GCTracer::RecordGCPhasesHistograms(TimedHistogram* gc_timer) {
1106 107088 : Counters* counters = heap_->isolate()->counters();
1107 107088 : if (gc_timer == counters->gc_finalize()) {
1108 : DCHECK_EQ(Scope::FIRST_TOP_MC_SCOPE, Scope::MC_CLEAR);
1109 : counters->gc_finalize_clear()->AddSample(
1110 28220 : static_cast<int>(current_.scopes[Scope::MC_CLEAR]));
1111 : counters->gc_finalize_epilogue()->AddSample(
1112 28220 : static_cast<int>(current_.scopes[Scope::MC_EPILOGUE]));
1113 : counters->gc_finalize_evacuate()->AddSample(
1114 28220 : static_cast<int>(current_.scopes[Scope::MC_EVACUATE]));
1115 : counters->gc_finalize_finish()->AddSample(
1116 28220 : static_cast<int>(current_.scopes[Scope::MC_FINISH]));
1117 : counters->gc_finalize_mark()->AddSample(
1118 28220 : static_cast<int>(current_.scopes[Scope::MC_MARK]));
1119 : counters->gc_finalize_prologue()->AddSample(
1120 28220 : static_cast<int>(current_.scopes[Scope::MC_PROLOGUE]));
1121 : counters->gc_finalize_sweep()->AddSample(
1122 28220 : static_cast<int>(current_.scopes[Scope::MC_SWEEP]));
1123 : DCHECK_EQ(Scope::LAST_TOP_MC_SCOPE, Scope::MC_SWEEP);
1124 78868 : } else if (gc_timer == counters->gc_scavenger()) {
1125 : counters->gc_scavenger_scavenge_main()->AddSample(
1126 23595 : static_cast<int>(current_.scopes[Scope::SCAVENGER_SCAVENGE_PARALLEL]));
1127 : counters->gc_scavenger_scavenge_roots()->AddSample(
1128 23595 : static_cast<int>(current_.scopes[Scope::SCAVENGER_SCAVENGE_ROOTS]));
1129 : }
1130 107088 : }
1131 :
1132 83488 : void GCTracer::RecordGCSumCounters(double atomic_pause_duration) {
1133 83488 : base::MutexGuard guard(&background_counter_mutex_);
1134 :
1135 : const double overall_duration =
1136 : current_.incremental_marking_scopes[Scope::MC_INCREMENTAL_LAYOUT_CHANGE]
1137 83488 : .duration +
1138 : current_.incremental_marking_scopes[Scope::MC_INCREMENTAL_START]
1139 83488 : .duration +
1140 : current_.incremental_marking_scopes[Scope::MC_INCREMENTAL_SWEEPING]
1141 83488 : .duration +
1142 83488 : incremental_marking_duration_ +
1143 : current_.incremental_marking_scopes[Scope::MC_INCREMENTAL_FINALIZE]
1144 83488 : .duration +
1145 83488 : atomic_pause_duration;
1146 : const double background_duration =
1147 : background_counter_[BackgroundScope::MC_BACKGROUND_EVACUATE_COPY]
1148 83488 : .total_duration_ms +
1149 : background_counter_
1150 : [BackgroundScope::MC_BACKGROUND_EVACUATE_UPDATE_POINTERS]
1151 83488 : .total_duration_ms +
1152 : background_counter_[BackgroundScope::MC_BACKGROUND_MARKING]
1153 83488 : .total_duration_ms +
1154 : background_counter_[BackgroundScope::MC_BACKGROUND_SWEEPING]
1155 83488 : .total_duration_ms;
1156 :
1157 : const double marking_duration =
1158 : current_.incremental_marking_scopes[Scope::MC_INCREMENTAL_LAYOUT_CHANGE]
1159 : .duration +
1160 : current_.incremental_marking_scopes[Scope::MC_INCREMENTAL_START]
1161 83488 : .duration +
1162 83488 : incremental_marking_duration_ +
1163 : current_.incremental_marking_scopes[Scope::MC_INCREMENTAL_FINALIZE]
1164 83488 : .duration +
1165 166976 : current_.scopes[Scope::MC_MARK];
1166 : const double marking_background_duration =
1167 : background_counter_[BackgroundScope::MC_BACKGROUND_MARKING]
1168 83488 : .total_duration_ms;
1169 :
1170 : // UMA.
1171 : heap_->isolate()->counters()->gc_mark_compactor()->AddSample(
1172 166976 : static_cast<int>(overall_duration));
1173 :
1174 : // Emit trace event counters.
1175 166976 : TRACE_EVENT_INSTANT2(TRACE_DISABLED_BY_DEFAULT("v8.gc"),
1176 : "V8.GCMarkCompactorSummary", TRACE_EVENT_SCOPE_THREAD,
1177 : "duration", overall_duration, "background_duration",
1178 : background_duration);
1179 166976 : TRACE_EVENT_INSTANT2(TRACE_DISABLED_BY_DEFAULT("v8.gc"),
1180 : "V8.GCMarkCompactorMarkingSummary",
1181 : TRACE_EVENT_SCOPE_THREAD, "duration", marking_duration,
1182 : "background_duration", marking_background_duration);
1183 83488 : }
1184 :
1185 : } // namespace internal
1186 183867 : } // namespace v8
|
