Ben Murdoch | b8a8cc1 | 2014-11-26 15:28:44 +0000 | [diff] [blame^] | 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 |