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 "src/counters.h"
8 #include "src/heap/heap-inl.h"
9 #include "src/isolate.h"
10
11 namespace v8 {
12 namespace internal {
13
CountTotalHolesSize(Heap * heap)14 static intptr_t CountTotalHolesSize(Heap* heap) {
15 intptr_t holes_size = 0;
16 OldSpaces spaces(heap);
17 for (OldSpace* space = spaces.next(); space != NULL; space = spaces.next()) {
18 holes_size += space->Waste() + space->Available();
19 }
20 return holes_size;
21 }
22
23
Scope(GCTracer * tracer,ScopeId scope)24 GCTracer::Scope::Scope(GCTracer* tracer, ScopeId scope)
25 : tracer_(tracer), scope_(scope) {
26 start_time_ = tracer_->heap_->MonotonicallyIncreasingTimeInMs();
27 // TODO(cbruni): remove once we fully moved to a trace-based system.
28 if (FLAG_runtime_call_stats) {
29 RuntimeCallStats::Enter(tracer_->heap_->isolate(), &timer_,
30 &RuntimeCallStats::GC);
31 }
32 }
33
34
~Scope()35 GCTracer::Scope::~Scope() {
36 DCHECK(scope_ < NUMBER_OF_SCOPES); // scope_ is unsigned.
37 tracer_->current_.scopes[scope_] +=
38 tracer_->heap_->MonotonicallyIncreasingTimeInMs() - start_time_;
39 // TODO(cbruni): remove once we fully moved to a trace-based system.
40 if (FLAG_runtime_call_stats) {
41 RuntimeCallStats::Leave(tracer_->heap_->isolate(), &timer_);
42 }
43 }
44
Name(ScopeId id)45 const char* GCTracer::Scope::Name(ScopeId id) {
46 #define CASE(scope) \
47 case Scope::scope: \
48 return "V8.GC_" #scope;
49 switch (id) {
50 TRACER_SCOPES(CASE)
51 case Scope::NUMBER_OF_SCOPES:
52 break;
53 }
54 #undef CASE
55 return "(unknown)";
56 }
57
Event(Type type,const char * gc_reason,const char * collector_reason)58 GCTracer::Event::Event(Type type, const char* gc_reason,
59 const char* collector_reason)
60 : type(type),
61 gc_reason(gc_reason),
62 collector_reason(collector_reason),
63 start_time(0.0),
64 end_time(0.0),
65 reduce_memory(false),
66 start_object_size(0),
67 end_object_size(0),
68 start_memory_size(0),
69 end_memory_size(0),
70 start_holes_size(0),
71 end_holes_size(0),
72 cumulative_incremental_marking_steps(0),
73 incremental_marking_steps(0),
74 cumulative_incremental_marking_bytes(0),
75 incremental_marking_bytes(0),
76 cumulative_incremental_marking_duration(0.0),
77 incremental_marking_duration(0.0),
78 cumulative_pure_incremental_marking_duration(0.0),
79 pure_incremental_marking_duration(0.0),
80 longest_incremental_marking_step(0.0) {
81 for (int i = 0; i < Scope::NUMBER_OF_SCOPES; i++) {
82 scopes[i] = 0;
83 }
84 }
85
86
TypeName(bool short_name) const87 const char* GCTracer::Event::TypeName(bool short_name) const {
88 switch (type) {
89 case SCAVENGER:
90 if (short_name) {
91 return "s";
92 } else {
93 return "Scavenge";
94 }
95 case MARK_COMPACTOR:
96 case INCREMENTAL_MARK_COMPACTOR:
97 if (short_name) {
98 return "ms";
99 } else {
100 return "Mark-sweep";
101 }
102 case START:
103 if (short_name) {
104 return "st";
105 } else {
106 return "Start";
107 }
108 }
109 return "Unknown Event Type";
110 }
111
112
GCTracer(Heap * heap)113 GCTracer::GCTracer(Heap* heap)
114 : heap_(heap),
115 cumulative_incremental_marking_steps_(0),
116 cumulative_incremental_marking_bytes_(0),
117 cumulative_incremental_marking_duration_(0.0),
118 cumulative_pure_incremental_marking_duration_(0.0),
119 longest_incremental_marking_step_(0.0),
120 cumulative_incremental_marking_finalization_steps_(0),
121 cumulative_incremental_marking_finalization_duration_(0.0),
122 longest_incremental_marking_finalization_step_(0.0),
123 cumulative_marking_duration_(0.0),
124 cumulative_sweeping_duration_(0.0),
125 allocation_time_ms_(0.0),
126 new_space_allocation_counter_bytes_(0),
127 old_generation_allocation_counter_bytes_(0),
128 allocation_duration_since_gc_(0.0),
129 new_space_allocation_in_bytes_since_gc_(0),
130 old_generation_allocation_in_bytes_since_gc_(0),
131 combined_mark_compact_speed_cache_(0.0),
132 start_counter_(0) {
133 current_ = Event(Event::START, NULL, NULL);
134 current_.end_time = heap_->MonotonicallyIncreasingTimeInMs();
135 previous_ = previous_incremental_mark_compactor_event_ = current_;
136 }
137
ResetForTesting()138 void GCTracer::ResetForTesting() {
139 cumulative_incremental_marking_steps_ = 0.0;
140 cumulative_incremental_marking_bytes_ = 0.0;
141 cumulative_incremental_marking_duration_ = 0.0;
142 cumulative_pure_incremental_marking_duration_ = 0.0;
143 longest_incremental_marking_step_ = 0.0;
144 cumulative_incremental_marking_finalization_steps_ = 0.0;
145 cumulative_incremental_marking_finalization_duration_ = 0.0;
146 longest_incremental_marking_finalization_step_ = 0.0;
147 cumulative_marking_duration_ = 0.0;
148 cumulative_sweeping_duration_ = 0.0;
149 allocation_time_ms_ = 0.0;
150 new_space_allocation_counter_bytes_ = 0.0;
151 old_generation_allocation_counter_bytes_ = 0.0;
152 allocation_duration_since_gc_ = 0.0;
153 new_space_allocation_in_bytes_since_gc_ = 0.0;
154 old_generation_allocation_in_bytes_since_gc_ = 0.0;
155 combined_mark_compact_speed_cache_ = 0.0;
156 start_counter_ = 0;
157 }
158
Start(GarbageCollector collector,const char * gc_reason,const char * collector_reason)159 void GCTracer::Start(GarbageCollector collector, const char* gc_reason,
160 const char* collector_reason) {
161 start_counter_++;
162 if (start_counter_ != 1) return;
163
164 previous_ = current_;
165 double start_time = heap_->MonotonicallyIncreasingTimeInMs();
166 SampleAllocation(start_time, heap_->NewSpaceAllocationCounter(),
167 heap_->OldGenerationAllocationCounter());
168 if (current_.type == Event::INCREMENTAL_MARK_COMPACTOR)
169 previous_incremental_mark_compactor_event_ = current_;
170
171 if (collector == SCAVENGER) {
172 current_ = Event(Event::SCAVENGER, gc_reason, collector_reason);
173 } else if (collector == MARK_COMPACTOR) {
174 if (heap_->incremental_marking()->WasActivated()) {
175 current_ =
176 Event(Event::INCREMENTAL_MARK_COMPACTOR, gc_reason, collector_reason);
177 } else {
178 current_ = Event(Event::MARK_COMPACTOR, gc_reason, collector_reason);
179 }
180 }
181
182 current_.reduce_memory = heap_->ShouldReduceMemory();
183 current_.start_time = start_time;
184 current_.start_object_size = heap_->SizeOfObjects();
185 current_.start_memory_size = heap_->memory_allocator()->Size();
186 current_.start_holes_size = CountTotalHolesSize(heap_);
187 current_.new_space_object_size =
188 heap_->new_space()->top() - heap_->new_space()->bottom();
189
190 current_.cumulative_incremental_marking_steps =
191 cumulative_incremental_marking_steps_;
192 current_.cumulative_incremental_marking_bytes =
193 cumulative_incremental_marking_bytes_;
194 current_.cumulative_incremental_marking_duration =
195 cumulative_incremental_marking_duration_;
196 current_.cumulative_pure_incremental_marking_duration =
197 cumulative_pure_incremental_marking_duration_;
198 current_.longest_incremental_marking_step = longest_incremental_marking_step_;
199
200 for (int i = 0; i < Scope::NUMBER_OF_SCOPES; i++) {
201 current_.scopes[i] = 0;
202 }
203 int committed_memory = static_cast<int>(heap_->CommittedMemory() / KB);
204 int used_memory = static_cast<int>(current_.start_object_size / KB);
205 heap_->isolate()->counters()->aggregated_memory_heap_committed()->AddSample(
206 start_time, committed_memory);
207 heap_->isolate()->counters()->aggregated_memory_heap_used()->AddSample(
208 start_time, used_memory);
209 // TODO(cbruni): remove once we fully moved to a trace-based system.
210 if (FLAG_runtime_call_stats) {
211 RuntimeCallStats::Enter(heap_->isolate(), &timer_, &RuntimeCallStats::GC);
212 }
213 }
214
Stop(GarbageCollector collector)215 void GCTracer::Stop(GarbageCollector collector) {
216 start_counter_--;
217 if (start_counter_ != 0) {
218 Output("[Finished reentrant %s during %s.]\n",
219 collector == SCAVENGER ? "Scavenge" : "Mark-sweep",
220 current_.TypeName(false));
221 return;
222 }
223
224 DCHECK(start_counter_ >= 0);
225 DCHECK((collector == SCAVENGER && current_.type == Event::SCAVENGER) ||
226 (collector == MARK_COMPACTOR &&
227 (current_.type == Event::MARK_COMPACTOR ||
228 current_.type == Event::INCREMENTAL_MARK_COMPACTOR)));
229
230 current_.end_time = heap_->MonotonicallyIncreasingTimeInMs();
231 current_.end_object_size = heap_->SizeOfObjects();
232 current_.end_memory_size = heap_->memory_allocator()->Size();
233 current_.end_holes_size = CountTotalHolesSize(heap_);
234 current_.survived_new_space_object_size = heap_->SurvivedNewSpaceObjectSize();
235
236 AddAllocation(current_.end_time);
237
238 int committed_memory = static_cast<int>(heap_->CommittedMemory() / KB);
239 int used_memory = static_cast<int>(current_.end_object_size / KB);
240 heap_->isolate()->counters()->aggregated_memory_heap_committed()->AddSample(
241 current_.end_time, committed_memory);
242 heap_->isolate()->counters()->aggregated_memory_heap_used()->AddSample(
243 current_.end_time, used_memory);
244
245 double duration = current_.end_time - current_.start_time;
246 if (current_.type == Event::SCAVENGER) {
247 current_.incremental_marking_steps =
248 current_.cumulative_incremental_marking_steps -
249 previous_.cumulative_incremental_marking_steps;
250 current_.incremental_marking_bytes =
251 current_.cumulative_incremental_marking_bytes -
252 previous_.cumulative_incremental_marking_bytes;
253 current_.incremental_marking_duration =
254 current_.cumulative_incremental_marking_duration -
255 previous_.cumulative_incremental_marking_duration;
256 current_.pure_incremental_marking_duration =
257 current_.cumulative_pure_incremental_marking_duration -
258 previous_.cumulative_pure_incremental_marking_duration;
259 recorded_scavenges_total_.Push(
260 MakeBytesAndDuration(current_.new_space_object_size, duration));
261 recorded_scavenges_survived_.Push(MakeBytesAndDuration(
262 current_.survived_new_space_object_size, duration));
263 } else if (current_.type == Event::INCREMENTAL_MARK_COMPACTOR) {
264 current_.incremental_marking_steps =
265 current_.cumulative_incremental_marking_steps -
266 previous_incremental_mark_compactor_event_
267 .cumulative_incremental_marking_steps;
268 current_.incremental_marking_bytes =
269 current_.cumulative_incremental_marking_bytes -
270 previous_incremental_mark_compactor_event_
271 .cumulative_incremental_marking_bytes;
272 current_.incremental_marking_duration =
273 current_.cumulative_incremental_marking_duration -
274 previous_incremental_mark_compactor_event_
275 .cumulative_incremental_marking_duration;
276 current_.pure_incremental_marking_duration =
277 current_.cumulative_pure_incremental_marking_duration -
278 previous_incremental_mark_compactor_event_
279 .cumulative_pure_incremental_marking_duration;
280 longest_incremental_marking_step_ = 0.0;
281 recorded_incremental_marking_steps_.Push(
282 MakeBytesAndDuration(current_.incremental_marking_bytes,
283 current_.pure_incremental_marking_duration));
284 recorded_incremental_mark_compacts_.Push(
285 MakeBytesAndDuration(current_.start_object_size, duration));
286 combined_mark_compact_speed_cache_ = 0.0;
287 } else {
288 DCHECK(current_.incremental_marking_bytes == 0);
289 DCHECK(current_.incremental_marking_duration == 0);
290 DCHECK(current_.pure_incremental_marking_duration == 0);
291 longest_incremental_marking_step_ = 0.0;
292 recorded_mark_compacts_.Push(
293 MakeBytesAndDuration(current_.start_object_size, duration));
294 combined_mark_compact_speed_cache_ = 0.0;
295 }
296
297 // TODO(ernstm): move the code below out of GCTracer.
298
299 double spent_in_mutator = Max(current_.start_time - previous_.end_time, 0.0);
300
301 heap_->UpdateCumulativeGCStatistics(duration, spent_in_mutator,
302 current_.scopes[Scope::MC_MARK]);
303
304 if (current_.type == Event::SCAVENGER && FLAG_trace_gc_ignore_scavenger)
305 return;
306
307 if (FLAG_trace_gc_nvp)
308 PrintNVP();
309 else
310 Print();
311
312 if (FLAG_trace_gc) {
313 heap_->PrintShortHeapStatistics();
314 }
315
316 longest_incremental_marking_finalization_step_ = 0.0;
317 cumulative_incremental_marking_finalization_steps_ = 0;
318 cumulative_incremental_marking_finalization_duration_ = 0.0;
319 // TODO(cbruni): remove once we fully moved to a trace-based system.
320 if (FLAG_runtime_call_stats) {
321 RuntimeCallStats::Leave(heap_->isolate(), &timer_);
322 }
323 }
324
325
SampleAllocation(double current_ms,size_t new_space_counter_bytes,size_t old_generation_counter_bytes)326 void GCTracer::SampleAllocation(double current_ms,
327 size_t new_space_counter_bytes,
328 size_t old_generation_counter_bytes) {
329 if (allocation_time_ms_ == 0) {
330 // It is the first sample.
331 allocation_time_ms_ = current_ms;
332 new_space_allocation_counter_bytes_ = new_space_counter_bytes;
333 old_generation_allocation_counter_bytes_ = old_generation_counter_bytes;
334 return;
335 }
336 // This assumes that counters are unsigned integers so that the subtraction
337 // below works even if the new counter is less then the old counter.
338 size_t new_space_allocated_bytes =
339 new_space_counter_bytes - new_space_allocation_counter_bytes_;
340 size_t old_generation_allocated_bytes =
341 old_generation_counter_bytes - old_generation_allocation_counter_bytes_;
342 double duration = current_ms - allocation_time_ms_;
343 allocation_time_ms_ = current_ms;
344 new_space_allocation_counter_bytes_ = new_space_counter_bytes;
345 old_generation_allocation_counter_bytes_ = old_generation_counter_bytes;
346 allocation_duration_since_gc_ += duration;
347 new_space_allocation_in_bytes_since_gc_ += new_space_allocated_bytes;
348 old_generation_allocation_in_bytes_since_gc_ +=
349 old_generation_allocated_bytes;
350 }
351
352
AddAllocation(double current_ms)353 void GCTracer::AddAllocation(double current_ms) {
354 allocation_time_ms_ = current_ms;
355 if (allocation_duration_since_gc_ > 0) {
356 recorded_new_generation_allocations_.Push(
357 MakeBytesAndDuration(new_space_allocation_in_bytes_since_gc_,
358 allocation_duration_since_gc_));
359 recorded_old_generation_allocations_.Push(
360 MakeBytesAndDuration(old_generation_allocation_in_bytes_since_gc_,
361 allocation_duration_since_gc_));
362 }
363 allocation_duration_since_gc_ = 0;
364 new_space_allocation_in_bytes_since_gc_ = 0;
365 old_generation_allocation_in_bytes_since_gc_ = 0;
366 }
367
368
AddContextDisposalTime(double time)369 void GCTracer::AddContextDisposalTime(double time) {
370 recorded_context_disposal_times_.Push(time);
371 }
372
373
AddCompactionEvent(double duration,intptr_t live_bytes_compacted)374 void GCTracer::AddCompactionEvent(double duration,
375 intptr_t live_bytes_compacted) {
376 recorded_compactions_.Push(
377 MakeBytesAndDuration(live_bytes_compacted, duration));
378 }
379
380
AddSurvivalRatio(double promotion_ratio)381 void GCTracer::AddSurvivalRatio(double promotion_ratio) {
382 recorded_survival_ratios_.Push(promotion_ratio);
383 }
384
385
AddIncrementalMarkingStep(double duration,intptr_t bytes)386 void GCTracer::AddIncrementalMarkingStep(double duration, intptr_t bytes) {
387 cumulative_incremental_marking_steps_++;
388 cumulative_incremental_marking_bytes_ += bytes;
389 cumulative_incremental_marking_duration_ += duration;
390 longest_incremental_marking_step_ =
391 Max(longest_incremental_marking_step_, duration);
392 cumulative_marking_duration_ += duration;
393 if (bytes > 0) {
394 cumulative_pure_incremental_marking_duration_ += duration;
395 }
396 }
397
398
AddIncrementalMarkingFinalizationStep(double duration)399 void GCTracer::AddIncrementalMarkingFinalizationStep(double duration) {
400 cumulative_incremental_marking_finalization_steps_++;
401 cumulative_incremental_marking_finalization_duration_ += duration;
402 longest_incremental_marking_finalization_step_ =
403 Max(longest_incremental_marking_finalization_step_, duration);
404 }
405
406
Output(const char * format,...) const407 void GCTracer::Output(const char* format, ...) const {
408 if (FLAG_trace_gc) {
409 va_list arguments;
410 va_start(arguments, format);
411 base::OS::VPrint(format, arguments);
412 va_end(arguments);
413 }
414
415 const int kBufferSize = 256;
416 char raw_buffer[kBufferSize];
417 Vector<char> buffer(raw_buffer, kBufferSize);
418 va_list arguments2;
419 va_start(arguments2, format);
420 VSNPrintF(buffer, format, arguments2);
421 va_end(arguments2);
422
423 heap_->AddToRingBuffer(buffer.start());
424 }
425
426
Print() const427 void GCTracer::Print() const {
428 if (FLAG_trace_gc) {
429 PrintIsolate(heap_->isolate(), "%s", "");
430 }
431 Output("%8.0f ms: ", heap_->isolate()->time_millis_since_init());
432
433 Output("%s %.1f (%.1f) -> %.1f (%.1f) MB, ", current_.TypeName(false),
434 static_cast<double>(current_.start_object_size) / MB,
435 static_cast<double>(current_.start_memory_size) / MB,
436 static_cast<double>(current_.end_object_size) / MB,
437 static_cast<double>(current_.end_memory_size) / MB);
438
439 double duration = current_.end_time - current_.start_time;
440 Output("%.1f / %.1f ms", duration, TotalExternalTime());
441
442 if (current_.type == Event::SCAVENGER) {
443 if (current_.incremental_marking_steps > 0) {
444 Output(" (+ %.1f ms in %d steps since last GC)",
445 current_.incremental_marking_duration,
446 current_.incremental_marking_steps);
447 }
448 } else {
449 if (current_.incremental_marking_steps > 0) {
450 Output(
451 " (+ %.1f ms in %d steps since start of marking, "
452 "biggest step %.1f ms)",
453 current_.incremental_marking_duration,
454 current_.incremental_marking_steps,
455 current_.longest_incremental_marking_step);
456 }
457 }
458
459 if (current_.gc_reason != NULL) {
460 Output(" [%s]", current_.gc_reason);
461 }
462
463 if (current_.collector_reason != NULL) {
464 Output(" [%s]", current_.collector_reason);
465 }
466
467 Output(".\n");
468 }
469
470
PrintNVP() const471 void GCTracer::PrintNVP() const {
472 double duration = current_.end_time - current_.start_time;
473 double spent_in_mutator = current_.start_time - previous_.end_time;
474 intptr_t allocated_since_last_gc =
475 current_.start_object_size - previous_.end_object_size;
476
477 switch (current_.type) {
478 case Event::SCAVENGER:
479 PrintIsolate(heap_->isolate(),
480 "%8.0f ms: "
481 "pause=%.1f "
482 "mutator=%.1f "
483 "gc=%s "
484 "reduce_memory=%d "
485 "scavenge=%.2f "
486 "old_new=%.2f "
487 "weak=%.2f "
488 "roots=%.2f "
489 "code=%.2f "
490 "semispace=%.2f "
491 "object_groups=%.2f "
492 "external_prologue=%.2f "
493 "external_epilogue=%.2f "
494 "external_weak_global_handles=%.2f "
495 "steps_count=%d "
496 "steps_took=%.1f "
497 "scavenge_throughput=%.f "
498 "total_size_before=%" V8PRIdPTR
499 " "
500 "total_size_after=%" V8PRIdPTR
501 " "
502 "holes_size_before=%" V8PRIdPTR
503 " "
504 "holes_size_after=%" V8PRIdPTR
505 " "
506 "allocated=%" V8PRIdPTR
507 " "
508 "promoted=%" V8PRIdPTR
509 " "
510 "semi_space_copied=%" V8PRIdPTR
511 " "
512 "nodes_died_in_new=%d "
513 "nodes_copied_in_new=%d "
514 "nodes_promoted=%d "
515 "promotion_ratio=%.1f%% "
516 "average_survival_ratio=%.1f%% "
517 "promotion_rate=%.1f%% "
518 "semi_space_copy_rate=%.1f%% "
519 "new_space_allocation_throughput=%.1f "
520 "context_disposal_rate=%.1f\n",
521 heap_->isolate()->time_millis_since_init(), duration,
522 spent_in_mutator, current_.TypeName(true),
523 current_.reduce_memory,
524 current_.scopes[Scope::SCAVENGER_SCAVENGE],
525 current_.scopes[Scope::SCAVENGER_OLD_TO_NEW_POINTERS],
526 current_.scopes[Scope::SCAVENGER_WEAK],
527 current_.scopes[Scope::SCAVENGER_ROOTS],
528 current_.scopes[Scope::SCAVENGER_CODE_FLUSH_CANDIDATES],
529 current_.scopes[Scope::SCAVENGER_SEMISPACE],
530 current_.scopes[Scope::SCAVENGER_OBJECT_GROUPS],
531 current_.scopes[Scope::SCAVENGER_EXTERNAL_PROLOGUE],
532 current_.scopes[Scope::SCAVENGER_EXTERNAL_EPILOGUE],
533 current_.scopes[Scope::EXTERNAL_WEAK_GLOBAL_HANDLES],
534 current_.incremental_marking_steps,
535 current_.incremental_marking_duration,
536 ScavengeSpeedInBytesPerMillisecond(),
537 current_.start_object_size, current_.end_object_size,
538 current_.start_holes_size, current_.end_holes_size,
539 allocated_since_last_gc, heap_->promoted_objects_size(),
540 heap_->semi_space_copied_object_size(),
541 heap_->nodes_died_in_new_space_,
542 heap_->nodes_copied_in_new_space_, heap_->nodes_promoted_,
543 heap_->promotion_ratio_, AverageSurvivalRatio(),
544 heap_->promotion_rate_, heap_->semi_space_copied_rate_,
545 NewSpaceAllocationThroughputInBytesPerMillisecond(),
546 ContextDisposalRateInMilliseconds());
547 break;
548 case Event::MARK_COMPACTOR:
549 case Event::INCREMENTAL_MARK_COMPACTOR:
550 PrintIsolate(
551 heap_->isolate(),
552 "%8.0f ms: "
553 "pause=%.1f "
554 "mutator=%.1f "
555 "gc=%s "
556 "reduce_memory=%d "
557 "clear=%1.f "
558 "clear.code_flush=%.1f "
559 "clear.dependent_code=%.1f "
560 "clear.global_handles=%.1f "
561 "clear.maps=%.1f "
562 "clear.slots_buffer=%.1f "
563 "clear.store_buffer=%.1f "
564 "clear.string_table=%.1f "
565 "clear.weak_cells=%.1f "
566 "clear.weak_collections=%.1f "
567 "clear.weak_lists=%.1f "
568 "evacuate=%.1f "
569 "evacuate.candidates=%.1f "
570 "evacuate.clean_up=%.1f "
571 "evacuate.copy=%.1f "
572 "evacuate.update_pointers=%.1f "
573 "evacuate.update_pointers.to_evacuated=%.1f "
574 "evacuate.update_pointers.to_new=%.1f "
575 "evacuate.update_pointers.weak=%.1f "
576 "external.mc_prologue=%.1f "
577 "external.mc_epilogue=%.1f "
578 "external.mc_incremental_prologue=%.1f "
579 "external.mc_incremental_epilogue=%.1f "
580 "external.weak_global_handles=%.1f "
581 "finish=%.1f "
582 "mark=%.1f "
583 "mark.finish_incremental=%.1f "
584 "mark.prepare_code_flush=%.1f "
585 "mark.roots=%.1f "
586 "mark.weak_closure=%.1f "
587 "mark.weak_closure.ephemeral=%.1f "
588 "mark.weak_closure.weak_handles=%.1f "
589 "mark.weak_closure.weak_roots=%.1f "
590 "mark.weak_closure.harmony=%.1f "
591 "sweep=%.1f "
592 "sweep.code=%.1f "
593 "sweep.map=%.1f "
594 "sweep.old=%.1f "
595 "incremental_finalize=%.1f "
596 "steps_count=%d "
597 "steps_took=%.1f "
598 "longest_step=%.1f "
599 "finalization_steps_count=%d "
600 "finalization_steps_took=%.1f "
601 "finalization_longest_step=%.1f "
602 "incremental_marking_throughput=%.f "
603 "total_size_before=%" V8PRIdPTR
604 " "
605 "total_size_after=%" V8PRIdPTR
606 " "
607 "holes_size_before=%" V8PRIdPTR
608 " "
609 "holes_size_after=%" V8PRIdPTR
610 " "
611 "allocated=%" V8PRIdPTR
612 " "
613 "promoted=%" V8PRIdPTR
614 " "
615 "semi_space_copied=%" V8PRIdPTR
616 " "
617 "nodes_died_in_new=%d "
618 "nodes_copied_in_new=%d "
619 "nodes_promoted=%d "
620 "promotion_ratio=%.1f%% "
621 "average_survival_ratio=%.1f%% "
622 "promotion_rate=%.1f%% "
623 "semi_space_copy_rate=%.1f%% "
624 "new_space_allocation_throughput=%.1f "
625 "context_disposal_rate=%.1f "
626 "compaction_speed=%.f\n",
627 heap_->isolate()->time_millis_since_init(), duration,
628 spent_in_mutator, current_.TypeName(true), current_.reduce_memory,
629 current_.scopes[Scope::MC_CLEAR],
630 current_.scopes[Scope::MC_CLEAR_CODE_FLUSH],
631 current_.scopes[Scope::MC_CLEAR_DEPENDENT_CODE],
632 current_.scopes[Scope::MC_CLEAR_GLOBAL_HANDLES],
633 current_.scopes[Scope::MC_CLEAR_MAPS],
634 current_.scopes[Scope::MC_CLEAR_SLOTS_BUFFER],
635 current_.scopes[Scope::MC_CLEAR_STORE_BUFFER],
636 current_.scopes[Scope::MC_CLEAR_STRING_TABLE],
637 current_.scopes[Scope::MC_CLEAR_WEAK_CELLS],
638 current_.scopes[Scope::MC_CLEAR_WEAK_COLLECTIONS],
639 current_.scopes[Scope::MC_CLEAR_WEAK_LISTS],
640 current_.scopes[Scope::MC_EVACUATE],
641 current_.scopes[Scope::MC_EVACUATE_CANDIDATES],
642 current_.scopes[Scope::MC_EVACUATE_CLEAN_UP],
643 current_.scopes[Scope::MC_EVACUATE_COPY],
644 current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS],
645 current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS_TO_EVACUATED],
646 current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS_TO_NEW],
647 current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS_WEAK],
648 current_.scopes[Scope::MC_EXTERNAL_PROLOGUE],
649 current_.scopes[Scope::MC_EXTERNAL_EPILOGUE],
650 current_.scopes[Scope::MC_INCREMENTAL_EXTERNAL_PROLOGUE],
651 current_.scopes[Scope::MC_INCREMENTAL_EXTERNAL_EPILOGUE],
652 current_.scopes[Scope::EXTERNAL_WEAK_GLOBAL_HANDLES],
653 current_.scopes[Scope::MC_FINISH], current_.scopes[Scope::MC_MARK],
654 current_.scopes[Scope::MC_MARK_FINISH_INCREMENTAL],
655 current_.scopes[Scope::MC_MARK_PREPARE_CODE_FLUSH],
656 current_.scopes[Scope::MC_MARK_ROOTS],
657 current_.scopes[Scope::MC_MARK_WEAK_CLOSURE],
658 current_.scopes[Scope::MC_MARK_WEAK_CLOSURE_EPHEMERAL],
659 current_.scopes[Scope::MC_MARK_WEAK_CLOSURE_WEAK_HANDLES],
660 current_.scopes[Scope::MC_MARK_WEAK_CLOSURE_WEAK_ROOTS],
661 current_.scopes[Scope::MC_MARK_WEAK_CLOSURE_HARMONY],
662 current_.scopes[Scope::MC_SWEEP],
663 current_.scopes[Scope::MC_SWEEP_CODE],
664 current_.scopes[Scope::MC_SWEEP_MAP],
665 current_.scopes[Scope::MC_SWEEP_OLD],
666 current_.scopes[Scope::MC_INCREMENTAL_FINALIZE],
667 current_.incremental_marking_steps,
668 current_.incremental_marking_duration,
669 current_.longest_incremental_marking_step,
670 cumulative_incremental_marking_finalization_steps_,
671 cumulative_incremental_marking_finalization_duration_,
672 longest_incremental_marking_finalization_step_,
673 IncrementalMarkingSpeedInBytesPerMillisecond(),
674 current_.start_object_size, current_.end_object_size,
675 current_.start_holes_size, current_.end_holes_size,
676 allocated_since_last_gc, heap_->promoted_objects_size(),
677 heap_->semi_space_copied_object_size(),
678 heap_->nodes_died_in_new_space_, heap_->nodes_copied_in_new_space_,
679 heap_->nodes_promoted_, heap_->promotion_ratio_,
680 AverageSurvivalRatio(), heap_->promotion_rate_,
681 heap_->semi_space_copied_rate_,
682 NewSpaceAllocationThroughputInBytesPerMillisecond(),
683 ContextDisposalRateInMilliseconds(),
684 CompactionSpeedInBytesPerMillisecond());
685 break;
686 case Event::START:
687 break;
688 default:
689 UNREACHABLE();
690 }
691 }
692
AverageSpeed(const RingBuffer<BytesAndDuration> & buffer,const BytesAndDuration & initial,double time_ms)693 double GCTracer::AverageSpeed(const RingBuffer<BytesAndDuration>& buffer,
694 const BytesAndDuration& initial, double time_ms) {
695 BytesAndDuration sum = buffer.Sum(
696 [time_ms](BytesAndDuration a, BytesAndDuration b) {
697 if (time_ms != 0 && a.second >= time_ms) return a;
698 return std::make_pair(a.first + b.first, a.second + b.second);
699 },
700 initial);
701 uint64_t bytes = sum.first;
702 double durations = sum.second;
703 if (durations == 0.0) return 0;
704 double speed = bytes / durations;
705 const int max_speed = 1024 * MB;
706 const int min_speed = 1;
707 if (speed >= max_speed) return max_speed;
708 if (speed <= min_speed) return min_speed;
709 return speed;
710 }
711
AverageSpeed(const RingBuffer<BytesAndDuration> & buffer)712 double GCTracer::AverageSpeed(const RingBuffer<BytesAndDuration>& buffer) {
713 return AverageSpeed(buffer, MakeBytesAndDuration(0, 0), 0);
714 }
715
IncrementalMarkingSpeedInBytesPerMillisecond() const716 double GCTracer::IncrementalMarkingSpeedInBytesPerMillisecond() const {
717 if (cumulative_incremental_marking_duration_ == 0.0) return 0;
718 // We haven't completed an entire round of incremental marking, yet.
719 // Use data from GCTracer instead of data from event buffers.
720 if (recorded_incremental_marking_steps_.Count() == 0) {
721 return cumulative_incremental_marking_bytes_ /
722 cumulative_pure_incremental_marking_duration_;
723 }
724 return AverageSpeed(recorded_incremental_marking_steps_);
725 }
726
ScavengeSpeedInBytesPerMillisecond(ScavengeSpeedMode mode) const727 double GCTracer::ScavengeSpeedInBytesPerMillisecond(
728 ScavengeSpeedMode mode) const {
729 if (mode == kForAllObjects) {
730 return AverageSpeed(recorded_scavenges_total_);
731 } else {
732 return AverageSpeed(recorded_scavenges_survived_);
733 }
734 }
735
CompactionSpeedInBytesPerMillisecond() const736 double GCTracer::CompactionSpeedInBytesPerMillisecond() const {
737 return AverageSpeed(recorded_compactions_);
738 }
739
MarkCompactSpeedInBytesPerMillisecond() const740 double GCTracer::MarkCompactSpeedInBytesPerMillisecond() const {
741 return AverageSpeed(recorded_mark_compacts_);
742 }
743
FinalIncrementalMarkCompactSpeedInBytesPerMillisecond() const744 double GCTracer::FinalIncrementalMarkCompactSpeedInBytesPerMillisecond() const {
745 return AverageSpeed(recorded_incremental_mark_compacts_);
746 }
747
CombinedMarkCompactSpeedInBytesPerMillisecond()748 double GCTracer::CombinedMarkCompactSpeedInBytesPerMillisecond() {
749 if (combined_mark_compact_speed_cache_ > 0)
750 return combined_mark_compact_speed_cache_;
751 const double kMinimumMarkingSpeed = 0.5;
752 double speed1 = IncrementalMarkingSpeedInBytesPerMillisecond();
753 double speed2 = FinalIncrementalMarkCompactSpeedInBytesPerMillisecond();
754 if (speed1 < kMinimumMarkingSpeed || speed2 < kMinimumMarkingSpeed) {
755 // No data for the incremental marking speed.
756 // Return the non-incremental mark-compact speed.
757 combined_mark_compact_speed_cache_ =
758 MarkCompactSpeedInBytesPerMillisecond();
759 } else {
760 // Combine the speed of incremental step and the speed of the final step.
761 // 1 / (1 / speed1 + 1 / speed2) = speed1 * speed2 / (speed1 + speed2).
762 combined_mark_compact_speed_cache_ = speed1 * speed2 / (speed1 + speed2);
763 }
764 return combined_mark_compact_speed_cache_;
765 }
766
NewSpaceAllocationThroughputInBytesPerMillisecond(double time_ms) const767 double GCTracer::NewSpaceAllocationThroughputInBytesPerMillisecond(
768 double time_ms) const {
769 size_t bytes = new_space_allocation_in_bytes_since_gc_;
770 double durations = allocation_duration_since_gc_;
771 return AverageSpeed(recorded_new_generation_allocations_,
772 MakeBytesAndDuration(bytes, durations), time_ms);
773 }
774
OldGenerationAllocationThroughputInBytesPerMillisecond(double time_ms) const775 double GCTracer::OldGenerationAllocationThroughputInBytesPerMillisecond(
776 double time_ms) const {
777 size_t bytes = old_generation_allocation_in_bytes_since_gc_;
778 double durations = allocation_duration_since_gc_;
779 return AverageSpeed(recorded_old_generation_allocations_,
780 MakeBytesAndDuration(bytes, durations), time_ms);
781 }
782
AllocationThroughputInBytesPerMillisecond(double time_ms) const783 double GCTracer::AllocationThroughputInBytesPerMillisecond(
784 double time_ms) const {
785 return NewSpaceAllocationThroughputInBytesPerMillisecond(time_ms) +
786 OldGenerationAllocationThroughputInBytesPerMillisecond(time_ms);
787 }
788
CurrentAllocationThroughputInBytesPerMillisecond() const789 double GCTracer::CurrentAllocationThroughputInBytesPerMillisecond() const {
790 return AllocationThroughputInBytesPerMillisecond(kThroughputTimeFrameMs);
791 }
792
CurrentOldGenerationAllocationThroughputInBytesPerMillisecond() const793 double GCTracer::CurrentOldGenerationAllocationThroughputInBytesPerMillisecond()
794 const {
795 return OldGenerationAllocationThroughputInBytesPerMillisecond(
796 kThroughputTimeFrameMs);
797 }
798
ContextDisposalRateInMilliseconds() const799 double GCTracer::ContextDisposalRateInMilliseconds() const {
800 if (recorded_context_disposal_times_.Count() <
801 recorded_context_disposal_times_.kSize)
802 return 0.0;
803 double begin = heap_->MonotonicallyIncreasingTimeInMs();
804 double end = recorded_context_disposal_times_.Sum(
805 [](double a, double b) { return b; }, 0.0);
806 return (begin - end) / recorded_context_disposal_times_.Count();
807 }
808
AverageSurvivalRatio() const809 double GCTracer::AverageSurvivalRatio() const {
810 if (recorded_survival_ratios_.Count() == 0) return 0.0;
811 double sum = recorded_survival_ratios_.Sum(
812 [](double a, double b) { return a + b; }, 0.0);
813 return sum / recorded_survival_ratios_.Count();
814 }
815
SurvivalEventsRecorded() const816 bool GCTracer::SurvivalEventsRecorded() const {
817 return recorded_survival_ratios_.Count() > 0;
818 }
819
ResetSurvivalEvents()820 void GCTracer::ResetSurvivalEvents() { recorded_survival_ratios_.Reset(); }
821 } // namespace internal
822 } // namespace v8
823