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 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 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 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 57 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 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 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 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 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 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 223 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 266 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 340 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 354 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 368 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 393 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 407 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 432 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 448 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 465 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
