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