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/v8.h"
6
7 #include "src/heap/gc-tracer.h"
8
9 namespace v8 {
10 namespace internal {
11
CountTotalHolesSize(Heap * heap)12 static intptr_t CountTotalHolesSize(Heap* heap) {
13 intptr_t holes_size = 0;
14 OldSpaces spaces(heap);
15 for (OldSpace* space = spaces.next(); space != NULL; space = spaces.next()) {
16 holes_size += space->Waste() + space->Available();
17 }
18 return holes_size;
19 }
20
21
AllocationEvent(double duration,intptr_t allocation_in_bytes)22 GCTracer::AllocationEvent::AllocationEvent(double duration,
23 intptr_t allocation_in_bytes) {
24 duration_ = duration;
25 allocation_in_bytes_ = allocation_in_bytes;
26 }
27
28
Event(Type type,const char * gc_reason,const char * collector_reason)29 GCTracer::Event::Event(Type type, const char* gc_reason,
30 const char* collector_reason)
31 : type(type),
32 gc_reason(gc_reason),
33 collector_reason(collector_reason),
34 start_time(0.0),
35 end_time(0.0),
36 start_object_size(0),
37 end_object_size(0),
38 start_memory_size(0),
39 end_memory_size(0),
40 start_holes_size(0),
41 end_holes_size(0),
42 cumulative_incremental_marking_steps(0),
43 incremental_marking_steps(0),
44 cumulative_incremental_marking_bytes(0),
45 incremental_marking_bytes(0),
46 cumulative_incremental_marking_duration(0.0),
47 incremental_marking_duration(0.0),
48 cumulative_pure_incremental_marking_duration(0.0),
49 pure_incremental_marking_duration(0.0),
50 longest_incremental_marking_step(0.0) {
51 for (int i = 0; i < Scope::NUMBER_OF_SCOPES; i++) {
52 scopes[i] = 0;
53 }
54 }
55
56
TypeName(bool short_name) const57 const char* GCTracer::Event::TypeName(bool short_name) const {
58 switch (type) {
59 case SCAVENGER:
60 if (short_name) {
61 return "s";
62 } else {
63 return "Scavenge";
64 }
65 case MARK_COMPACTOR:
66 if (short_name) {
67 return "ms";
68 } else {
69 return "Mark-sweep";
70 }
71 case START:
72 if (short_name) {
73 return "st";
74 } else {
75 return "Start";
76 }
77 }
78 return "Unknown Event Type";
79 }
80
81
GCTracer(Heap * heap)82 GCTracer::GCTracer(Heap* heap)
83 : heap_(heap),
84 cumulative_incremental_marking_steps_(0),
85 cumulative_incremental_marking_bytes_(0),
86 cumulative_incremental_marking_duration_(0.0),
87 cumulative_pure_incremental_marking_duration_(0.0),
88 longest_incremental_marking_step_(0.0),
89 cumulative_marking_duration_(0.0),
90 cumulative_sweeping_duration_(0.0),
91 new_space_top_after_gc_(0) {
92 current_ = Event(Event::START, NULL, NULL);
93 current_.end_time = base::OS::TimeCurrentMillis();
94 previous_ = previous_mark_compactor_event_ = current_;
95 }
96
97
Start(GarbageCollector collector,const char * gc_reason,const char * collector_reason)98 void GCTracer::Start(GarbageCollector collector, const char* gc_reason,
99 const char* collector_reason) {
100 previous_ = current_;
101 double start_time = base::OS::TimeCurrentMillis();
102 if (new_space_top_after_gc_ != 0) {
103 AddNewSpaceAllocationTime(
104 start_time - previous_.end_time,
105 reinterpret_cast<intptr_t>((heap_->new_space()->top()) -
106 new_space_top_after_gc_));
107 }
108 if (current_.type == Event::MARK_COMPACTOR)
109 previous_mark_compactor_event_ = current_;
110
111 if (collector == SCAVENGER) {
112 current_ = Event(Event::SCAVENGER, gc_reason, collector_reason);
113 } else {
114 current_ = Event(Event::MARK_COMPACTOR, gc_reason, collector_reason);
115 }
116
117 current_.start_time = start_time;
118 current_.start_object_size = heap_->SizeOfObjects();
119 current_.start_memory_size = heap_->isolate()->memory_allocator()->Size();
120 current_.start_holes_size = CountTotalHolesSize(heap_);
121 current_.new_space_object_size =
122 heap_->new_space()->top() - heap_->new_space()->bottom();
123
124 current_.cumulative_incremental_marking_steps =
125 cumulative_incremental_marking_steps_;
126 current_.cumulative_incremental_marking_bytes =
127 cumulative_incremental_marking_bytes_;
128 current_.cumulative_incremental_marking_duration =
129 cumulative_incremental_marking_duration_;
130 current_.cumulative_pure_incremental_marking_duration =
131 cumulative_pure_incremental_marking_duration_;
132 current_.longest_incremental_marking_step = longest_incremental_marking_step_;
133
134 for (int i = 0; i < Scope::NUMBER_OF_SCOPES; i++) {
135 current_.scopes[i] = 0;
136 }
137 }
138
139
Stop()140 void GCTracer::Stop() {
141 current_.end_time = base::OS::TimeCurrentMillis();
142 current_.end_object_size = heap_->SizeOfObjects();
143 current_.end_memory_size = heap_->isolate()->memory_allocator()->Size();
144 current_.end_holes_size = CountTotalHolesSize(heap_);
145 new_space_top_after_gc_ =
146 reinterpret_cast<intptr_t>(heap_->new_space()->top());
147
148 if (current_.type == Event::SCAVENGER) {
149 current_.incremental_marking_steps =
150 current_.cumulative_incremental_marking_steps -
151 previous_.cumulative_incremental_marking_steps;
152 current_.incremental_marking_bytes =
153 current_.cumulative_incremental_marking_bytes -
154 previous_.cumulative_incremental_marking_bytes;
155 current_.incremental_marking_duration =
156 current_.cumulative_incremental_marking_duration -
157 previous_.cumulative_incremental_marking_duration;
158 current_.pure_incremental_marking_duration =
159 current_.cumulative_pure_incremental_marking_duration -
160 previous_.cumulative_pure_incremental_marking_duration;
161 scavenger_events_.push_front(current_);
162 } else {
163 current_.incremental_marking_steps =
164 current_.cumulative_incremental_marking_steps -
165 previous_mark_compactor_event_.cumulative_incremental_marking_steps;
166 current_.incremental_marking_bytes =
167 current_.cumulative_incremental_marking_bytes -
168 previous_mark_compactor_event_.cumulative_incremental_marking_bytes;
169 current_.incremental_marking_duration =
170 current_.cumulative_incremental_marking_duration -
171 previous_mark_compactor_event_.cumulative_incremental_marking_duration;
172 current_.pure_incremental_marking_duration =
173 current_.cumulative_pure_incremental_marking_duration -
174 previous_mark_compactor_event_
175 .cumulative_pure_incremental_marking_duration;
176 longest_incremental_marking_step_ = 0.0;
177 mark_compactor_events_.push_front(current_);
178 }
179
180 // TODO(ernstm): move the code below out of GCTracer.
181
182 if (!FLAG_trace_gc && !FLAG_print_cumulative_gc_stat) return;
183
184 double duration = current_.end_time - current_.start_time;
185 double spent_in_mutator = Max(current_.start_time - previous_.end_time, 0.0);
186
187 heap_->UpdateCumulativeGCStatistics(duration, spent_in_mutator,
188 current_.scopes[Scope::MC_MARK]);
189
190 if (current_.type == Event::SCAVENGER && FLAG_trace_gc_ignore_scavenger)
191 return;
192
193 if (FLAG_trace_gc) {
194 if (FLAG_trace_gc_nvp)
195 PrintNVP();
196 else
197 Print();
198
199 heap_->PrintShortHeapStatistics();
200 }
201 }
202
203
AddNewSpaceAllocationTime(double duration,intptr_t allocation_in_bytes)204 void GCTracer::AddNewSpaceAllocationTime(double duration,
205 intptr_t allocation_in_bytes) {
206 allocation_events_.push_front(AllocationEvent(duration, allocation_in_bytes));
207 }
208
209
AddIncrementalMarkingStep(double duration,intptr_t bytes)210 void GCTracer::AddIncrementalMarkingStep(double duration, intptr_t bytes) {
211 cumulative_incremental_marking_steps_++;
212 cumulative_incremental_marking_bytes_ += bytes;
213 cumulative_incremental_marking_duration_ += duration;
214 longest_incremental_marking_step_ =
215 Max(longest_incremental_marking_step_, duration);
216 cumulative_marking_duration_ += duration;
217 if (bytes > 0) {
218 cumulative_pure_incremental_marking_duration_ += duration;
219 }
220 }
221
222
Print() const223 void GCTracer::Print() const {
224 PrintPID("%8.0f ms: ", heap_->isolate()->time_millis_since_init());
225
226 PrintF("%s %.1f (%.1f) -> %.1f (%.1f) MB, ", current_.TypeName(false),
227 static_cast<double>(current_.start_object_size) / MB,
228 static_cast<double>(current_.start_memory_size) / MB,
229 static_cast<double>(current_.end_object_size) / MB,
230 static_cast<double>(current_.end_memory_size) / MB);
231
232 int external_time = static_cast<int>(current_.scopes[Scope::EXTERNAL]);
233 if (external_time > 0) PrintF("%d / ", external_time);
234
235 double duration = current_.end_time - current_.start_time;
236 PrintF("%.1f ms", duration);
237 if (current_.type == Event::SCAVENGER) {
238 if (current_.incremental_marking_steps > 0) {
239 PrintF(" (+ %.1f ms in %d steps since last GC)",
240 current_.incremental_marking_duration,
241 current_.incremental_marking_steps);
242 }
243 } else {
244 if (current_.incremental_marking_steps > 0) {
245 PrintF(
246 " (+ %.1f ms in %d steps since start of marking, "
247 "biggest step %.1f ms)",
248 current_.incremental_marking_duration,
249 current_.incremental_marking_steps,
250 current_.longest_incremental_marking_step);
251 }
252 }
253
254 if (current_.gc_reason != NULL) {
255 PrintF(" [%s]", current_.gc_reason);
256 }
257
258 if (current_.collector_reason != NULL) {
259 PrintF(" [%s]", current_.collector_reason);
260 }
261
262 PrintF(".\n");
263 }
264
265
PrintNVP() const266 void GCTracer::PrintNVP() const {
267 PrintPID("%8.0f ms: ", heap_->isolate()->time_millis_since_init());
268
269 double duration = current_.end_time - current_.start_time;
270 double spent_in_mutator = current_.start_time - previous_.end_time;
271
272 PrintF("pause=%.1f ", duration);
273 PrintF("mutator=%.1f ", spent_in_mutator);
274 PrintF("gc=%s ", current_.TypeName(true));
275
276 PrintF("external=%.1f ", current_.scopes[Scope::EXTERNAL]);
277 PrintF("mark=%.1f ", current_.scopes[Scope::MC_MARK]);
278 PrintF("sweep=%.2f ", current_.scopes[Scope::MC_SWEEP]);
279 PrintF("sweepns=%.2f ", current_.scopes[Scope::MC_SWEEP_NEWSPACE]);
280 PrintF("sweepos=%.2f ", current_.scopes[Scope::MC_SWEEP_OLDSPACE]);
281 PrintF("sweepcode=%.2f ", current_.scopes[Scope::MC_SWEEP_CODE]);
282 PrintF("sweepcell=%.2f ", current_.scopes[Scope::MC_SWEEP_CELL]);
283 PrintF("sweepmap=%.2f ", current_.scopes[Scope::MC_SWEEP_MAP]);
284 PrintF("evacuate=%.1f ", current_.scopes[Scope::MC_EVACUATE_PAGES]);
285 PrintF("new_new=%.1f ",
286 current_.scopes[Scope::MC_UPDATE_NEW_TO_NEW_POINTERS]);
287 PrintF("root_new=%.1f ",
288 current_.scopes[Scope::MC_UPDATE_ROOT_TO_NEW_POINTERS]);
289 PrintF("old_new=%.1f ",
290 current_.scopes[Scope::MC_UPDATE_OLD_TO_NEW_POINTERS]);
291 PrintF("compaction_ptrs=%.1f ",
292 current_.scopes[Scope::MC_UPDATE_POINTERS_TO_EVACUATED]);
293 PrintF("intracompaction_ptrs=%.1f ",
294 current_.scopes[Scope::MC_UPDATE_POINTERS_BETWEEN_EVACUATED]);
295 PrintF("misc_compaction=%.1f ",
296 current_.scopes[Scope::MC_UPDATE_MISC_POINTERS]);
297 PrintF("weakcollection_process=%.1f ",
298 current_.scopes[Scope::MC_WEAKCOLLECTION_PROCESS]);
299 PrintF("weakcollection_clear=%.1f ",
300 current_.scopes[Scope::MC_WEAKCOLLECTION_CLEAR]);
301 PrintF("weakcollection_abort=%.1f ",
302 current_.scopes[Scope::MC_WEAKCOLLECTION_ABORT]);
303
304 PrintF("total_size_before=%" V8_PTR_PREFIX "d ", current_.start_object_size);
305 PrintF("total_size_after=%" V8_PTR_PREFIX "d ", current_.end_object_size);
306 PrintF("holes_size_before=%" V8_PTR_PREFIX "d ", current_.start_holes_size);
307 PrintF("holes_size_after=%" V8_PTR_PREFIX "d ", current_.end_holes_size);
308
309 intptr_t allocated_since_last_gc =
310 current_.start_object_size - previous_.end_object_size;
311 PrintF("allocated=%" V8_PTR_PREFIX "d ", allocated_since_last_gc);
312 PrintF("promoted=%" V8_PTR_PREFIX "d ", heap_->promoted_objects_size_);
313 PrintF("semi_space_copied=%" V8_PTR_PREFIX "d ",
314 heap_->semi_space_copied_object_size_);
315 PrintF("nodes_died_in_new=%d ", heap_->nodes_died_in_new_space_);
316 PrintF("nodes_copied_in_new=%d ", heap_->nodes_copied_in_new_space_);
317 PrintF("nodes_promoted=%d ", heap_->nodes_promoted_);
318 PrintF("promotion_rate=%.1f%% ", heap_->promotion_rate_);
319 PrintF("semi_space_copy_rate=%.1f%% ", heap_->semi_space_copied_rate_);
320 PrintF("new_space_allocation_throughput=%" V8_PTR_PREFIX "d ",
321 NewSpaceAllocationThroughputInBytesPerMillisecond());
322
323 if (current_.type == Event::SCAVENGER) {
324 PrintF("steps_count=%d ", current_.incremental_marking_steps);
325 PrintF("steps_took=%.1f ", current_.incremental_marking_duration);
326 PrintF("scavenge_throughput=%" V8_PTR_PREFIX "d ",
327 ScavengeSpeedInBytesPerMillisecond());
328 } else {
329 PrintF("steps_count=%d ", current_.incremental_marking_steps);
330 PrintF("steps_took=%.1f ", current_.incremental_marking_duration);
331 PrintF("longest_step=%.1f ", current_.longest_incremental_marking_step);
332 PrintF("incremental_marking_throughput=%" V8_PTR_PREFIX "d ",
333 IncrementalMarkingSpeedInBytesPerMillisecond());
334 }
335
336 PrintF("\n");
337 }
338
339
MeanDuration(const EventBuffer & events) const340 double GCTracer::MeanDuration(const EventBuffer& events) const {
341 if (events.empty()) return 0.0;
342
343 double mean = 0.0;
344 EventBuffer::const_iterator iter = events.begin();
345 while (iter != events.end()) {
346 mean += iter->end_time - iter->start_time;
347 ++iter;
348 }
349
350 return mean / events.size();
351 }
352
353
MaxDuration(const EventBuffer & events) const354 double GCTracer::MaxDuration(const EventBuffer& events) const {
355 if (events.empty()) return 0.0;
356
357 double maximum = 0.0f;
358 EventBuffer::const_iterator iter = events.begin();
359 while (iter != events.end()) {
360 maximum = Max(iter->end_time - iter->start_time, maximum);
361 ++iter;
362 }
363
364 return maximum;
365 }
366
367
MeanIncrementalMarkingDuration() const368 double GCTracer::MeanIncrementalMarkingDuration() const {
369 if (cumulative_incremental_marking_steps_ == 0) return 0.0;
370
371 // We haven't completed an entire round of incremental marking, yet.
372 // Use data from GCTracer instead of data from event buffers.
373 if (mark_compactor_events_.empty()) {
374 return cumulative_incremental_marking_duration_ /
375 cumulative_incremental_marking_steps_;
376 }
377
378 int steps = 0;
379 double durations = 0.0;
380 EventBuffer::const_iterator iter = mark_compactor_events_.begin();
381 while (iter != mark_compactor_events_.end()) {
382 steps += iter->incremental_marking_steps;
383 durations += iter->incremental_marking_duration;
384 ++iter;
385 }
386
387 if (steps == 0) return 0.0;
388
389 return durations / steps;
390 }
391
392
MaxIncrementalMarkingDuration() const393 double GCTracer::MaxIncrementalMarkingDuration() const {
394 // We haven't completed an entire round of incremental marking, yet.
395 // Use data from GCTracer instead of data from event buffers.
396 if (mark_compactor_events_.empty()) return longest_incremental_marking_step_;
397
398 double max_duration = 0.0;
399 EventBuffer::const_iterator iter = mark_compactor_events_.begin();
400 while (iter != mark_compactor_events_.end())
401 max_duration = Max(iter->longest_incremental_marking_step, max_duration);
402
403 return max_duration;
404 }
405
406
IncrementalMarkingSpeedInBytesPerMillisecond() const407 intptr_t GCTracer::IncrementalMarkingSpeedInBytesPerMillisecond() const {
408 if (cumulative_incremental_marking_duration_ == 0.0) return 0;
409
410 // We haven't completed an entire round of incremental marking, yet.
411 // Use data from GCTracer instead of data from event buffers.
412 if (mark_compactor_events_.empty()) {
413 return static_cast<intptr_t>(cumulative_incremental_marking_bytes_ /
414 cumulative_pure_incremental_marking_duration_);
415 }
416
417 intptr_t bytes = 0;
418 double durations = 0.0;
419 EventBuffer::const_iterator iter = mark_compactor_events_.begin();
420 while (iter != mark_compactor_events_.end()) {
421 bytes += iter->incremental_marking_bytes;
422 durations += iter->pure_incremental_marking_duration;
423 ++iter;
424 }
425
426 if (durations == 0.0) return 0;
427
428 return static_cast<intptr_t>(bytes / durations);
429 }
430
431
ScavengeSpeedInBytesPerMillisecond() const432 intptr_t GCTracer::ScavengeSpeedInBytesPerMillisecond() const {
433 intptr_t bytes = 0;
434 double durations = 0.0;
435 EventBuffer::const_iterator iter = scavenger_events_.begin();
436 while (iter != scavenger_events_.end()) {
437 bytes += iter->new_space_object_size;
438 durations += iter->end_time - iter->start_time;
439 ++iter;
440 }
441
442 if (durations == 0.0) return 0;
443
444 return static_cast<intptr_t>(bytes / durations);
445 }
446
447
MarkCompactSpeedInBytesPerMillisecond() const448 intptr_t GCTracer::MarkCompactSpeedInBytesPerMillisecond() const {
449 intptr_t bytes = 0;
450 double durations = 0.0;
451 EventBuffer::const_iterator iter = mark_compactor_events_.begin();
452 while (iter != mark_compactor_events_.end()) {
453 bytes += iter->start_object_size;
454 durations += iter->end_time - iter->start_time +
455 iter->pure_incremental_marking_duration;
456 ++iter;
457 }
458
459 if (durations == 0.0) return 0;
460
461 return static_cast<intptr_t>(bytes / durations);
462 }
463
464
NewSpaceAllocationThroughputInBytesPerMillisecond() const465 intptr_t GCTracer::NewSpaceAllocationThroughputInBytesPerMillisecond() const {
466 intptr_t bytes = 0;
467 double durations = 0.0;
468 AllocationEventBuffer::const_iterator iter = allocation_events_.begin();
469 while (iter != allocation_events_.end()) {
470 bytes += iter->allocation_in_bytes_;
471 durations += iter->duration_;
472 ++iter;
473 }
474
475 if (durations == 0.0) return 0;
476
477 return static_cast<intptr_t>(bytes / durations);
478 }
479 }
480 } // namespace v8::internal
481