blob: 3c46f5292dfdd2d37e39e2da0e35c52627c6ffeb [file] [log] [blame]
Ben Murdochb8a8cc12014-11-26 15:28:44 +00001// 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
Ben Murdochb8a8cc12014-11-26 15:28:44 +00005#include "src/heap/gc-tracer.h"
6
Ben Murdoch4a90d5f2016-03-22 12:00:34 +00007#include "src/counters.h"
8#include "src/heap/heap-inl.h"
9#include "src/isolate.h"
10
Ben Murdochb8a8cc12014-11-26 15:28:44 +000011namespace v8 {
12namespace internal {
13
14static 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
Ben Murdoch4a90d5f2016-03-22 12:00:34 +000024GCTracer::Scope::Scope(GCTracer* tracer, ScopeId scope)
25 : tracer_(tracer), scope_(scope) {
26 start_time_ = tracer_->heap_->MonotonicallyIncreasingTimeInMs();
Ben Murdochda12d292016-06-02 14:46:10 +010027 // TODO(cbruni): remove once we fully moved to a trace-based system.
28 if (FLAG_runtime_call_stats) {
29 RuntimeCallStats* stats =
30 tracer_->heap_->isolate()->counters()->runtime_call_stats();
31 timer_.Initialize(&stats->GC, stats->current_timer());
32 stats->Enter(&timer_);
33 }
Ben Murdoch4a90d5f2016-03-22 12:00:34 +000034}
35
36
37GCTracer::Scope::~Scope() {
38 DCHECK(scope_ < NUMBER_OF_SCOPES); // scope_ is unsigned.
39 tracer_->current_.scopes[scope_] +=
40 tracer_->heap_->MonotonicallyIncreasingTimeInMs() - start_time_;
Ben Murdochda12d292016-06-02 14:46:10 +010041 // TODO(cbruni): remove once we fully moved to a trace-based system.
42 if (FLAG_runtime_call_stats) {
43 tracer_->heap_->isolate()->counters()->runtime_call_stats()->Leave(&timer_);
44 }
Ben Murdoch4a90d5f2016-03-22 12:00:34 +000045}
46
Ben Murdochda12d292016-06-02 14:46:10 +010047const char* GCTracer::Scope::Name(ScopeId id) {
48#define CASE(scope) \
49 case Scope::scope: \
50 return "V8.GC_" #scope;
51 switch (id) {
52 TRACER_SCOPES(CASE)
53 case Scope::NUMBER_OF_SCOPES:
54 break;
55 }
56#undef CASE
57 return "(unknown)";
Ben Murdochb8a8cc12014-11-26 15:28:44 +000058}
59
Ben Murdochb8a8cc12014-11-26 15:28:44 +000060GCTracer::Event::Event(Type type, const char* gc_reason,
61 const char* collector_reason)
62 : type(type),
63 gc_reason(gc_reason),
64 collector_reason(collector_reason),
65 start_time(0.0),
66 end_time(0.0),
Ben Murdoch4a90d5f2016-03-22 12:00:34 +000067 reduce_memory(false),
Ben Murdochb8a8cc12014-11-26 15:28:44 +000068 start_object_size(0),
69 end_object_size(0),
70 start_memory_size(0),
71 end_memory_size(0),
72 start_holes_size(0),
73 end_holes_size(0),
74 cumulative_incremental_marking_steps(0),
75 incremental_marking_steps(0),
76 cumulative_incremental_marking_bytes(0),
77 incremental_marking_bytes(0),
78 cumulative_incremental_marking_duration(0.0),
79 incremental_marking_duration(0.0),
80 cumulative_pure_incremental_marking_duration(0.0),
81 pure_incremental_marking_duration(0.0),
82 longest_incremental_marking_step(0.0) {
83 for (int i = 0; i < Scope::NUMBER_OF_SCOPES; i++) {
84 scopes[i] = 0;
85 }
86}
87
88
89const char* GCTracer::Event::TypeName(bool short_name) const {
90 switch (type) {
91 case SCAVENGER:
92 if (short_name) {
93 return "s";
94 } else {
95 return "Scavenge";
96 }
97 case MARK_COMPACTOR:
Emily Bernierd0a1eb72015-03-24 16:35:39 -040098 case INCREMENTAL_MARK_COMPACTOR:
Ben Murdochb8a8cc12014-11-26 15:28:44 +000099 if (short_name) {
100 return "ms";
101 } else {
102 return "Mark-sweep";
103 }
104 case START:
105 if (short_name) {
106 return "st";
107 } else {
108 return "Start";
109 }
110 }
111 return "Unknown Event Type";
112}
113
114
115GCTracer::GCTracer(Heap* heap)
116 : heap_(heap),
117 cumulative_incremental_marking_steps_(0),
118 cumulative_incremental_marking_bytes_(0),
119 cumulative_incremental_marking_duration_(0.0),
120 cumulative_pure_incremental_marking_duration_(0.0),
121 longest_incremental_marking_step_(0.0),
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000122 cumulative_incremental_marking_finalization_steps_(0),
123 cumulative_incremental_marking_finalization_duration_(0.0),
124 longest_incremental_marking_finalization_step_(0.0),
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000125 cumulative_marking_duration_(0.0),
126 cumulative_sweeping_duration_(0.0),
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000127 allocation_time_ms_(0.0),
128 new_space_allocation_counter_bytes_(0),
129 old_generation_allocation_counter_bytes_(0),
130 allocation_duration_since_gc_(0.0),
131 new_space_allocation_in_bytes_since_gc_(0),
132 old_generation_allocation_in_bytes_since_gc_(0),
133 combined_mark_compact_speed_cache_(0.0),
Emily Bernierd0a1eb72015-03-24 16:35:39 -0400134 start_counter_(0) {
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000135 current_ = Event(Event::START, NULL, NULL);
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000136 current_.end_time = heap_->MonotonicallyIncreasingTimeInMs();
Emily Bernierd0a1eb72015-03-24 16:35:39 -0400137 previous_ = previous_incremental_mark_compactor_event_ = current_;
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000138}
139
140
141void GCTracer::Start(GarbageCollector collector, const char* gc_reason,
142 const char* collector_reason) {
Emily Bernierd0a1eb72015-03-24 16:35:39 -0400143 start_counter_++;
144 if (start_counter_ != 1) return;
145
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000146 previous_ = current_;
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000147 double start_time = heap_->MonotonicallyIncreasingTimeInMs();
148 SampleAllocation(start_time, heap_->NewSpaceAllocationCounter(),
149 heap_->OldGenerationAllocationCounter());
Emily Bernierd0a1eb72015-03-24 16:35:39 -0400150 if (current_.type == Event::INCREMENTAL_MARK_COMPACTOR)
151 previous_incremental_mark_compactor_event_ = current_;
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000152
153 if (collector == SCAVENGER) {
154 current_ = Event(Event::SCAVENGER, gc_reason, collector_reason);
Emily Bernierd0a1eb72015-03-24 16:35:39 -0400155 } else if (collector == MARK_COMPACTOR) {
156 if (heap_->incremental_marking()->WasActivated()) {
157 current_ =
158 Event(Event::INCREMENTAL_MARK_COMPACTOR, gc_reason, collector_reason);
159 } else {
160 current_ = Event(Event::MARK_COMPACTOR, gc_reason, collector_reason);
161 }
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000162 }
163
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000164 current_.reduce_memory = heap_->ShouldReduceMemory();
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000165 current_.start_time = start_time;
166 current_.start_object_size = heap_->SizeOfObjects();
167 current_.start_memory_size = heap_->isolate()->memory_allocator()->Size();
168 current_.start_holes_size = CountTotalHolesSize(heap_);
169 current_.new_space_object_size =
170 heap_->new_space()->top() - heap_->new_space()->bottom();
171
172 current_.cumulative_incremental_marking_steps =
173 cumulative_incremental_marking_steps_;
174 current_.cumulative_incremental_marking_bytes =
175 cumulative_incremental_marking_bytes_;
176 current_.cumulative_incremental_marking_duration =
177 cumulative_incremental_marking_duration_;
178 current_.cumulative_pure_incremental_marking_duration =
179 cumulative_pure_incremental_marking_duration_;
180 current_.longest_incremental_marking_step = longest_incremental_marking_step_;
181
182 for (int i = 0; i < Scope::NUMBER_OF_SCOPES; i++) {
183 current_.scopes[i] = 0;
184 }
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000185 int committed_memory = static_cast<int>(heap_->CommittedMemory() / KB);
186 int used_memory = static_cast<int>(current_.start_object_size / KB);
187 heap_->isolate()->counters()->aggregated_memory_heap_committed()->AddSample(
188 start_time, committed_memory);
189 heap_->isolate()->counters()->aggregated_memory_heap_used()->AddSample(
190 start_time, used_memory);
Ben Murdochda12d292016-06-02 14:46:10 +0100191 // TODO(cbruni): remove once we fully moved to a trace-based system.
192 if (FLAG_runtime_call_stats) {
193 RuntimeCallStats* stats =
194 heap_->isolate()->counters()->runtime_call_stats();
195 timer_.Initialize(&stats->GC, stats->current_timer());
196 stats->Enter(&timer_);
197 }
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000198}
199
Emily Bernierd0a1eb72015-03-24 16:35:39 -0400200void GCTracer::Stop(GarbageCollector collector) {
201 start_counter_--;
202 if (start_counter_ != 0) {
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000203 Output("[Finished reentrant %s during %s.]\n",
204 collector == SCAVENGER ? "Scavenge" : "Mark-sweep",
205 current_.TypeName(false));
Emily Bernierd0a1eb72015-03-24 16:35:39 -0400206 return;
207 }
208
209 DCHECK(start_counter_ >= 0);
210 DCHECK((collector == SCAVENGER && current_.type == Event::SCAVENGER) ||
211 (collector == MARK_COMPACTOR &&
212 (current_.type == Event::MARK_COMPACTOR ||
213 current_.type == Event::INCREMENTAL_MARK_COMPACTOR)));
214
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000215 current_.end_time = heap_->MonotonicallyIncreasingTimeInMs();
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000216 current_.end_object_size = heap_->SizeOfObjects();
217 current_.end_memory_size = heap_->isolate()->memory_allocator()->Size();
218 current_.end_holes_size = CountTotalHolesSize(heap_);
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000219 current_.survived_new_space_object_size = heap_->SurvivedNewSpaceObjectSize();
220
221 AddAllocation(current_.end_time);
222
223 int committed_memory = static_cast<int>(heap_->CommittedMemory() / KB);
224 int used_memory = static_cast<int>(current_.end_object_size / KB);
225 heap_->isolate()->counters()->aggregated_memory_heap_committed()->AddSample(
226 current_.end_time, committed_memory);
227 heap_->isolate()->counters()->aggregated_memory_heap_used()->AddSample(
228 current_.end_time, used_memory);
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000229
Ben Murdochda12d292016-06-02 14:46:10 +0100230 double duration = current_.end_time - current_.start_time;
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000231 if (current_.type == Event::SCAVENGER) {
232 current_.incremental_marking_steps =
233 current_.cumulative_incremental_marking_steps -
234 previous_.cumulative_incremental_marking_steps;
235 current_.incremental_marking_bytes =
236 current_.cumulative_incremental_marking_bytes -
237 previous_.cumulative_incremental_marking_bytes;
238 current_.incremental_marking_duration =
239 current_.cumulative_incremental_marking_duration -
240 previous_.cumulative_incremental_marking_duration;
241 current_.pure_incremental_marking_duration =
242 current_.cumulative_pure_incremental_marking_duration -
243 previous_.cumulative_pure_incremental_marking_duration;
Ben Murdochda12d292016-06-02 14:46:10 +0100244 recorded_scavenges_total_.Push(
245 MakeBytesAndDuration(current_.new_space_object_size, duration));
246 recorded_scavenges_survived_.Push(MakeBytesAndDuration(
247 current_.survived_new_space_object_size, duration));
Emily Bernierd0a1eb72015-03-24 16:35:39 -0400248 } else if (current_.type == Event::INCREMENTAL_MARK_COMPACTOR) {
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000249 current_.incremental_marking_steps =
250 current_.cumulative_incremental_marking_steps -
Emily Bernierd0a1eb72015-03-24 16:35:39 -0400251 previous_incremental_mark_compactor_event_
252 .cumulative_incremental_marking_steps;
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000253 current_.incremental_marking_bytes =
254 current_.cumulative_incremental_marking_bytes -
Emily Bernierd0a1eb72015-03-24 16:35:39 -0400255 previous_incremental_mark_compactor_event_
256 .cumulative_incremental_marking_bytes;
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000257 current_.incremental_marking_duration =
258 current_.cumulative_incremental_marking_duration -
Emily Bernierd0a1eb72015-03-24 16:35:39 -0400259 previous_incremental_mark_compactor_event_
260 .cumulative_incremental_marking_duration;
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000261 current_.pure_incremental_marking_duration =
262 current_.cumulative_pure_incremental_marking_duration -
Emily Bernierd0a1eb72015-03-24 16:35:39 -0400263 previous_incremental_mark_compactor_event_
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000264 .cumulative_pure_incremental_marking_duration;
265 longest_incremental_marking_step_ = 0.0;
Ben Murdochda12d292016-06-02 14:46:10 +0100266 recorded_incremental_marking_steps_.Push(
267 MakeBytesAndDuration(current_.incremental_marking_bytes,
268 current_.pure_incremental_marking_duration));
269 recorded_incremental_mark_compacts_.Push(
270 MakeBytesAndDuration(current_.start_object_size, duration));
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000271 combined_mark_compact_speed_cache_ = 0.0;
Emily Bernierd0a1eb72015-03-24 16:35:39 -0400272 } else {
273 DCHECK(current_.incremental_marking_bytes == 0);
274 DCHECK(current_.incremental_marking_duration == 0);
275 DCHECK(current_.pure_incremental_marking_duration == 0);
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000276 longest_incremental_marking_step_ = 0.0;
Ben Murdochda12d292016-06-02 14:46:10 +0100277 recorded_mark_compacts_.Push(
278 MakeBytesAndDuration(current_.start_object_size, duration));
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000279 combined_mark_compact_speed_cache_ = 0.0;
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000280 }
281
282 // TODO(ernstm): move the code below out of GCTracer.
283
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000284 double spent_in_mutator = Max(current_.start_time - previous_.end_time, 0.0);
285
286 heap_->UpdateCumulativeGCStatistics(duration, spent_in_mutator,
287 current_.scopes[Scope::MC_MARK]);
288
289 if (current_.type == Event::SCAVENGER && FLAG_trace_gc_ignore_scavenger)
290 return;
291
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000292 if (FLAG_trace_gc_nvp)
293 PrintNVP();
294 else
295 Print();
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000296
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000297 if (FLAG_trace_gc) {
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000298 heap_->PrintShortHeapStatistics();
299 }
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000300
301 longest_incremental_marking_finalization_step_ = 0.0;
302 cumulative_incremental_marking_finalization_steps_ = 0;
303 cumulative_incremental_marking_finalization_duration_ = 0.0;
Ben Murdochda12d292016-06-02 14:46:10 +0100304 // TODO(cbruni): remove once we fully moved to a trace-based system.
305 if (FLAG_runtime_call_stats) {
306 heap_->isolate()->counters()->runtime_call_stats()->Leave(&timer_);
307 }
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000308}
309
310
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000311void GCTracer::SampleAllocation(double current_ms,
312 size_t new_space_counter_bytes,
313 size_t old_generation_counter_bytes) {
314 if (allocation_time_ms_ == 0) {
315 // It is the first sample.
316 allocation_time_ms_ = current_ms;
317 new_space_allocation_counter_bytes_ = new_space_counter_bytes;
318 old_generation_allocation_counter_bytes_ = old_generation_counter_bytes;
319 return;
320 }
321 // This assumes that counters are unsigned integers so that the subtraction
322 // below works even if the new counter is less then the old counter.
323 size_t new_space_allocated_bytes =
324 new_space_counter_bytes - new_space_allocation_counter_bytes_;
325 size_t old_generation_allocated_bytes =
326 old_generation_counter_bytes - old_generation_allocation_counter_bytes_;
327 double duration = current_ms - allocation_time_ms_;
328 allocation_time_ms_ = current_ms;
329 new_space_allocation_counter_bytes_ = new_space_counter_bytes;
330 old_generation_allocation_counter_bytes_ = old_generation_counter_bytes;
331 allocation_duration_since_gc_ += duration;
332 new_space_allocation_in_bytes_since_gc_ += new_space_allocated_bytes;
333 old_generation_allocation_in_bytes_since_gc_ +=
334 old_generation_allocated_bytes;
335}
336
337
338void GCTracer::AddAllocation(double current_ms) {
339 allocation_time_ms_ = current_ms;
Ben Murdochda12d292016-06-02 14:46:10 +0100340 if (allocation_duration_since_gc_ > 0) {
341 recorded_new_generation_allocations_.Push(
342 MakeBytesAndDuration(new_space_allocation_in_bytes_since_gc_,
343 allocation_duration_since_gc_));
344 recorded_old_generation_allocations_.Push(
345 MakeBytesAndDuration(old_generation_allocation_in_bytes_since_gc_,
346 allocation_duration_since_gc_));
347 }
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000348 allocation_duration_since_gc_ = 0;
349 new_space_allocation_in_bytes_since_gc_ = 0;
350 old_generation_allocation_in_bytes_since_gc_ = 0;
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000351}
352
353
Emily Bernierd0a1eb72015-03-24 16:35:39 -0400354void GCTracer::AddContextDisposalTime(double time) {
Ben Murdochda12d292016-06-02 14:46:10 +0100355 recorded_context_disposal_times_.Push(time);
Emily Bernierd0a1eb72015-03-24 16:35:39 -0400356}
357
358
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000359void GCTracer::AddCompactionEvent(double duration,
360 intptr_t live_bytes_compacted) {
Ben Murdochda12d292016-06-02 14:46:10 +0100361 recorded_compactions_.Push(
362 MakeBytesAndDuration(live_bytes_compacted, duration));
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000363}
364
365
366void GCTracer::AddSurvivalRatio(double promotion_ratio) {
Ben Murdochda12d292016-06-02 14:46:10 +0100367 recorded_survival_ratios_.Push(promotion_ratio);
Emily Bernierd0a1eb72015-03-24 16:35:39 -0400368}
369
370
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000371void GCTracer::AddIncrementalMarkingStep(double duration, intptr_t bytes) {
372 cumulative_incremental_marking_steps_++;
373 cumulative_incremental_marking_bytes_ += bytes;
374 cumulative_incremental_marking_duration_ += duration;
375 longest_incremental_marking_step_ =
376 Max(longest_incremental_marking_step_, duration);
377 cumulative_marking_duration_ += duration;
378 if (bytes > 0) {
379 cumulative_pure_incremental_marking_duration_ += duration;
380 }
381}
382
383
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000384void GCTracer::AddIncrementalMarkingFinalizationStep(double duration) {
385 cumulative_incremental_marking_finalization_steps_++;
386 cumulative_incremental_marking_finalization_duration_ += duration;
387 longest_incremental_marking_finalization_step_ =
388 Max(longest_incremental_marking_finalization_step_, duration);
389}
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000390
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000391
392void GCTracer::Output(const char* format, ...) const {
393 if (FLAG_trace_gc) {
394 va_list arguments;
395 va_start(arguments, format);
396 base::OS::VPrint(format, arguments);
397 va_end(arguments);
398 }
399
400 const int kBufferSize = 256;
401 char raw_buffer[kBufferSize];
402 Vector<char> buffer(raw_buffer, kBufferSize);
403 va_list arguments2;
404 va_start(arguments2, format);
405 VSNPrintF(buffer, format, arguments2);
406 va_end(arguments2);
407
408 heap_->AddToRingBuffer(buffer.start());
409}
410
411
412void GCTracer::Print() const {
413 if (FLAG_trace_gc) {
414 PrintIsolate(heap_->isolate(), "");
415 }
416 Output("%8.0f ms: ", heap_->isolate()->time_millis_since_init());
417
418 Output("%s %.1f (%.1f) -> %.1f (%.1f) MB, ", current_.TypeName(false),
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000419 static_cast<double>(current_.start_object_size) / MB,
420 static_cast<double>(current_.start_memory_size) / MB,
421 static_cast<double>(current_.end_object_size) / MB,
422 static_cast<double>(current_.end_memory_size) / MB);
423
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000424 double duration = current_.end_time - current_.start_time;
Ben Murdochda12d292016-06-02 14:46:10 +0100425 Output("%.1f / %.1f ms", duration, TotalExternalTime());
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000426
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000427 if (current_.type == Event::SCAVENGER) {
428 if (current_.incremental_marking_steps > 0) {
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000429 Output(" (+ %.1f ms in %d steps since last GC)",
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000430 current_.incremental_marking_duration,
431 current_.incremental_marking_steps);
432 }
433 } else {
434 if (current_.incremental_marking_steps > 0) {
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000435 Output(
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000436 " (+ %.1f ms in %d steps since start of marking, "
437 "biggest step %.1f ms)",
438 current_.incremental_marking_duration,
439 current_.incremental_marking_steps,
440 current_.longest_incremental_marking_step);
441 }
442 }
443
444 if (current_.gc_reason != NULL) {
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000445 Output(" [%s]", current_.gc_reason);
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000446 }
447
448 if (current_.collector_reason != NULL) {
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000449 Output(" [%s]", current_.collector_reason);
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000450 }
451
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000452 Output(".\n");
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000453}
454
455
456void GCTracer::PrintNVP() const {
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000457 double duration = current_.end_time - current_.start_time;
458 double spent_in_mutator = current_.start_time - previous_.end_time;
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000459 intptr_t allocated_since_last_gc =
460 current_.start_object_size - previous_.end_object_size;
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000461
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000462 switch (current_.type) {
463 case Event::SCAVENGER:
464 PrintIsolate(heap_->isolate(),
465 "%8.0f ms: "
466 "pause=%.1f "
467 "mutator=%.1f "
468 "gc=%s "
469 "reduce_memory=%d "
470 "scavenge=%.2f "
471 "old_new=%.2f "
472 "weak=%.2f "
473 "roots=%.2f "
474 "code=%.2f "
475 "semispace=%.2f "
476 "object_groups=%.2f "
Ben Murdochda12d292016-06-02 14:46:10 +0100477 "external_prologue=%.2f "
478 "external_epilogue=%.2f "
479 "external_weak_global_handles=%.2f "
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000480 "steps_count=%d "
481 "steps_took=%.1f "
Ben Murdochda12d292016-06-02 14:46:10 +0100482 "scavenge_throughput=%.f "
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000483 "total_size_before=%" V8_PTR_PREFIX
484 "d "
485 "total_size_after=%" V8_PTR_PREFIX
486 "d "
487 "holes_size_before=%" V8_PTR_PREFIX
488 "d "
489 "holes_size_after=%" V8_PTR_PREFIX
490 "d "
491 "allocated=%" V8_PTR_PREFIX
492 "d "
493 "promoted=%" V8_PTR_PREFIX
494 "d "
495 "semi_space_copied=%" V8_PTR_PREFIX
496 "d "
497 "nodes_died_in_new=%d "
498 "nodes_copied_in_new=%d "
499 "nodes_promoted=%d "
500 "promotion_ratio=%.1f%% "
501 "average_survival_ratio=%.1f%% "
502 "promotion_rate=%.1f%% "
503 "semi_space_copy_rate=%.1f%% "
Ben Murdochda12d292016-06-02 14:46:10 +0100504 "new_space_allocation_throughput=%.1f "
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000505 "context_disposal_rate=%.1f\n",
506 heap_->isolate()->time_millis_since_init(), duration,
507 spent_in_mutator, current_.TypeName(true),
508 current_.reduce_memory,
509 current_.scopes[Scope::SCAVENGER_SCAVENGE],
510 current_.scopes[Scope::SCAVENGER_OLD_TO_NEW_POINTERS],
511 current_.scopes[Scope::SCAVENGER_WEAK],
512 current_.scopes[Scope::SCAVENGER_ROOTS],
513 current_.scopes[Scope::SCAVENGER_CODE_FLUSH_CANDIDATES],
514 current_.scopes[Scope::SCAVENGER_SEMISPACE],
515 current_.scopes[Scope::SCAVENGER_OBJECT_GROUPS],
Ben Murdochda12d292016-06-02 14:46:10 +0100516 current_.scopes[Scope::SCAVENGER_EXTERNAL_PROLOGUE],
517 current_.scopes[Scope::SCAVENGER_EXTERNAL_EPILOGUE],
518 current_.scopes[Scope::EXTERNAL_WEAK_GLOBAL_HANDLES],
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000519 current_.incremental_marking_steps,
520 current_.incremental_marking_duration,
521 ScavengeSpeedInBytesPerMillisecond(),
522 current_.start_object_size, current_.end_object_size,
523 current_.start_holes_size, current_.end_holes_size,
524 allocated_since_last_gc, heap_->promoted_objects_size(),
525 heap_->semi_space_copied_object_size(),
526 heap_->nodes_died_in_new_space_,
527 heap_->nodes_copied_in_new_space_, heap_->nodes_promoted_,
528 heap_->promotion_ratio_, AverageSurvivalRatio(),
529 heap_->promotion_rate_, heap_->semi_space_copied_rate_,
530 NewSpaceAllocationThroughputInBytesPerMillisecond(),
531 ContextDisposalRateInMilliseconds());
532 break;
533 case Event::MARK_COMPACTOR:
534 case Event::INCREMENTAL_MARK_COMPACTOR:
535 PrintIsolate(
536 heap_->isolate(),
537 "%8.0f ms: "
538 "pause=%.1f "
539 "mutator=%.1f "
540 "gc=%s "
541 "reduce_memory=%d "
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000542 "clear=%1.f "
543 "clear.code_flush=%.1f "
544 "clear.dependent_code=%.1f "
545 "clear.global_handles=%.1f "
546 "clear.maps=%.1f "
547 "clear.slots_buffer=%.1f "
548 "clear.store_buffer=%.1f "
549 "clear.string_table=%.1f "
550 "clear.weak_cells=%.1f "
551 "clear.weak_collections=%.1f "
552 "clear.weak_lists=%.1f "
553 "evacuate=%.1f "
554 "evacuate.candidates=%.1f "
555 "evacuate.clean_up=%.1f "
Ben Murdochda12d292016-06-02 14:46:10 +0100556 "evacuate.copy=%.1f "
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000557 "evacuate.update_pointers=%.1f "
558 "evacuate.update_pointers.between_evacuated=%.1f "
559 "evacuate.update_pointers.to_evacuated=%.1f "
560 "evacuate.update_pointers.to_new=%.1f "
561 "evacuate.update_pointers.weak=%.1f "
Ben Murdochda12d292016-06-02 14:46:10 +0100562 "external.mc_prologue=%.1f "
563 "external.mc_epilogue=%.1f "
564 "external.mc_incremental_prologue=%.1f "
565 "external.mc_incremental_epilogue=%.1f "
566 "external.weak_global_handles=%.1f "
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000567 "finish=%.1f "
568 "mark=%.1f "
569 "mark.finish_incremental=%.1f "
570 "mark.prepare_code_flush=%.1f "
571 "mark.roots=%.1f "
572 "mark.weak_closure=%.1f "
Ben Murdochda12d292016-06-02 14:46:10 +0100573 "mark.weak_closure.ephemeral=%.1f "
574 "mark.weak_closure.weak_handles=%.1f "
575 "mark.weak_closure.weak_roots=%.1f "
576 "mark.weak_closure.harmony=%.1f "
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000577 "sweep=%.1f "
578 "sweep.code=%.1f "
579 "sweep.map=%.1f "
580 "sweep.old=%.1f "
581 "incremental_finalize=%.1f "
582 "steps_count=%d "
583 "steps_took=%.1f "
584 "longest_step=%.1f "
585 "finalization_steps_count=%d "
586 "finalization_steps_took=%.1f "
587 "finalization_longest_step=%.1f "
Ben Murdochda12d292016-06-02 14:46:10 +0100588 "incremental_marking_throughput=%.f "
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000589 "total_size_before=%" V8_PTR_PREFIX
590 "d "
591 "total_size_after=%" V8_PTR_PREFIX
592 "d "
593 "holes_size_before=%" V8_PTR_PREFIX
594 "d "
595 "holes_size_after=%" V8_PTR_PREFIX
596 "d "
597 "allocated=%" V8_PTR_PREFIX
598 "d "
599 "promoted=%" V8_PTR_PREFIX
600 "d "
601 "semi_space_copied=%" V8_PTR_PREFIX
602 "d "
603 "nodes_died_in_new=%d "
604 "nodes_copied_in_new=%d "
605 "nodes_promoted=%d "
606 "promotion_ratio=%.1f%% "
607 "average_survival_ratio=%.1f%% "
608 "promotion_rate=%.1f%% "
609 "semi_space_copy_rate=%.1f%% "
Ben Murdochda12d292016-06-02 14:46:10 +0100610 "new_space_allocation_throughput=%.1f "
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000611 "context_disposal_rate=%.1f "
Ben Murdochda12d292016-06-02 14:46:10 +0100612 "compaction_speed=%.f\n",
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000613 heap_->isolate()->time_millis_since_init(), duration,
614 spent_in_mutator, current_.TypeName(true), current_.reduce_memory,
Ben Murdochda12d292016-06-02 14:46:10 +0100615 current_.scopes[Scope::MC_CLEAR],
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000616 current_.scopes[Scope::MC_CLEAR_CODE_FLUSH],
617 current_.scopes[Scope::MC_CLEAR_DEPENDENT_CODE],
618 current_.scopes[Scope::MC_CLEAR_GLOBAL_HANDLES],
619 current_.scopes[Scope::MC_CLEAR_MAPS],
620 current_.scopes[Scope::MC_CLEAR_SLOTS_BUFFER],
621 current_.scopes[Scope::MC_CLEAR_STORE_BUFFER],
622 current_.scopes[Scope::MC_CLEAR_STRING_TABLE],
623 current_.scopes[Scope::MC_CLEAR_WEAK_CELLS],
624 current_.scopes[Scope::MC_CLEAR_WEAK_COLLECTIONS],
625 current_.scopes[Scope::MC_CLEAR_WEAK_LISTS],
626 current_.scopes[Scope::MC_EVACUATE],
627 current_.scopes[Scope::MC_EVACUATE_CANDIDATES],
628 current_.scopes[Scope::MC_EVACUATE_CLEAN_UP],
Ben Murdochda12d292016-06-02 14:46:10 +0100629 current_.scopes[Scope::MC_EVACUATE_COPY],
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000630 current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS],
631 current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS_BETWEEN_EVACUATED],
632 current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS_TO_EVACUATED],
633 current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS_TO_NEW],
634 current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS_WEAK],
Ben Murdochda12d292016-06-02 14:46:10 +0100635 current_.scopes[Scope::MC_EXTERNAL_PROLOGUE],
636 current_.scopes[Scope::MC_EXTERNAL_EPILOGUE],
637 current_.scopes[Scope::MC_INCREMENTAL_EXTERNAL_PROLOGUE],
638 current_.scopes[Scope::MC_INCREMENTAL_EXTERNAL_EPILOGUE],
639 current_.scopes[Scope::EXTERNAL_WEAK_GLOBAL_HANDLES],
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000640 current_.scopes[Scope::MC_FINISH], current_.scopes[Scope::MC_MARK],
641 current_.scopes[Scope::MC_MARK_FINISH_INCREMENTAL],
642 current_.scopes[Scope::MC_MARK_PREPARE_CODE_FLUSH],
643 current_.scopes[Scope::MC_MARK_ROOTS],
644 current_.scopes[Scope::MC_MARK_WEAK_CLOSURE],
Ben Murdochda12d292016-06-02 14:46:10 +0100645 current_.scopes[Scope::MC_MARK_WEAK_CLOSURE_EPHEMERAL],
646 current_.scopes[Scope::MC_MARK_WEAK_CLOSURE_WEAK_HANDLES],
647 current_.scopes[Scope::MC_MARK_WEAK_CLOSURE_WEAK_ROOTS],
648 current_.scopes[Scope::MC_MARK_WEAK_CLOSURE_HARMONY],
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000649 current_.scopes[Scope::MC_SWEEP],
650 current_.scopes[Scope::MC_SWEEP_CODE],
651 current_.scopes[Scope::MC_SWEEP_MAP],
652 current_.scopes[Scope::MC_SWEEP_OLD],
653 current_.scopes[Scope::MC_INCREMENTAL_FINALIZE],
654 current_.incremental_marking_steps,
655 current_.incremental_marking_duration,
656 current_.longest_incremental_marking_step,
657 cumulative_incremental_marking_finalization_steps_,
658 cumulative_incremental_marking_finalization_duration_,
659 longest_incremental_marking_finalization_step_,
660 IncrementalMarkingSpeedInBytesPerMillisecond(),
661 current_.start_object_size, current_.end_object_size,
662 current_.start_holes_size, current_.end_holes_size,
663 allocated_since_last_gc, heap_->promoted_objects_size(),
664 heap_->semi_space_copied_object_size(),
665 heap_->nodes_died_in_new_space_, heap_->nodes_copied_in_new_space_,
666 heap_->nodes_promoted_, heap_->promotion_ratio_,
667 AverageSurvivalRatio(), heap_->promotion_rate_,
668 heap_->semi_space_copied_rate_,
669 NewSpaceAllocationThroughputInBytesPerMillisecond(),
670 ContextDisposalRateInMilliseconds(),
671 CompactionSpeedInBytesPerMillisecond());
672 break;
673 case Event::START:
674 break;
675 default:
676 UNREACHABLE();
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000677 }
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000678}
679
Ben Murdochda12d292016-06-02 14:46:10 +0100680double GCTracer::AverageSpeed(const RingBuffer<BytesAndDuration>& buffer,
681 const BytesAndDuration& initial, double time_ms) {
682 BytesAndDuration sum = buffer.Sum(
683 [time_ms](BytesAndDuration a, BytesAndDuration b) {
684 if (time_ms != 0 && a.second >= time_ms) return a;
685 return std::make_pair(a.first + b.first, a.second + b.second);
686 },
687 initial);
688 uint64_t bytes = sum.first;
689 double durations = sum.second;
690 if (durations == 0.0) return 0;
691 double speed = bytes / durations;
692 const int max_speed = 1024 * MB;
693 const int min_speed = 1;
694 if (speed >= max_speed) return max_speed;
695 if (speed <= min_speed) return min_speed;
696 return speed;
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000697}
698
Ben Murdochda12d292016-06-02 14:46:10 +0100699double GCTracer::AverageSpeed(const RingBuffer<BytesAndDuration>& buffer) {
700 return AverageSpeed(buffer, MakeBytesAndDuration(0, 0), 0);
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000701}
702
Ben Murdochda12d292016-06-02 14:46:10 +0100703double GCTracer::IncrementalMarkingSpeedInBytesPerMillisecond() const {
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000704 if (cumulative_incremental_marking_duration_ == 0.0) return 0;
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000705 // We haven't completed an entire round of incremental marking, yet.
706 // Use data from GCTracer instead of data from event buffers.
Ben Murdochda12d292016-06-02 14:46:10 +0100707 if (recorded_incremental_marking_steps_.Count() == 0) {
708 return cumulative_incremental_marking_bytes_ /
709 cumulative_pure_incremental_marking_duration_;
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000710 }
Ben Murdochda12d292016-06-02 14:46:10 +0100711 return AverageSpeed(recorded_incremental_marking_steps_);
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000712}
713
Ben Murdochda12d292016-06-02 14:46:10 +0100714double GCTracer::ScavengeSpeedInBytesPerMillisecond(
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000715 ScavengeSpeedMode mode) const {
Ben Murdochda12d292016-06-02 14:46:10 +0100716 if (mode == kForAllObjects) {
717 return AverageSpeed(recorded_scavenges_total_);
718 } else {
719 return AverageSpeed(recorded_scavenges_survived_);
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000720 }
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000721}
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000722
Ben Murdochda12d292016-06-02 14:46:10 +0100723double GCTracer::CompactionSpeedInBytesPerMillisecond() const {
724 return AverageSpeed(recorded_compactions_);
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000725}
726
Ben Murdochda12d292016-06-02 14:46:10 +0100727double GCTracer::MarkCompactSpeedInBytesPerMillisecond() const {
728 return AverageSpeed(recorded_mark_compacts_);
Emily Bernierd0a1eb72015-03-24 16:35:39 -0400729}
730
Ben Murdochda12d292016-06-02 14:46:10 +0100731double GCTracer::FinalIncrementalMarkCompactSpeedInBytesPerMillisecond() const {
732 return AverageSpeed(recorded_incremental_mark_compacts_);
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000733}
734
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000735double GCTracer::CombinedMarkCompactSpeedInBytesPerMillisecond() {
736 if (combined_mark_compact_speed_cache_ > 0)
737 return combined_mark_compact_speed_cache_;
738 const double kMinimumMarkingSpeed = 0.5;
Ben Murdochda12d292016-06-02 14:46:10 +0100739 double speed1 = IncrementalMarkingSpeedInBytesPerMillisecond();
740 double speed2 = FinalIncrementalMarkCompactSpeedInBytesPerMillisecond();
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000741 if (speed1 < kMinimumMarkingSpeed || speed2 < kMinimumMarkingSpeed) {
742 // No data for the incremental marking speed.
743 // Return the non-incremental mark-compact speed.
744 combined_mark_compact_speed_cache_ =
Ben Murdochda12d292016-06-02 14:46:10 +0100745 MarkCompactSpeedInBytesPerMillisecond();
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000746 } else {
747 // Combine the speed of incremental step and the speed of the final step.
748 // 1 / (1 / speed1 + 1 / speed2) = speed1 * speed2 / (speed1 + speed2).
749 combined_mark_compact_speed_cache_ = speed1 * speed2 / (speed1 + speed2);
750 }
751 return combined_mark_compact_speed_cache_;
752}
753
Ben Murdochda12d292016-06-02 14:46:10 +0100754double GCTracer::NewSpaceAllocationThroughputInBytesPerMillisecond(
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000755 double time_ms) const {
756 size_t bytes = new_space_allocation_in_bytes_since_gc_;
757 double durations = allocation_duration_since_gc_;
Ben Murdochda12d292016-06-02 14:46:10 +0100758 return AverageSpeed(recorded_new_generation_allocations_,
759 MakeBytesAndDuration(bytes, durations), time_ms);
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000760}
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000761
Ben Murdochda12d292016-06-02 14:46:10 +0100762double GCTracer::OldGenerationAllocationThroughputInBytesPerMillisecond(
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000763 double time_ms) const {
764 size_t bytes = old_generation_allocation_in_bytes_since_gc_;
765 double durations = allocation_duration_since_gc_;
Ben Murdochda12d292016-06-02 14:46:10 +0100766 return AverageSpeed(recorded_old_generation_allocations_,
767 MakeBytesAndDuration(bytes, durations), time_ms);
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000768}
769
Ben Murdochda12d292016-06-02 14:46:10 +0100770double GCTracer::AllocationThroughputInBytesPerMillisecond(
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000771 double time_ms) const {
772 return NewSpaceAllocationThroughputInBytesPerMillisecond(time_ms) +
773 OldGenerationAllocationThroughputInBytesPerMillisecond(time_ms);
774}
775
Ben Murdochda12d292016-06-02 14:46:10 +0100776double GCTracer::CurrentAllocationThroughputInBytesPerMillisecond() const {
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000777 return AllocationThroughputInBytesPerMillisecond(kThroughputTimeFrameMs);
778}
779
Ben Murdochda12d292016-06-02 14:46:10 +0100780double GCTracer::CurrentOldGenerationAllocationThroughputInBytesPerMillisecond()
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000781 const {
782 return OldGenerationAllocationThroughputInBytesPerMillisecond(
783 kThroughputTimeFrameMs);
Ben Murdochb8a8cc12014-11-26 15:28:44 +0000784}
Emily Bernierd0a1eb72015-03-24 16:35:39 -0400785
Emily Bernierd0a1eb72015-03-24 16:35:39 -0400786double GCTracer::ContextDisposalRateInMilliseconds() const {
Ben Murdochda12d292016-06-02 14:46:10 +0100787 if (recorded_context_disposal_times_.Count() <
788 recorded_context_disposal_times_.kSize)
789 return 0.0;
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000790 double begin = heap_->MonotonicallyIncreasingTimeInMs();
Ben Murdochda12d292016-06-02 14:46:10 +0100791 double end = recorded_context_disposal_times_.Sum(
792 [](double a, double b) { return b; }, 0.0);
793 return (begin - end) / recorded_context_disposal_times_.Count();
Emily Bernierd0a1eb72015-03-24 16:35:39 -0400794}
795
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000796double GCTracer::AverageSurvivalRatio() const {
Ben Murdochda12d292016-06-02 14:46:10 +0100797 if (recorded_survival_ratios_.Count() == 0) return 0.0;
798 double sum = recorded_survival_ratios_.Sum(
799 [](double a, double b) { return a + b; }, 0.0);
800 return sum / recorded_survival_ratios_.Count();
Emily Bernierd0a1eb72015-03-24 16:35:39 -0400801}
802
Emily Bernierd0a1eb72015-03-24 16:35:39 -0400803bool GCTracer::SurvivalEventsRecorded() const {
Ben Murdochda12d292016-06-02 14:46:10 +0100804 return recorded_survival_ratios_.Count() > 0;
Emily Bernierd0a1eb72015-03-24 16:35:39 -0400805}
806
Ben Murdochda12d292016-06-02 14:46:10 +0100807void GCTracer::ResetSurvivalEvents() { recorded_survival_ratios_.Reset(); }
Ben Murdoch4a90d5f2016-03-22 12:00:34 +0000808} // namespace internal
809} // namespace v8