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