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 172860 : static size_t CountTotalHolesSize(Heap* heap) {
17 : size_t holes_size = 0;
18 : OldSpaces spaces(heap);
19 518580 : for (OldSpace* space = spaces.next(); space != nullptr;
20 : space = spaces.next()) {
21 : DCHECK_GE(holes_size + space->Waste() + space->Available(), holes_size);
22 345720 : holes_size += space->Waste() + space->Available();
23 : }
24 172860 : return holes_size;
25 : }
26 :
27 0 : RuntimeCallStats::CounterId GCTracer::RCSCounterFromScope(Scope::ScopeId id) {
28 0 : return RuntimeCallStats::counters[kFirstGCIndexInRuntimeCallStats +
29 0 : static_cast<int>(id)];
30 : }
31 :
32 2911178 : GCTracer::Scope::Scope(GCTracer* tracer, ScopeId scope)
33 5822356 : : tracer_(tracer), scope_(scope) {
34 2911178 : start_time_ = tracer_->heap_->MonotonicallyIncreasingTimeInMs();
35 : // TODO(cbruni): remove once we fully moved to a trace-based system.
36 5822358 : if (V8_LIKELY(!FLAG_runtime_stats)) return;
37 0 : runtime_stats_ = tracer_->heap_->isolate()->counters()->runtime_call_stats();
38 : RuntimeCallStats::Enter(runtime_stats_, &timer_,
39 0 : GCTracer::RCSCounterFromScope(scope));
40 : }
41 :
42 2911178 : GCTracer::Scope::~Scope() {
43 : tracer_->AddScopeSample(
44 2911178 : scope_, tracer_->heap_->MonotonicallyIncreasingTimeInMs() - start_time_);
45 : // TODO(cbruni): remove once we fully moved to a trace-based system.
46 2911179 : if (V8_LIKELY(runtime_stats_ == nullptr)) return;
47 0 : RuntimeCallStats::Leave(runtime_stats_, &timer_);
48 2911179 : }
49 :
50 0 : const char* GCTracer::Scope::Name(ScopeId id) {
51 : #define CASE(scope) \
52 : case Scope::scope: \
53 : return "V8.GC_" #scope;
54 0 : switch (id) {
55 0 : TRACER_SCOPES(CASE)
56 : case Scope::NUMBER_OF_SCOPES:
57 : break;
58 : }
59 : #undef CASE
60 0 : return "(unknown)";
61 : }
62 :
63 141437 : GCTracer::Event::Event(Type type, GarbageCollectionReason gc_reason,
64 : const char* collector_reason)
65 : : type(type),
66 : gc_reason(gc_reason),
67 : collector_reason(collector_reason),
68 : start_time(0.0),
69 : end_time(0.0),
70 : reduce_memory(false),
71 : start_object_size(0),
72 : end_object_size(0),
73 : start_memory_size(0),
74 : end_memory_size(0),
75 : start_holes_size(0),
76 : end_holes_size(0),
77 : new_space_object_size(0),
78 : survived_new_space_object_size(0),
79 : incremental_marking_bytes(0),
80 1414370 : incremental_marking_duration(0.0) {
81 11880708 : for (int i = 0; i < Scope::NUMBER_OF_SCOPES; i++) {
82 11880708 : scopes[i] = 0;
83 : }
84 141437 : }
85 :
86 86460 : const char* GCTracer::Event::TypeName(bool short_name) const {
87 86460 : switch (type) {
88 : case SCAVENGER:
89 29634 : return (short_name) ? "s" : "Scavenge";
90 : case MARK_COMPACTOR:
91 : case INCREMENTAL_MARK_COMPACTOR:
92 56826 : return (short_name) ? "ms" : "Mark-sweep";
93 : case MINOR_MARK_COMPACTOR:
94 0 : return (short_name) ? "mmc" : "Minor Mark-Compact";
95 : case START:
96 0 : return (short_name) ? "st" : "Start";
97 : }
98 : return "Unknown Event Type";
99 : }
100 :
101 54999 : GCTracer::GCTracer(Heap* heap)
102 : : heap_(heap),
103 : current_(Event::START, GarbageCollectionReason::kUnknown, nullptr),
104 : previous_(current_),
105 : incremental_marking_bytes_(0),
106 : incremental_marking_duration_(0.0),
107 : incremental_marking_start_time_(0.0),
108 : recorded_incremental_marking_speed_(0.0),
109 : allocation_time_ms_(0.0),
110 : new_space_allocation_counter_bytes_(0),
111 : old_generation_allocation_counter_bytes_(0),
112 : allocation_duration_since_gc_(0.0),
113 : new_space_allocation_in_bytes_since_gc_(0),
114 : old_generation_allocation_in_bytes_since_gc_(0),
115 : combined_mark_compact_speed_cache_(0.0),
116 549990 : start_counter_(0) {
117 : // All accesses to incremental_marking_scope assume that incremental marking
118 : // scopes come first.
119 : STATIC_ASSERT(0 == Scope::FIRST_INCREMENTAL_SCOPE);
120 : // We assume that MC_INCREMENTAL is the first scope so that we can properly
121 : // map it to RuntimeCallStats.
122 : STATIC_ASSERT(0 == Scope::MC_INCREMENTAL);
123 54999 : CHECK(&RuntimeCallStats::GC_MC_INCREMENTAL ==
124 : RuntimeCallStats::counters[GCTracer::kFirstGCIndexInRuntimeCallStats]);
125 54999 : current_.end_time = heap_->MonotonicallyIncreasingTimeInMs();
126 54999 : }
127 :
128 8 : void GCTracer::ResetForTesting() {
129 8 : current_ = Event(Event::START, GarbageCollectionReason::kTesting, nullptr);
130 8 : current_.end_time = heap_->MonotonicallyIncreasingTimeInMs();
131 8 : previous_ = current_;
132 8 : ResetIncrementalMarkingCounters();
133 8 : allocation_time_ms_ = 0.0;
134 8 : new_space_allocation_counter_bytes_ = 0.0;
135 8 : old_generation_allocation_counter_bytes_ = 0.0;
136 8 : allocation_duration_since_gc_ = 0.0;
137 8 : new_space_allocation_in_bytes_since_gc_ = 0.0;
138 8 : old_generation_allocation_in_bytes_since_gc_ = 0.0;
139 8 : combined_mark_compact_speed_cache_ = 0.0;
140 : recorded_minor_gcs_total_.Reset();
141 : recorded_minor_gcs_survived_.Reset();
142 : recorded_compactions_.Reset();
143 : recorded_mark_compacts_.Reset();
144 : recorded_incremental_mark_compacts_.Reset();
145 : recorded_new_generation_allocations_.Reset();
146 : recorded_old_generation_allocations_.Reset();
147 : recorded_context_disposal_times_.Reset();
148 : recorded_survival_ratios_.Reset();
149 8 : start_counter_ = 0;
150 8 : }
151 :
152 29652 : void GCTracer::NotifyYoungGenerationHandling(
153 : YoungGenerationHandling young_generation_handling) {
154 : DCHECK(current_.type == Event::SCAVENGER || start_counter_ > 1);
155 : heap_->isolate()->counters()->young_generation_handling()->AddSample(
156 59304 : static_cast<int>(young_generation_handling));
157 29652 : }
158 :
159 86460 : void GCTracer::Start(GarbageCollector collector,
160 : GarbageCollectionReason gc_reason,
161 : const char* collector_reason) {
162 86460 : start_counter_++;
163 172920 : if (start_counter_ != 1) return;
164 :
165 86430 : previous_ = current_;
166 402516 : double start_time = heap_->MonotonicallyIncreasingTimeInMs();
167 : SampleAllocation(start_time, heap_->NewSpaceAllocationCounter(),
168 172860 : heap_->OldGenerationAllocationCounter());
169 :
170 86430 : switch (collector) {
171 : case SCAVENGER:
172 29634 : current_ = Event(Event::SCAVENGER, gc_reason, collector_reason);
173 29634 : break;
174 : case MINOR_MARK_COMPACTOR:
175 : current_ =
176 0 : Event(Event::MINOR_MARK_COMPACTOR, gc_reason, collector_reason);
177 0 : break;
178 : case MARK_COMPACTOR:
179 113592 : if (heap_->incremental_marking()->WasActivated()) {
180 : current_ = Event(Event::INCREMENTAL_MARK_COMPACTOR, gc_reason,
181 18887 : collector_reason);
182 : } else {
183 37909 : current_ = Event(Event::MARK_COMPACTOR, gc_reason, collector_reason);
184 : }
185 : break;
186 : }
187 :
188 172860 : current_.reduce_memory = heap_->ShouldReduceMemory();
189 86430 : current_.start_time = start_time;
190 86430 : current_.start_object_size = heap_->SizeOfObjects();
191 172860 : current_.start_memory_size = heap_->memory_allocator()->Size();
192 86430 : current_.start_holes_size = CountTotalHolesSize(heap_);
193 172860 : current_.new_space_object_size = heap_->new_space()->Size();
194 :
195 86430 : current_.incremental_marking_bytes = 0;
196 86430 : current_.incremental_marking_duration = 0;
197 :
198 7346550 : for (int i = 0; i < Scope::NUMBER_OF_SCOPES; i++) {
199 7260120 : current_.scopes[i] = 0;
200 : }
201 :
202 86430 : size_t committed_memory = heap_->CommittedMemory() / KB;
203 86430 : size_t used_memory = current_.start_object_size / KB;
204 :
205 86430 : Counters* counters = heap_->isolate()->counters();
206 :
207 86430 : if (Heap::IsYoungGenerationCollector(collector)) {
208 29634 : counters->scavenge_reason()->AddSample(static_cast<int>(gc_reason));
209 : } else {
210 56796 : counters->mark_compact_reason()->AddSample(static_cast<int>(gc_reason));
211 : }
212 : counters->aggregated_memory_heap_committed()->AddSample(start_time,
213 86430 : committed_memory);
214 86430 : counters->aggregated_memory_heap_used()->AddSample(start_time, used_memory);
215 : }
216 :
217 56804 : void GCTracer::ResetIncrementalMarkingCounters() {
218 56804 : if (incremental_marking_duration_ > 0) {
219 : heap_->isolate()->counters()->incremental_marking_sum()->AddSample(
220 32106 : static_cast<int>(incremental_marking_duration_));
221 : }
222 56804 : incremental_marking_bytes_ = 0;
223 56804 : incremental_marking_duration_ = 0;
224 568040 : for (int i = 0; i < Scope::NUMBER_OF_INCREMENTAL_SCOPES; i++) {
225 511236 : incremental_marking_scopes_[i].ResetCurrentCycle();
226 : }
227 56804 : }
228 :
229 86460 : void GCTracer::Stop(GarbageCollector collector) {
230 86460 : start_counter_--;
231 86460 : if (start_counter_ != 0) {
232 : heap_->isolate()->PrintWithTimestamp("[Finished reentrant %s during %s.]\n",
233 : Heap::CollectorName(collector),
234 172950 : current_.TypeName(false));
235 30 : return;
236 : }
237 :
238 : DCHECK_LE(0, start_counter_);
239 : DCHECK((collector == SCAVENGER && current_.type == Event::SCAVENGER) ||
240 : (collector == MINOR_MARK_COMPACTOR &&
241 : current_.type == Event::MINOR_MARK_COMPACTOR) ||
242 : (collector == MARK_COMPACTOR &&
243 : (current_.type == Event::MARK_COMPACTOR ||
244 : current_.type == Event::INCREMENTAL_MARK_COMPACTOR)));
245 :
246 86430 : current_.end_time = heap_->MonotonicallyIncreasingTimeInMs();
247 86430 : current_.end_object_size = heap_->SizeOfObjects();
248 172860 : current_.end_memory_size = heap_->memory_allocator()->Size();
249 86430 : current_.end_holes_size = CountTotalHolesSize(heap_);
250 172860 : current_.survived_new_space_object_size = heap_->SurvivedNewSpaceObjectSize();
251 :
252 86430 : AddAllocation(current_.end_time);
253 :
254 86430 : size_t committed_memory = heap_->CommittedMemory() / KB;
255 86430 : size_t used_memory = current_.end_object_size / KB;
256 : heap_->isolate()->counters()->aggregated_memory_heap_committed()->AddSample(
257 172860 : current_.end_time, committed_memory);
258 : heap_->isolate()->counters()->aggregated_memory_heap_used()->AddSample(
259 172860 : current_.end_time, used_memory);
260 :
261 86430 : double duration = current_.end_time - current_.start_time;
262 :
263 86430 : switch (current_.type) {
264 : case Event::SCAVENGER:
265 : case Event::MINOR_MARK_COMPACTOR:
266 : recorded_minor_gcs_total_.Push(
267 29634 : MakeBytesAndDuration(current_.new_space_object_size, duration));
268 : recorded_minor_gcs_survived_.Push(MakeBytesAndDuration(
269 29634 : current_.survived_new_space_object_size, duration));
270 29634 : break;
271 : case Event::INCREMENTAL_MARK_COMPACTOR:
272 18892 : current_.incremental_marking_bytes = incremental_marking_bytes_;
273 18892 : current_.incremental_marking_duration = incremental_marking_duration_;
274 188920 : for (int i = 0; i < Scope::NUMBER_OF_INCREMENTAL_SCOPES; i++) {
275 170028 : current_.incremental_marking_scopes[i] = incremental_marking_scopes_[i];
276 170028 : current_.scopes[i] = incremental_marking_scopes_[i].duration;
277 : }
278 : RecordIncrementalMarkingSpeed(current_.incremental_marking_bytes,
279 18892 : current_.incremental_marking_duration);
280 : recorded_incremental_mark_compacts_.Push(
281 18892 : MakeBytesAndDuration(current_.start_object_size, duration));
282 18892 : ResetIncrementalMarkingCounters();
283 18892 : combined_mark_compact_speed_cache_ = 0.0;
284 18892 : break;
285 : case Event::MARK_COMPACTOR:
286 : DCHECK_EQ(0u, current_.incremental_marking_bytes);
287 : DCHECK_EQ(0, current_.incremental_marking_duration);
288 : recorded_mark_compacts_.Push(
289 37904 : MakeBytesAndDuration(current_.start_object_size, duration));
290 37904 : ResetIncrementalMarkingCounters();
291 37904 : combined_mark_compact_speed_cache_ = 0.0;
292 37904 : break;
293 : case Event::START:
294 0 : UNREACHABLE();
295 : }
296 :
297 86430 : heap_->UpdateTotalGCTime(duration);
298 :
299 172860 : if ((current_.type == Event::SCAVENGER ||
300 86430 : current_.type == Event::MINOR_MARK_COMPACTOR) &&
301 : FLAG_trace_gc_ignore_scavenger)
302 : return;
303 :
304 86430 : if (FLAG_trace_gc_nvp) {
305 0 : PrintNVP();
306 : } else {
307 86430 : Print();
308 : }
309 :
310 86429 : if (FLAG_trace_gc) {
311 26 : heap_->PrintShortHeapStatistics();
312 : }
313 : }
314 :
315 :
316 5877 : void GCTracer::SampleAllocation(double current_ms,
317 : size_t new_space_counter_bytes,
318 : size_t old_generation_counter_bytes) {
319 92307 : if (allocation_time_ms_ == 0) {
320 : // It is the first sample.
321 17211 : allocation_time_ms_ = current_ms;
322 17211 : new_space_allocation_counter_bytes_ = new_space_counter_bytes;
323 17211 : old_generation_allocation_counter_bytes_ = old_generation_counter_bytes;
324 8291 : 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 75096 : new_space_counter_bytes - new_space_allocation_counter_bytes_;
330 : size_t old_generation_allocated_bytes =
331 75096 : old_generation_counter_bytes - old_generation_allocation_counter_bytes_;
332 75096 : double duration = current_ms - allocation_time_ms_;
333 75096 : allocation_time_ms_ = current_ms;
334 75096 : new_space_allocation_counter_bytes_ = new_space_counter_bytes;
335 75096 : old_generation_allocation_counter_bytes_ = old_generation_counter_bytes;
336 75096 : allocation_duration_since_gc_ += duration;
337 75096 : new_space_allocation_in_bytes_since_gc_ += new_space_allocated_bytes;
338 : old_generation_allocation_in_bytes_since_gc_ +=
339 75096 : old_generation_allocated_bytes;
340 : }
341 :
342 :
343 86442 : void GCTracer::AddAllocation(double current_ms) {
344 86442 : allocation_time_ms_ = current_ms;
345 86442 : if (allocation_duration_since_gc_ > 0) {
346 : recorded_new_generation_allocations_.Push(
347 : MakeBytesAndDuration(new_space_allocation_in_bytes_since_gc_,
348 71641 : allocation_duration_since_gc_));
349 : recorded_old_generation_allocations_.Push(
350 : MakeBytesAndDuration(old_generation_allocation_in_bytes_since_gc_,
351 71641 : allocation_duration_since_gc_));
352 : }
353 86442 : allocation_duration_since_gc_ = 0;
354 86442 : new_space_allocation_in_bytes_since_gc_ = 0;
355 86442 : old_generation_allocation_in_bytes_since_gc_ = 0;
356 86442 : }
357 :
358 :
359 6056 : void GCTracer::AddContextDisposalTime(double time) {
360 : recorded_context_disposal_times_.Push(time);
361 6056 : }
362 :
363 56062 : void GCTracer::AddCompactionEvent(double duration,
364 : size_t live_bytes_compacted) {
365 : recorded_compactions_.Push(
366 56062 : MakeBytesAndDuration(live_bytes_compacted, duration));
367 56062 : }
368 :
369 :
370 75979 : void GCTracer::AddSurvivalRatio(double promotion_ratio) {
371 : recorded_survival_ratios_.Push(promotion_ratio);
372 75979 : }
373 :
374 85916 : void GCTracer::AddIncrementalMarkingStep(double duration, size_t bytes) {
375 85916 : if (bytes > 0) {
376 78002 : incremental_marking_bytes_ += bytes;
377 78002 : incremental_marking_duration_ += duration;
378 : }
379 85916 : }
380 :
381 86430 : void GCTracer::Output(const char* format, ...) const {
382 86430 : if (FLAG_trace_gc) {
383 : va_list arguments;
384 26 : va_start(arguments, format);
385 26 : base::OS::VPrint(format, arguments);
386 26 : 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 86430 : va_start(arguments2, format);
394 86430 : VSNPrintF(buffer, format, arguments2);
395 86430 : va_end(arguments2);
396 :
397 86430 : heap_->AddToRingBuffer(buffer.start());
398 86429 : }
399 :
400 86430 : void GCTracer::Print() const {
401 86430 : double duration = current_.end_time - current_.start_time;
402 : const size_t kIncrementalStatsSize = 128;
403 86430 : char incremental_buffer[kIncrementalStatsSize] = {0};
404 :
405 86430 : 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 18892 : 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 37784 : 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 86430 : 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 259290 : current_.collector_reason != nullptr ? current_.collector_reason : "");
433 86429 : }
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 : "fast_promote=%.2f "
463 : "scavenge=%.2f "
464 : "scavenge.roots=%.2f "
465 : "scavenge.weak=%.2f "
466 : "scavenge.weak_global_handles.identify=%.2f "
467 : "scavenge.weak_global_handles.process=%.2f "
468 : "scavenge.parallel=%.2f "
469 : "incremental.steps_count=%d "
470 : "incremental.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 : "unmapper_chunks=%d "
495 : "unmapper_delayed_chunks=%d "
496 : "context_disposal_rate=%.1f\n",
497 : duration, spent_in_mutator, current_.TypeName(true),
498 0 : current_.reduce_memory, current_.scopes[Scope::HEAP_PROLOGUE],
499 0 : current_.scopes[Scope::HEAP_EPILOGUE],
500 0 : current_.scopes[Scope::HEAP_EPILOGUE_REDUCE_NEW_SPACE],
501 0 : current_.scopes[Scope::HEAP_EXTERNAL_PROLOGUE],
502 0 : current_.scopes[Scope::HEAP_EXTERNAL_EPILOGUE],
503 0 : current_.scopes[Scope::HEAP_EXTERNAL_WEAK_GLOBAL_HANDLES],
504 0 : current_.scopes[Scope::SCAVENGER_FAST_PROMOTE],
505 0 : current_.scopes[Scope::SCAVENGER_SCAVENGE],
506 0 : current_.scopes[Scope::SCAVENGER_SCAVENGE_ROOTS],
507 0 : current_.scopes[Scope::SCAVENGER_SCAVENGE_WEAK],
508 : current_
509 0 : .scopes[Scope::SCAVENGER_SCAVENGE_WEAK_GLOBAL_HANDLES_IDENTIFY],
510 : current_
511 0 : .scopes[Scope::SCAVENGER_SCAVENGE_WEAK_GLOBAL_HANDLES_PROCESS],
512 0 : current_.scopes[Scope::SCAVENGER_SCAVENGE_PARALLEL],
513 : current_.incremental_marking_scopes[GCTracer::Scope::MC_INCREMENTAL]
514 : .steps,
515 0 : current_.scopes[Scope::MC_INCREMENTAL],
516 : ScavengeSpeedInBytesPerMillisecond(), current_.start_object_size,
517 : current_.end_object_size, current_.start_holes_size,
518 : current_.end_holes_size, allocated_since_last_gc,
519 : heap_->promoted_objects_size(),
520 : heap_->semi_space_copied_object_size(),
521 : heap_->nodes_died_in_new_space_, heap_->nodes_copied_in_new_space_,
522 : heap_->nodes_promoted_, heap_->promotion_ratio_,
523 : AverageSurvivalRatio(), heap_->promotion_rate_,
524 : heap_->semi_space_copied_rate_,
525 : NewSpaceAllocationThroughputInBytesPerMillisecond(),
526 : heap_->memory_allocator()->unmapper()->NumberOfChunks(),
527 : heap_->memory_allocator()->unmapper()->NumberOfDelayedChunks(),
528 0 : ContextDisposalRateInMilliseconds());
529 0 : break;
530 : case Event::MINOR_MARK_COMPACTOR:
531 : heap_->isolate()->PrintWithTimestamp(
532 : "pause=%.1f "
533 : "mutator=%.1f "
534 : "gc=%s "
535 : "reduce_memory=%d "
536 : "minor_mc=%.2f "
537 : "finish_sweeping=%.2f "
538 : "mark=%.2f "
539 : "mark.seed=%.2f "
540 : "mark.roots=%.2f "
541 : "mark.weak=%.2f "
542 : "mark.global_handles=%.2f "
543 : "clear=%.2f "
544 : "clear.string_table=%.2f "
545 : "clear.weak_lists=%.2f "
546 : "evacuate=%.2f "
547 : "evacuate.copy=%.2f "
548 : "evacuate.update_pointers=%.2f "
549 : "evacuate.update_pointers.to_new_roots=%.2f "
550 : "evacuate.update_pointers.slots=%.2f "
551 : "update_marking_deque=%.2f "
552 : "reset_liveness=%.2f\n",
553 : duration, spent_in_mutator, "mmc", current_.reduce_memory,
554 0 : current_.scopes[Scope::MINOR_MC],
555 0 : current_.scopes[Scope::MINOR_MC_SWEEPING],
556 0 : current_.scopes[Scope::MINOR_MC_MARK],
557 0 : current_.scopes[Scope::MINOR_MC_MARK_SEED],
558 0 : current_.scopes[Scope::MINOR_MC_MARK_ROOTS],
559 0 : current_.scopes[Scope::MINOR_MC_MARK_WEAK],
560 0 : current_.scopes[Scope::MINOR_MC_MARK_GLOBAL_HANDLES],
561 0 : current_.scopes[Scope::MINOR_MC_CLEAR],
562 0 : current_.scopes[Scope::MINOR_MC_CLEAR_STRING_TABLE],
563 0 : current_.scopes[Scope::MINOR_MC_CLEAR_WEAK_LISTS],
564 0 : current_.scopes[Scope::MINOR_MC_EVACUATE],
565 0 : current_.scopes[Scope::MINOR_MC_EVACUATE_COPY],
566 0 : current_.scopes[Scope::MINOR_MC_EVACUATE_UPDATE_POINTERS],
567 : current_
568 0 : .scopes[Scope::MINOR_MC_EVACUATE_UPDATE_POINTERS_TO_NEW_ROOTS],
569 0 : current_.scopes[Scope::MINOR_MC_EVACUATE_UPDATE_POINTERS_SLOTS],
570 0 : current_.scopes[Scope::MINOR_MC_MARKING_DEQUE],
571 0 : current_.scopes[Scope::MINOR_MC_RESET_LIVENESS]);
572 0 : break;
573 : case Event::MARK_COMPACTOR:
574 : case Event::INCREMENTAL_MARK_COMPACTOR:
575 : heap_->isolate()->PrintWithTimestamp(
576 : "pause=%.1f "
577 : "mutator=%.1f "
578 : "gc=%s "
579 : "reduce_memory=%d "
580 : "heap.prologue=%.2f "
581 : "heap.epilogue=%.2f "
582 : "heap.epilogue.reduce_new_space=%.2f "
583 : "heap.external.prologue=%.1f "
584 : "heap.external.epilogue=%.1f "
585 : "heap.external.weak_global_handles=%.1f "
586 : "clear=%1.f "
587 : "clear.dependent_code=%.1f "
588 : "clear.maps=%.1f "
589 : "clear.slots_buffer=%.1f "
590 : "clear.store_buffer=%.1f "
591 : "clear.string_table=%.1f "
592 : "clear.weak_cells=%.1f "
593 : "clear.weak_collections=%.1f "
594 : "clear.weak_lists=%.1f "
595 : "epilogue=%.1f "
596 : "evacuate=%.1f "
597 : "evacuate.candidates=%.1f "
598 : "evacuate.clean_up=%.1f "
599 : "evacuate.copy=%.1f "
600 : "evacuate.prologue=%.1f "
601 : "evacuate.epilogue=%.1f "
602 : "evacuate.rebalance=%.1f "
603 : "evacuate.update_pointers=%.1f "
604 : "evacuate.update_pointers.to_new_roots=%.1f "
605 : "evacuate.update_pointers.slots.main=%.1f "
606 : "evacuate.update_pointers.slots.map_space=%.1f "
607 : "evacuate.update_pointers.weak=%.1f "
608 : "finish=%.1f "
609 : "mark=%.1f "
610 : "mark.finish_incremental=%.1f "
611 : "mark.roots=%.1f "
612 : "mark.main=%.1f "
613 : "mark.weak_closure=%.1f "
614 : "mark.weak_closure.ephemeral=%.1f "
615 : "mark.weak_closure.weak_handles=%.1f "
616 : "mark.weak_closure.weak_roots=%.1f "
617 : "mark.weak_closure.harmony=%.1f "
618 : "mark.wrapper_prologue=%.1f "
619 : "mark.wrapper_epilogue=%.1f "
620 : "mark.wrapper_tracing=%.1f "
621 : "prologue=%.1f "
622 : "sweep=%.1f "
623 : "sweep.code=%.1f "
624 : "sweep.map=%.1f "
625 : "sweep.old=%.1f "
626 : "incremental=%.1f "
627 : "incremental.finalize=%.1f "
628 : "incremental.finalize.body=%.1f "
629 : "incremental.finalize.external.prologue=%.1f "
630 : "incremental.finalize.external.epilogue=%.1f "
631 : "incremental.sweeping=%.1f "
632 : "incremental.wrapper_prologue=%.1f "
633 : "incremental.wrapper_tracing=%.1f "
634 : "incremental_wrapper_tracing_longest_step=%.1f "
635 : "incremental_finalize_longest_step=%.1f "
636 : "incremental_finalize_steps_count=%d "
637 : "incremental_longest_step=%.1f "
638 : "incremental_steps_count=%d "
639 : "incremental_marking_throughput=%.f "
640 : "incremental_walltime_duration=%.f "
641 : "total_size_before=%" PRIuS
642 : " "
643 : "total_size_after=%" PRIuS
644 : " "
645 : "holes_size_before=%" PRIuS
646 : " "
647 : "holes_size_after=%" PRIuS
648 : " "
649 : "allocated=%" PRIuS
650 : " "
651 : "promoted=%" PRIuS
652 : " "
653 : "semi_space_copied=%" PRIuS
654 : " "
655 : "nodes_died_in_new=%d "
656 : "nodes_copied_in_new=%d "
657 : "nodes_promoted=%d "
658 : "promotion_ratio=%.1f%% "
659 : "average_survival_ratio=%.1f%% "
660 : "promotion_rate=%.1f%% "
661 : "semi_space_copy_rate=%.1f%% "
662 : "new_space_allocation_throughput=%.1f "
663 : "unmapper_chunks=%d "
664 : "unmapper_delayed_chunks=%d "
665 : "context_disposal_rate=%.1f "
666 : "compaction_speed=%.f\n",
667 : duration, spent_in_mutator, current_.TypeName(true),
668 0 : current_.reduce_memory, current_.scopes[Scope::HEAP_PROLOGUE],
669 0 : current_.scopes[Scope::HEAP_EPILOGUE],
670 0 : current_.scopes[Scope::HEAP_EPILOGUE_REDUCE_NEW_SPACE],
671 0 : current_.scopes[Scope::HEAP_EXTERNAL_PROLOGUE],
672 0 : current_.scopes[Scope::HEAP_EXTERNAL_EPILOGUE],
673 0 : current_.scopes[Scope::HEAP_EXTERNAL_WEAK_GLOBAL_HANDLES],
674 0 : current_.scopes[Scope::MC_CLEAR],
675 0 : current_.scopes[Scope::MC_CLEAR_DEPENDENT_CODE],
676 0 : current_.scopes[Scope::MC_CLEAR_MAPS],
677 0 : current_.scopes[Scope::MC_CLEAR_SLOTS_BUFFER],
678 0 : current_.scopes[Scope::MC_CLEAR_STORE_BUFFER],
679 0 : current_.scopes[Scope::MC_CLEAR_STRING_TABLE],
680 0 : current_.scopes[Scope::MC_CLEAR_WEAK_CELLS],
681 0 : current_.scopes[Scope::MC_CLEAR_WEAK_COLLECTIONS],
682 0 : current_.scopes[Scope::MC_CLEAR_WEAK_LISTS],
683 0 : current_.scopes[Scope::MC_EPILOGUE],
684 0 : current_.scopes[Scope::MC_EVACUATE],
685 0 : current_.scopes[Scope::MC_EVACUATE_CANDIDATES],
686 0 : current_.scopes[Scope::MC_EVACUATE_CLEAN_UP],
687 0 : current_.scopes[Scope::MC_EVACUATE_COPY],
688 0 : current_.scopes[Scope::MC_EVACUATE_PROLOGUE],
689 0 : current_.scopes[Scope::MC_EVACUATE_EPILOGUE],
690 0 : current_.scopes[Scope::MC_EVACUATE_REBALANCE],
691 0 : current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS],
692 0 : current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS_TO_NEW_ROOTS],
693 0 : current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS_SLOTS_MAIN],
694 0 : current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS_SLOTS_MAP_SPACE],
695 0 : current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS_WEAK],
696 0 : current_.scopes[Scope::MC_FINISH], current_.scopes[Scope::MC_MARK],
697 0 : current_.scopes[Scope::MC_MARK_FINISH_INCREMENTAL],
698 0 : current_.scopes[Scope::MC_MARK_ROOTS],
699 0 : current_.scopes[Scope::MC_MARK_MAIN],
700 0 : current_.scopes[Scope::MC_MARK_WEAK_CLOSURE],
701 0 : current_.scopes[Scope::MC_MARK_WEAK_CLOSURE_EPHEMERAL],
702 0 : current_.scopes[Scope::MC_MARK_WEAK_CLOSURE_WEAK_HANDLES],
703 0 : current_.scopes[Scope::MC_MARK_WEAK_CLOSURE_WEAK_ROOTS],
704 0 : current_.scopes[Scope::MC_MARK_WEAK_CLOSURE_HARMONY],
705 0 : current_.scopes[Scope::MC_MARK_WRAPPER_PROLOGUE],
706 0 : current_.scopes[Scope::MC_MARK_WRAPPER_EPILOGUE],
707 0 : current_.scopes[Scope::MC_MARK_WRAPPER_TRACING],
708 0 : current_.scopes[Scope::MC_PROLOGUE], current_.scopes[Scope::MC_SWEEP],
709 0 : current_.scopes[Scope::MC_SWEEP_CODE],
710 0 : current_.scopes[Scope::MC_SWEEP_MAP],
711 0 : current_.scopes[Scope::MC_SWEEP_OLD],
712 0 : current_.scopes[Scope::MC_INCREMENTAL],
713 0 : current_.scopes[Scope::MC_INCREMENTAL_FINALIZE],
714 0 : current_.scopes[Scope::MC_INCREMENTAL_FINALIZE_BODY],
715 0 : current_.scopes[Scope::MC_INCREMENTAL_EXTERNAL_PROLOGUE],
716 0 : current_.scopes[Scope::MC_INCREMENTAL_EXTERNAL_EPILOGUE],
717 0 : current_.scopes[Scope::MC_INCREMENTAL_SWEEPING],
718 0 : current_.scopes[Scope::MC_INCREMENTAL_WRAPPER_PROLOGUE],
719 0 : current_.scopes[Scope::MC_INCREMENTAL_WRAPPER_TRACING],
720 : current_
721 : .incremental_marking_scopes[Scope::MC_INCREMENTAL_WRAPPER_TRACING]
722 : .longest_step,
723 : current_
724 : .incremental_marking_scopes[Scope::MC_INCREMENTAL_FINALIZE_BODY]
725 : .longest_step,
726 : current_
727 : .incremental_marking_scopes[Scope::MC_INCREMENTAL_FINALIZE_BODY]
728 : .steps,
729 : current_.incremental_marking_scopes[Scope::MC_INCREMENTAL]
730 : .longest_step,
731 : current_.incremental_marking_scopes[Scope::MC_INCREMENTAL].steps,
732 : IncrementalMarkingSpeedInBytesPerMillisecond(),
733 : incremental_walltime_duration, current_.start_object_size,
734 : current_.end_object_size, current_.start_holes_size,
735 : current_.end_holes_size, allocated_since_last_gc,
736 : heap_->promoted_objects_size(),
737 : heap_->semi_space_copied_object_size(),
738 : heap_->nodes_died_in_new_space_, heap_->nodes_copied_in_new_space_,
739 : heap_->nodes_promoted_, heap_->promotion_ratio_,
740 : AverageSurvivalRatio(), heap_->promotion_rate_,
741 : heap_->semi_space_copied_rate_,
742 : NewSpaceAllocationThroughputInBytesPerMillisecond(),
743 : heap_->memory_allocator()->unmapper()->NumberOfChunks(),
744 : heap_->memory_allocator()->unmapper()->NumberOfDelayedChunks(),
745 : ContextDisposalRateInMilliseconds(),
746 0 : CompactionSpeedInBytesPerMillisecond());
747 0 : break;
748 : case Event::START:
749 : break;
750 : default:
751 0 : UNREACHABLE();
752 : }
753 0 : }
754 :
755 556858 : double GCTracer::AverageSpeed(const base::RingBuffer<BytesAndDuration>& buffer,
756 : const BytesAndDuration& initial, double time_ms) {
757 : BytesAndDuration sum = buffer.Sum(
758 : [time_ms](BytesAndDuration a, BytesAndDuration b) {
759 2205967 : if (time_ms != 0 && a.second >= time_ms) return a;
760 2205315 : return std::make_pair(a.first + b.first, a.second + b.second);
761 : },
762 556858 : initial);
763 556857 : uint64_t bytes = sum.first;
764 556857 : double durations = sum.second;
765 556857 : if (durations == 0.0) return 0;
766 376595 : double speed = bytes / durations;
767 : const int max_speed = 1024 * MB;
768 : const int min_speed = 1;
769 376595 : if (speed >= max_speed) return max_speed;
770 376590 : if (speed <= min_speed) return min_speed;
771 326942 : return speed;
772 : }
773 :
774 0 : double GCTracer::AverageSpeed(
775 : const base::RingBuffer<BytesAndDuration>& buffer) {
776 267822 : return AverageSpeed(buffer, MakeBytesAndDuration(0, 0), 0);
777 : }
778 :
779 0 : void GCTracer::RecordIncrementalMarkingSpeed(size_t bytes, double duration) {
780 18892 : if (duration == 0 || bytes == 0) return;
781 16053 : double current_speed = bytes / duration;
782 16053 : if (recorded_incremental_marking_speed_ == 0) {
783 8854 : recorded_incremental_marking_speed_ = current_speed;
784 : } else {
785 : recorded_incremental_marking_speed_ =
786 7199 : (recorded_incremental_marking_speed_ + current_speed) / 2;
787 : }
788 : }
789 :
790 81083 : double GCTracer::IncrementalMarkingSpeedInBytesPerMillisecond() const {
791 : const int kConservativeSpeedInBytesPerMillisecond = 128 * KB;
792 158969 : if (recorded_incremental_marking_speed_ != 0) {
793 : return recorded_incremental_marking_speed_;
794 : }
795 105477 : if (incremental_marking_duration_ != 0.0) {
796 38185 : return incremental_marking_bytes_ / incremental_marking_duration_;
797 : }
798 : return kConservativeSpeedInBytesPerMillisecond;
799 : }
800 :
801 35250 : double GCTracer::ScavengeSpeedInBytesPerMillisecond(
802 : ScavengeSpeedMode mode) const {
803 35250 : if (mode == kForAllObjects) {
804 11178 : return AverageSpeed(recorded_minor_gcs_total_);
805 : } else {
806 59322 : return AverageSpeed(recorded_minor_gcs_survived_);
807 : }
808 : }
809 :
810 88018 : double GCTracer::CompactionSpeedInBytesPerMillisecond() const {
811 176036 : return AverageSpeed(recorded_compactions_);
812 : }
813 :
814 0 : double GCTracer::MarkCompactSpeedInBytesPerMillisecond() const {
815 66668 : return AverageSpeed(recorded_mark_compacts_);
816 : }
817 :
818 0 : double GCTracer::FinalIncrementalMarkCompactSpeedInBytesPerMillisecond() const {
819 77886 : return AverageSpeed(recorded_incremental_mark_compacts_);
820 : }
821 :
822 86452 : double GCTracer::CombinedMarkCompactSpeedInBytesPerMillisecond() {
823 86452 : if (combined_mark_compact_speed_cache_ > 0)
824 : return combined_mark_compact_speed_cache_;
825 : const double kMinimumMarkingSpeed = 0.5;
826 : double speed1 = IncrementalMarkingSpeedInBytesPerMillisecond();
827 : double speed2 = FinalIncrementalMarkCompactSpeedInBytesPerMillisecond();
828 77886 : if (speed1 < kMinimumMarkingSpeed || speed2 < kMinimumMarkingSpeed) {
829 : // No data for the incremental marking speed.
830 : // Return the non-incremental mark-compact speed.
831 : combined_mark_compact_speed_cache_ =
832 66669 : MarkCompactSpeedInBytesPerMillisecond();
833 : } else {
834 : // Combine the speed of incremental step and the speed of the final step.
835 : // 1 / (1 / speed1 + 1 / speed2) = speed1 * speed2 / (speed1 + speed2).
836 11218 : combined_mark_compact_speed_cache_ = speed1 * speed2 / (speed1 + speed2);
837 : }
838 77887 : return combined_mark_compact_speed_cache_;
839 : }
840 :
841 29665 : double GCTracer::NewSpaceAllocationThroughputInBytesPerMillisecond(
842 : double time_ms) const {
843 116119 : size_t bytes = new_space_allocation_in_bytes_since_gc_;
844 116119 : double durations = allocation_duration_since_gc_;
845 : return AverageSpeed(recorded_new_generation_allocations_,
846 116119 : MakeBytesAndDuration(bytes, durations), time_ms);
847 : }
848 :
849 3 : double GCTracer::OldGenerationAllocationThroughputInBytesPerMillisecond(
850 : double time_ms) const {
851 172909 : size_t bytes = old_generation_allocation_in_bytes_since_gc_;
852 172909 : double durations = allocation_duration_since_gc_;
853 : return AverageSpeed(recorded_old_generation_allocations_,
854 172909 : MakeBytesAndDuration(bytes, durations), time_ms);
855 : }
856 :
857 86454 : double GCTracer::AllocationThroughputInBytesPerMillisecond(
858 : double time_ms) const {
859 : return NewSpaceAllocationThroughputInBytesPerMillisecond(time_ms) +
860 86454 : OldGenerationAllocationThroughputInBytesPerMillisecond(time_ms);
861 : }
862 :
863 86452 : double GCTracer::CurrentAllocationThroughputInBytesPerMillisecond() const {
864 86452 : return AllocationThroughputInBytesPerMillisecond(kThroughputTimeFrameMs);
865 : }
866 :
867 86452 : double GCTracer::CurrentOldGenerationAllocationThroughputInBytesPerMillisecond()
868 : const {
869 : return OldGenerationAllocationThroughputInBytesPerMillisecond(
870 86452 : kThroughputTimeFrameMs);
871 : }
872 :
873 5855 : double GCTracer::ContextDisposalRateInMilliseconds() const {
874 5855 : if (recorded_context_disposal_times_.Count() <
875 : recorded_context_disposal_times_.kSize)
876 : return 0.0;
877 216 : double begin = heap_->MonotonicallyIncreasingTimeInMs();
878 : double end = recorded_context_disposal_times_.Sum(
879 : [](double a, double b) { return b; }, 0.0);
880 216 : return (begin - end) / recorded_context_disposal_times_.Count();
881 : }
882 :
883 20776 : double GCTracer::AverageSurvivalRatio() const {
884 20776 : if (recorded_survival_ratios_.Count() == 0) return 0.0;
885 : double sum = recorded_survival_ratios_.Sum(
886 155819 : [](double a, double b) { return a + b; }, 0.0);
887 20776 : return sum / recorded_survival_ratios_.Count();
888 : }
889 :
890 20776 : bool GCTracer::SurvivalEventsRecorded() const {
891 20776 : return recorded_survival_ratios_.Count() > 0;
892 : }
893 :
894 20 : void GCTracer::ResetSurvivalEvents() { recorded_survival_ratios_.Reset(); }
895 :
896 19399 : void GCTracer::NotifyIncrementalMarkingStart() {
897 19399 : incremental_marking_start_time_ = heap_->MonotonicallyIncreasingTimeInMs();
898 19399 : }
899 :
900 : } // namespace internal
901 : } // namespace v8
|
