1 /* 2 * Copyright (c) 2015, 2017, Oracle and/or its affiliates. All rights reserved. 3 * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. 4 * 5 * This code is free software; you can redistribute it and/or modify it 6 * under the terms of the GNU General Public License version 2 only, as 7 * published by the Free Software Foundation. 8 * 9 * This code is distributed in the hope that it will be useful, but WITHOUT 10 * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or 11 * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License 12 * version 2 for more details (a copy is included in the LICENSE file that 13 * accompanied this code). 14 * 15 * You should have received a copy of the GNU General Public License version 16 * 2 along with this work; if not, write to the Free Software Foundation, 17 * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA. 18 * 19 * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA 20 * or visit www.oracle.com if you need additional information or have any 21 * questions. 22 */ 23 24 #include "precompiled.hpp" 25 #include "gc/z/zCollectedHeap.hpp" 26 #include "gc/z/zCPU.hpp" 27 #include "gc/z/zHeap.inline.hpp" 28 #include "gc/z/zLargePages.inline.hpp" 29 #include "gc/z/zNMethodTable.hpp" 30 #include "gc/z/zNUMA.hpp" 31 #include "gc/z/zStat.hpp" 32 #include "gc/z/zTracer.inline.hpp" 33 #include "gc/z/zUtils.hpp" 34 #include "runtime/atomic.hpp" 35 #include "runtime/os.hpp" 36 #include "runtime/timer.hpp" 37 #include "utilities/align.hpp" 38 #include "utilities/compilerWarnings.hpp" 39 #include "utilities/debug.hpp" 40 #include "utilities/ticks.inline.hpp" 41 42 // 43 // Stat sampler/counter data 44 // 45 struct ZStatSamplerData { 46 uint64_t _nsamples; 47 uint64_t _sum; 48 uint64_t _max; 49 50 ZStatSamplerData() : 51 _nsamples(0), 52 _sum(0), 53 _max(0) {} 54 55 void add(const ZStatSamplerData& new_sample) { 56 _nsamples += new_sample._nsamples; 57 _sum += new_sample._nsamples; 58 _max = MAX2(_max, new_sample._max); 59 } 60 }; 61 62 struct ZStatCounterData { 63 uint64_t _counter; 64 65 ZStatCounterData() : 66 _counter(0) {} 67 }; 68 69 // 70 // Stat sampler history 71 // 72 template <size_t size> 73 class ZStatSamplerHistoryInterval VALUE_OBJ_CLASS_SPEC { 74 private: 75 size_t _next; 76 ZStatSamplerData _samples[size]; 77 ZStatSamplerData _accumulated; 78 ZStatSamplerData _total; 79 80 public: 81 ZStatSamplerHistoryInterval() : 82 _next(0), 83 _samples(), 84 _total(), 85 _accumulated() {} 86 87 bool add(const ZStatSamplerData& new_sample) { 88 // Insert sample 89 const ZStatSamplerData old_sample = _samples[_next]; 90 _samples[_next] = new_sample; 91 92 // Adjust accumulated 93 _accumulated._nsamples += new_sample._nsamples; 94 _accumulated._sum += new_sample._sum; 95 _accumulated._max = MAX2(_accumulated._max, new_sample._max); 96 97 // Adjust total 98 _total._nsamples -= old_sample._nsamples; 99 _total._sum -= old_sample._sum; 100 _total._nsamples += new_sample._nsamples; 101 _total._sum += new_sample._sum; 102 if (_total._max < new_sample._max) { 103 // Found new max 104 _total._max = new_sample._max; 105 } else if (_total._max == old_sample._max) { 106 // Removed old max, reset and find new max 107 _total._max = 0; 108 for (size_t i = 0; i < size; i++) { 109 if (_total._max < _samples[i]._max) { 110 _total._max = _samples[i]._max; 111 } 112 } 113 } 114 115 // Adjust next 116 if (++_next == size) { 117 _next = 0; 118 119 // Clear accumulated 120 const ZStatSamplerData zero; 121 _accumulated = zero; 122 123 // Became full 124 return true; 125 } 126 127 // Not yet full 128 return false; 129 } 130 131 const ZStatSamplerData& total() const { 132 return _total; 133 } 134 135 const ZStatSamplerData& accumulated() const { 136 return _accumulated; 137 } 138 }; 139 140 class ZStatSamplerHistory : public CHeapObj<mtGC> { 141 private: 142 ZStatSamplerHistoryInterval<10> _10seconds; 143 ZStatSamplerHistoryInterval<60> _10minutes; 144 ZStatSamplerHistoryInterval<60> _10hours; 145 ZStatSamplerData _total; 146 147 uint64_t avg(uint64_t sum, uint64_t nsamples) const { 148 return (nsamples > 0) ? sum / nsamples : 0; 149 } 150 151 public: 152 ZStatSamplerHistory() : 153 _10seconds(), 154 _10minutes(), 155 _10hours(), 156 _total() {} 157 158 void add(const ZStatSamplerData& new_sample) { 159 if (_10seconds.add(new_sample)) { 160 if (_10minutes.add(_10seconds.total())) { 161 if (_10hours.add(_10minutes.total())) { 162 _total.add(_10hours.total()); 163 } 164 } 165 } 166 } 167 168 uint64_t avg_10_seconds() const { 169 const uint64_t sum = _10seconds.total()._sum; 170 const uint64_t nsamples = _10seconds.total()._nsamples; 171 return avg(sum, nsamples); 172 } 173 174 uint64_t avg_10_minutes() const { 175 const uint64_t sum = _10seconds.accumulated()._sum + 176 _10minutes.total()._sum; 177 const uint64_t nsamples = _10seconds.accumulated()._nsamples + 178 _10minutes.total()._nsamples; 179 return avg(sum, nsamples); 180 } 181 182 uint64_t avg_10_hours() const { 183 const uint64_t sum = _10seconds.accumulated()._sum + 184 _10minutes.accumulated()._sum + 185 _10hours.total()._sum; 186 const uint64_t nsamples = _10seconds.accumulated()._nsamples + 187 _10minutes.accumulated()._nsamples + 188 _10hours.total()._nsamples; 189 return avg(sum, nsamples); 190 } 191 192 uint64_t avg_total() const { 193 const uint64_t sum = _10seconds.accumulated()._sum + 194 _10minutes.accumulated()._sum + 195 _10hours.accumulated()._sum + 196 _total._sum; 197 const uint64_t nsamples = _10seconds.accumulated()._nsamples + 198 _10minutes.accumulated()._nsamples + 199 _10hours.accumulated()._nsamples + 200 _total._nsamples; 201 return avg(sum, nsamples); 202 } 203 204 uint64_t max_10_seconds() const { 205 return _10seconds.total()._max; 206 } 207 208 uint64_t max_10_minutes() const { 209 return MAX2(_10seconds.accumulated()._max, 210 _10minutes.total()._max); 211 } 212 213 uint64_t max_10_hours() const { 214 return MAX3(_10seconds.accumulated()._max, 215 _10minutes.accumulated()._max, 216 _10hours.total()._max); 217 } 218 219 uint64_t max_total() const { 220 return MAX4(_10seconds.accumulated()._max, 221 _10minutes.accumulated()._max, 222 _10hours.accumulated()._max, 223 _total._max); 224 } 225 }; 226 227 // 228 // Stat unit printers 229 // 230 void ZStatUnitTime(LogTargetHandle log, const ZStatSampler& sampler, const ZStatSamplerHistory& history) { 231 log.print(" %10s: %-40s " 232 "%9.3f / %-9.3f " 233 "%9.3f / %-9.3f " 234 "%9.3f / %-9.3f " 235 "%9.3f / %-9.3f ms", 236 sampler.group(), 237 sampler.name(), 238 TimeHelper::counter_to_millis(history.avg_10_seconds()), 239 TimeHelper::counter_to_millis(history.max_10_seconds()), 240 TimeHelper::counter_to_millis(history.avg_10_minutes()), 241 TimeHelper::counter_to_millis(history.max_10_minutes()), 242 TimeHelper::counter_to_millis(history.avg_10_hours()), 243 TimeHelper::counter_to_millis(history.max_10_hours()), 244 TimeHelper::counter_to_millis(history.avg_total()), 245 TimeHelper::counter_to_millis(history.max_total())); 246 } 247 248 void ZStatUnitBytes(LogTargetHandle log, const ZStatSampler& sampler, const ZStatSamplerHistory& history) { 249 log.print(" %10s: %-40s " 250 UINT64_FORMAT_W(9) " / " UINT64_FORMAT_W(-9) " " 251 UINT64_FORMAT_W(9) " / " UINT64_FORMAT_W(-9) " " 252 UINT64_FORMAT_W(9) " / " UINT64_FORMAT_W(-9) " " 253 UINT64_FORMAT_W(9) " / " UINT64_FORMAT_W(-9) " MB", 254 sampler.group(), 255 sampler.name(), 256 history.avg_10_seconds() / M, 257 history.max_10_seconds() / M, 258 history.avg_10_minutes() / M, 259 history.max_10_minutes() / M, 260 history.avg_10_hours() / M, 261 history.max_10_hours() / M, 262 history.avg_total() / M, 263 history.max_total() / M); 264 } 265 266 void ZStatUnitThreads(LogTargetHandle log, const ZStatSampler& sampler, const ZStatSamplerHistory& history) { 267 log.print(" %10s: %-40s " 268 UINT64_FORMAT_W(9) " / " UINT64_FORMAT_W(-9) " " 269 UINT64_FORMAT_W(9) " / " UINT64_FORMAT_W(-9) " " 270 UINT64_FORMAT_W(9) " / " UINT64_FORMAT_W(-9) " " 271 UINT64_FORMAT_W(9) " / " UINT64_FORMAT_W(-9) " threads", 272 sampler.group(), 273 sampler.name(), 274 history.avg_10_seconds(), 275 history.max_10_seconds(), 276 history.avg_10_minutes(), 277 history.max_10_minutes(), 278 history.avg_10_hours(), 279 history.max_10_hours(), 280 history.avg_total(), 281 history.max_total()); 282 } 283 284 void ZStatUnitBytesPerSecond(LogTargetHandle log, const ZStatSampler& sampler, const ZStatSamplerHistory& history) { 285 log.print(" %10s: %-40s " 286 UINT64_FORMAT_W(9) " / " UINT64_FORMAT_W(-9) " " 287 UINT64_FORMAT_W(9) " / " UINT64_FORMAT_W(-9) " " 288 UINT64_FORMAT_W(9) " / " UINT64_FORMAT_W(-9) " " 289 UINT64_FORMAT_W(9) " / " UINT64_FORMAT_W(-9) " MB/s", 290 sampler.group(), 291 sampler.name(), 292 history.avg_10_seconds() / M, 293 history.max_10_seconds() / M, 294 history.avg_10_minutes() / M, 295 history.max_10_minutes() / M, 296 history.avg_10_hours() / M, 297 history.max_10_hours() / M, 298 history.avg_total() / M, 299 history.max_total() / M); 300 } 301 302 void ZStatUnitOpsPerSecond(LogTargetHandle log, const ZStatSampler& sampler, const ZStatSamplerHistory& history) { 303 log.print(" %10s: %-40s " 304 UINT64_FORMAT_W(9) " / " UINT64_FORMAT_W(-9) " " 305 UINT64_FORMAT_W(9) " / " UINT64_FORMAT_W(-9) " " 306 UINT64_FORMAT_W(9) " / " UINT64_FORMAT_W(-9) " " 307 UINT64_FORMAT_W(9) " / " UINT64_FORMAT_W(-9) " ops/s", 308 sampler.group(), 309 sampler.name(), 310 history.avg_10_seconds(), 311 history.max_10_seconds(), 312 history.avg_10_minutes(), 313 history.max_10_minutes(), 314 history.avg_10_hours(), 315 history.max_10_hours(), 316 history.avg_total(), 317 history.max_total()); 318 } 319 320 // 321 // Stat value 322 // 323 uintptr_t ZStatValue::_base = 0; 324 uint32_t ZStatValue::_cpu_offset = 0; 325 326 ZStatValue::ZStatValue(const char* group, 327 const char* name, 328 uint32_t id, 329 uint32_t size) : 330 _group(group), 331 _name(name), 332 _id(id), 333 _offset(_cpu_offset) { 334 assert(_base == 0, "Already initialized"); 335 _cpu_offset += size; 336 } 337 338 template <typename T> 339 T* ZStatValue::get_cpu_local(uint32_t cpu) const { 340 assert(_base != 0, "Not initialized"); 341 const uintptr_t cpu_base = _base + (_cpu_offset * cpu); 342 const uintptr_t value_addr = cpu_base + _offset; 343 return (T*)value_addr; 344 } 345 346 void ZStatValue::initialize() { 347 // Finalize and align CPU offset 348 _cpu_offset = align_up(_cpu_offset, DEFAULT_CACHE_LINE_SIZE); 349 350 // Allocation aligned memory 351 const size_t size = _cpu_offset * ZCPU::count(); 352 _base = ZUtils::alloc_aligned(DEFAULT_CACHE_LINE_SIZE, size); 353 memset((void*)_base, 0, size); 354 } 355 356 const char* ZStatValue::group() const { 357 return _group; 358 } 359 360 const char* ZStatValue::name() const { 361 return _name; 362 } 363 364 uint32_t ZStatValue::id() const { 365 return _id; 366 } 367 368 // 369 // Stat iterable value 370 // 371 template <typename T> uint32_t ZStatIterableValue<T>::_count = 0; 372 template <typename T> T* ZStatIterableValue<T>::_first = NULL; 373 374 template <typename T> 375 ZStatIterableValue<T>::ZStatIterableValue(const char* group, 376 const char* name, 377 uint32_t size) : 378 ZStatValue(group, name, _count++, size), 379 _next(insert()) {} 380 381 template <typename T> 382 T* ZStatIterableValue<T>::insert() const { 383 T** current = &_first; 384 385 while (*current != NULL) { 386 // First sort by group, then by name 387 const int group_cmp = strcmp((*current)->group(), group()); 388 const int name_cmp = strcmp((*current)->name(), name()); 389 if ((group_cmp > 0) || (group_cmp == 0 && name_cmp > 0)) { 390 break; 391 } 392 393 current = &(*current)->_next; 394 } 395 396 T* const next = *current; 397 *current = (T*)this; 398 return next; 399 } 400 401 // 402 // Stat sampler 403 // 404 ZStatSampler::ZStatSampler(const char* group, const char* name, ZStatUnitPrinter printer) : 405 ZStatIterableValue(group, name, sizeof(ZStatSamplerData)), 406 _printer(printer) {} 407 408 ZStatSamplerData* ZStatSampler::get() const { 409 return get_cpu_local<ZStatSamplerData>(ZCPU::id()); 410 } 411 412 ZStatSamplerData ZStatSampler::collect_and_reset() const { 413 ZStatSamplerData all; 414 415 const uint32_t ncpus = ZCPU::count(); 416 for (uint32_t i = 0; i < ncpus; i++) { 417 ZStatSamplerData* const cpu_data = get_cpu_local<ZStatSamplerData>(i); 418 if (cpu_data->_nsamples > 0) { 419 const uint64_t nsamples = Atomic::xchg((uint64_t)0, &cpu_data->_nsamples); 420 const uint64_t sum = Atomic::xchg((uint64_t)0, &cpu_data->_sum); 421 const uint64_t max = Atomic::xchg((uint64_t)0, &cpu_data->_max); 422 all._nsamples += nsamples; 423 all._sum += sum; 424 if (all._max < max) { 425 all._max = max; 426 } 427 } 428 } 429 430 return all; 431 } 432 433 ZStatUnitPrinter ZStatSampler::printer() const { 434 return _printer; 435 } 436 437 // 438 // Stat counter 439 // 440 ZStatCounter::ZStatCounter(const char* group, const char* name, ZStatUnitPrinter printer) : 441 ZStatIterableValue(group, name, sizeof(ZStatCounterData)), 442 _sampler(group, name, printer) {} 443 444 ZStatCounterData* ZStatCounter::get() const { 445 return get_cpu_local<ZStatCounterData>(ZCPU::id()); 446 } 447 448 void ZStatCounter::sample_and_reset() const { 449 uint64_t counter = 0; 450 451 const uint32_t ncpus = ZCPU::count(); 452 for (uint32_t i = 0; i < ncpus; i++) { 453 ZStatCounterData* const cpu_data = get_cpu_local<ZStatCounterData>(i); 454 counter += Atomic::xchg((uint64_t)0, &cpu_data->_counter); 455 } 456 457 ZStatSample(_sampler, counter); 458 } 459 460 // 461 // Stat unsampled counter 462 // 463 ZStatUnsampledCounter::ZStatUnsampledCounter(const char* name) : 464 ZStatIterableValue("Unsampled", name, sizeof(ZStatCounterData)) {} 465 466 ZStatCounterData* ZStatUnsampledCounter::get() const { 467 return get_cpu_local<ZStatCounterData>(ZCPU::id()); 468 } 469 470 ZStatCounterData ZStatUnsampledCounter::collect_and_reset() const { 471 ZStatCounterData all; 472 473 const uint32_t ncpus = ZCPU::count(); 474 for (uint32_t i = 0; i < ncpus; i++) { 475 ZStatCounterData* const cpu_data = get_cpu_local<ZStatCounterData>(i); 476 all._counter += Atomic::xchg((uint64_t)0, &cpu_data->_counter); 477 } 478 479 return all; 480 } 481 482 // 483 // Stat MMU (Mimimum Mutator Utilization) 484 // 485 ZStatMMUPause::ZStatMMUPause() : 486 _start(0.0), 487 _end(0.0) {} 488 489 ZStatMMUPause::ZStatMMUPause(const Ticks& start, const Ticks& end) : 490 _start(TimeHelper::counter_to_millis(start.value())), 491 _end(TimeHelper::counter_to_millis(end.value())) {} 492 493 double ZStatMMUPause::end() const { 494 return _end; 495 } 496 497 double ZStatMMUPause::overlap(double start, double end) const { 498 const double start_max = MAX2(start, _start); 499 const double end_min = MIN2(end, _end); 500 501 if (end_min > start_max) { 502 // Overlap found 503 return end_min - start_max; 504 } 505 506 // No overlap 507 return 0.0; 508 } 509 510 size_t ZStatMMU::_next = 0; 511 size_t ZStatMMU::_npauses = 0; 512 ZStatMMUPause ZStatMMU::_pauses[200]; 513 double ZStatMMU::_mmu_2ms = 100.0; 514 double ZStatMMU::_mmu_5ms = 100.0; 515 double ZStatMMU::_mmu_10ms = 100.0; 516 double ZStatMMU::_mmu_20ms = 100.0; 517 double ZStatMMU::_mmu_50ms = 100.0; 518 double ZStatMMU::_mmu_100ms = 100.0; 519 520 const ZStatMMUPause& ZStatMMU::pause(size_t index) { 521 return _pauses[(_next - index - 1) % ARRAY_SIZE(_pauses)]; 522 } 523 524 double ZStatMMU::calculate_mmu(double time_slice) { 525 const double end = pause(0).end(); 526 const double start = end - time_slice; 527 double time_paused = 0.0; 528 529 // Find all overlapping pauses 530 for (size_t i = 0; i < _npauses; i++) { 531 const double overlap = pause(i).overlap(start, end); 532 if (overlap == 0.0) { 533 // No overlap 534 break; 535 } 536 537 time_paused += overlap; 538 } 539 540 // Calculate MMU 541 const double time_mutator = time_slice - time_paused; 542 return percent_of(time_mutator, time_slice); 543 } 544 545 void ZStatMMU::register_pause(const Ticks& start, const Ticks& end) { 546 // Add pause 547 const size_t index = _next++ % ARRAY_SIZE(_pauses); 548 _pauses[index] = ZStatMMUPause(start, end); 549 _npauses = MIN2(_npauses + 1, ARRAY_SIZE(_pauses)); 550 551 // Recalculate MMUs 552 _mmu_2ms = MIN2(_mmu_2ms, calculate_mmu(2)); 553 _mmu_5ms = MIN2(_mmu_5ms, calculate_mmu(5)); 554 _mmu_10ms = MIN2(_mmu_10ms, calculate_mmu(10)); 555 _mmu_20ms = MIN2(_mmu_20ms, calculate_mmu(20)); 556 _mmu_50ms = MIN2(_mmu_50ms, calculate_mmu(50)); 557 _mmu_100ms = MIN2(_mmu_100ms, calculate_mmu(100)); 558 } 559 560 void ZStatMMU::print() { 561 log_info(gc, mmu)( 562 "MMU: 2ms/%.1f%%, 5ms/%.1f%%, 10ms/%.1f%%, 20ms/%.1f%%, 50ms/%.1f%%, 100ms/%.1f%%", 563 _mmu_2ms, _mmu_5ms, _mmu_10ms, _mmu_20ms, _mmu_50ms, _mmu_100ms); 564 } 565 566 // 567 // Stat phases 568 // 569 ConcurrentGCTimer ZStatPhase::_timer; 570 571 ZStatPhase::ZStatPhase(const char* group, const char* name) : 572 _sampler(group, name, ZStatUnitTime) {} 573 574 void ZStatPhase::log_start(LogTargetHandle log, bool thread) const { 575 if (!log.is_enabled()) { 576 return; 577 } 578 579 if (thread) { 580 ResourceMark rm; 581 log.print("%s (%s)", name(), Thread::current()->name()); 582 } else { 583 log.print("%s", name()); 584 } 585 } 586 587 void ZStatPhase::log_end(LogTargetHandle log, const Tickspan& duration, bool thread) const { 588 if (!log.is_enabled()) { 589 return; 590 } 591 592 if (thread) { 593 ResourceMark rm; 594 log.print("%s (%s) %.3fms", name(), Thread::current()->name(), TimeHelper::counter_to_millis(duration.value())); 595 } else { 596 log.print("%s %.3fms", name(), TimeHelper::counter_to_millis(duration.value())); 597 } 598 } 599 600 ConcurrentGCTimer* ZStatPhase::timer() { 601 return &_timer; 602 } 603 604 const char* ZStatPhase::name() const { 605 return _sampler.name(); 606 } 607 608 ZStatPhaseCycle::ZStatPhaseCycle(const char* name) : 609 ZStatPhase("Collector", name) {} 610 611 void ZStatPhaseCycle::register_start(const Ticks& start) const { 612 timer()->register_gc_start(start); 613 614 ZTracer::tracer()->report_gc_start(ZCollectedHeap::heap()->gc_cause(), start); 615 616 ZCollectedHeap::heap()->print_heap_before_gc(); 617 ZCollectedHeap::heap()->trace_heap_before_gc(ZTracer::tracer()); 618 619 log_info(gc, start)("Garbage Collection (%s)", 620 GCCause::to_string(ZCollectedHeap::heap()->gc_cause())); 621 } 622 623 #define ZUSED_FMT SIZE_FORMAT "M(%.0lf%%)" 624 #define ZUSED_ARGS(size, max_capacity) ((size) / M), (percent_of<size_t>(size, max_capacity)) 625 626 void ZStatPhaseCycle::register_end(const Ticks& start, const Ticks& end) const { 627 timer()->register_gc_end(end); 628 629 ZCollectedHeap::heap()->print_heap_after_gc(); 630 ZCollectedHeap::heap()->trace_heap_after_gc(ZTracer::tracer()); 631 632 ZTracer::tracer()->report_gc_end(end, timer()->time_partitions()); 633 634 const Tickspan duration = end - start; 635 ZStatSample(_sampler, duration.value()); 636 637 ZStatLoad::print(); 638 ZStatMMU::print(); 639 ZStatMark::print(); 640 ZStatRelocation::print(); 641 ZStatNMethods::print(); 642 ZStatReferences::print(); 643 ZStatHeap::print(); 644 645 log_info(gc)("Garbage Collection (%s) " ZUSED_FMT "->" ZUSED_FMT, 646 GCCause::to_string(ZCollectedHeap::heap()->gc_cause()), 647 ZUSED_ARGS(ZStatHeap::used_at_mark_start(), ZStatHeap::max_capacity()), 648 ZUSED_ARGS(ZStatHeap::used_at_relocate_end(), ZStatHeap::max_capacity())); 649 } 650 651 Tickspan ZStatPhasePause::_max; 652 653 ZStatPhasePause::ZStatPhasePause(const char* name) : 654 ZStatPhase("Phase", name) {} 655 656 const Tickspan& ZStatPhasePause::max() { 657 return _max; 658 } 659 660 void ZStatPhasePause::register_start(const Ticks& start) const { 661 timer()->register_gc_pause_start(name(), start); 662 663 LogTarget(Debug, gc, phases, start) log; 664 log_start(log); 665 } 666 667 void ZStatPhasePause::register_end(const Ticks& start, const Ticks& end) const { 668 timer()->register_gc_pause_end(end); 669 670 const Tickspan duration = end - start; 671 ZStatSample(_sampler, duration.value()); 672 673 // Track max pause time 674 if (_max < duration) { 675 _max = duration; 676 } 677 678 // Track minimum mutator utilization 679 ZStatMMU::register_pause(start, end); 680 681 LogTarget(Info, gc, phases) log; 682 log_end(log, duration); 683 } 684 685 ZStatPhaseConcurrent::ZStatPhaseConcurrent(const char* name) : 686 ZStatPhase("Phase", name) {} 687 688 void ZStatPhaseConcurrent::register_start(const Ticks& start) const { 689 timer()->register_gc_concurrent_start(name(), start); 690 691 LogTarget(Debug, gc, phases, start) log; 692 log_start(log); 693 } 694 695 void ZStatPhaseConcurrent::register_end(const Ticks& start, const Ticks& end) const { 696 timer()->register_gc_concurrent_end(end); 697 698 const Tickspan duration = end - start; 699 ZStatSample(_sampler, duration.value()); 700 701 LogTarget(Info, gc, phases) log; 702 log_end(log, duration); 703 } 704 705 ZStatSubPhase::ZStatSubPhase(const char* name) : 706 ZStatPhase("Subphase", name) {} 707 708 void ZStatSubPhase::register_start(const Ticks& start) const { 709 LogTarget(Debug, gc, phases, start) log; 710 log_start(log, true /* thread */); 711 } 712 713 void ZStatSubPhase::register_end(const Ticks& start, const Ticks& end) const { 714 ZTracer::tracer()->report_thread_phase(*this, start, end); 715 716 const Tickspan duration = end - start; 717 ZStatSample(_sampler, duration.value()); 718 719 LogTarget(Debug, gc, phases) log; 720 log_end(log, duration, true /* thread */); 721 } 722 723 ZStatCriticalPhase::ZStatCriticalPhase(const char* name, bool verbose) : 724 ZStatPhase("Critical", name), 725 _counter("Critical", name, ZStatUnitOpsPerSecond), 726 _verbose(verbose) {} 727 728 void ZStatCriticalPhase::register_start(const Ticks& start) const { 729 LogTarget(Debug, gc, start) log; 730 log_start(log, true /* thread */); 731 } 732 733 void ZStatCriticalPhase::register_end(const Ticks& start, const Ticks& end) const { 734 ZTracer::tracer()->report_thread_phase(*this, start, end); 735 736 const Tickspan duration = end - start; 737 ZStatSample(_sampler, duration.value()); 738 ZStatInc(_counter); 739 740 if (_verbose) { 741 LogTarget(Info, gc) log; 742 log_end(log, duration, true /* thread */); 743 } else { 744 LogTarget(Debug, gc) log; 745 log_end(log, duration, true /* thread */); 746 } 747 } 748 749 // 750 // Stat sample/inc 751 // 752 void ZStatSample(const ZStatSampler& sampler, uint64_t value, bool trace) { 753 ZStatSamplerData* const cpu_data = sampler.get(); 754 Atomic::add(1u, &cpu_data->_nsamples); 755 Atomic::add(value, &cpu_data->_sum); 756 757 uint64_t max = cpu_data->_max; 758 for (;;) { 759 if (max >= value) { 760 // Not max 761 break; 762 } 763 764 const uint64_t new_max = value; 765 const uint64_t prev_max = Atomic::cmpxchg(new_max, &cpu_data->_max, max); 766 if (prev_max == max) { 767 // Success 768 break; 769 } 770 771 // Retry 772 max = prev_max; 773 } 774 775 if (trace) { 776 ZTracer::tracer()->report_stat_sampler(sampler, value); 777 } 778 } 779 780 void ZStatInc(const ZStatCounter& counter, uint64_t increment, bool trace) { 781 ZStatCounterData* const cpu_data = counter.get(); 782 const uint64_t value = Atomic::add(increment, &cpu_data->_counter); 783 784 if (trace) { 785 ZTracer::tracer()->report_stat_counter(counter, increment, value); 786 } 787 } 788 789 void ZStatInc(const ZStatUnsampledCounter& counter, uint64_t increment) { 790 ZStatCounterData* const cpu_data = counter.get(); 791 Atomic::add(increment, &cpu_data->_counter); 792 } 793 794 // 795 // Stat allocation rate 796 // 797 const ZStatUnsampledCounter ZStatAllocRate::_counter("Allocation Rate"); 798 TruncatedSeq ZStatAllocRate::_rate(ZStatAllocRate::sample_window_sec * ZStatAllocRate::sample_hz); 799 TruncatedSeq ZStatAllocRate::_rate_avg(ZStatAllocRate::sample_window_sec * ZStatAllocRate::sample_hz); 800 801 const ZStatUnsampledCounter& ZStatAllocRate::counter() { 802 return _counter; 803 } 804 805 uint64_t ZStatAllocRate::sample_and_reset() { 806 const ZStatCounterData bytes_per_sample = _counter.collect_and_reset(); 807 const uint64_t bytes_per_second = bytes_per_sample._counter * sample_hz; 808 809 _rate.add(bytes_per_second); 810 _rate_avg.add(_rate.avg()); 811 812 return bytes_per_second; 813 } 814 815 double ZStatAllocRate::avg() { 816 return _rate.avg(); 817 } 818 819 double ZStatAllocRate::avg_sd() { 820 return _rate_avg.sd(); 821 } 822 823 // 824 // Stat thread 825 // 826 ZStat::ZStat() : 827 _metronome(sample_hz) { 828 set_name("ZStat"); 829 create_and_start(); 830 } 831 832 void ZStat::sample_and_collect(ZStatSamplerHistory* history) const { 833 // Sample counters 834 for (const ZStatCounter* counter = ZStatCounter::first(); counter != NULL; counter = counter->next()) { 835 counter->sample_and_reset(); 836 } 837 838 // Collect samples 839 for (const ZStatSampler* sampler = ZStatSampler::first(); sampler != NULL; sampler = sampler->next()) { 840 ZStatSamplerHistory& sampler_history = history[sampler->id()]; 841 sampler_history.add(sampler->collect_and_reset()); 842 } 843 } 844 845 bool ZStat::should_print(LogTargetHandle log) const { 846 return log.is_enabled() && (_metronome.nticks() % ZStatisticsInterval == 0); 847 } 848 849 void ZStat::print(LogTargetHandle log, const ZStatSamplerHistory* history) const { 850 // Print 851 log.print("=== Garbage Collection Statistics ======================================================================================================================="); 852 log.print(" Last 10s Last 10m Last 10h Total"); 853 log.print(" Avg / Max Avg / Max Avg / Max Avg / Max"); 854 855 for (const ZStatSampler* sampler = ZStatSampler::first(); sampler != NULL; sampler = sampler->next()) { 856 const ZStatSamplerHistory& sampler_history = history[sampler->id()]; 857 const ZStatUnitPrinter printer = sampler->printer(); 858 printer(log, *sampler, sampler_history); 859 } 860 861 log.print("========================================================================================================================================================="); 862 } 863 864 void ZStat::run_service() { 865 ZStatSamplerHistory* const history = new ZStatSamplerHistory[ZStatSampler::count()]; 866 LogTarget(Info, gc, stats) log; 867 868 // Main loop 869 while (_metronome.wait_for_tick()) { 870 sample_and_collect(history); 871 if (should_print(log)) { 872 print(log, history); 873 } 874 } 875 876 delete [] history; 877 } 878 879 void ZStat::stop_service() { 880 _metronome.stop(); 881 } 882 883 // 884 // Stat table 885 // 886 class ZStatTablePrinter { 887 private: 888 static const size_t _buffer_size = 256; 889 890 const size_t _column0_width; 891 const size_t _columnN_width; 892 char _buffer[_buffer_size]; 893 894 public: 895 class ZColumn { 896 private: 897 char* const _buffer; 898 const size_t _position; 899 const size_t _width; 900 const size_t _width_next; 901 902 ZColumn next() const { 903 // Insert space between columns 904 _buffer[_position + _width] = ' '; 905 return ZColumn(_buffer, _position + _width + 1, _width_next, _width_next); 906 } 907 908 size_t print(size_t position, const char* fmt, va_list va) { 909 const int res = jio_vsnprintf(_buffer + position, _buffer_size - position, fmt, va); 910 if (res < 0) { 911 return 0; 912 } 913 914 return (size_t)res; 915 } 916 917 public: 918 ZColumn(char* buffer, size_t position, size_t width, size_t width_next) : 919 _buffer(buffer), 920 _position(position), 921 _width(width), 922 _width_next(width_next) {} 923 924 ZColumn left(const char* fmt, ...) ATTRIBUTE_PRINTF(2, 3) { 925 va_list va; 926 927 va_start(va, fmt); 928 const size_t written = print(_position, fmt, va); 929 va_end(va); 930 931 if (written < _width) { 932 // Fill empty space 933 memset(_buffer + _position + written, ' ', _width - written); 934 } 935 936 return next(); 937 } 938 939 ZColumn right(const char* fmt, ...) ATTRIBUTE_PRINTF(2, 3) { 940 va_list va; 941 942 va_start(va, fmt); 943 const size_t written = print(_position, fmt, va); 944 va_end(va); 945 946 if (written > _width) { 947 // Line too long 948 return fill('?'); 949 } 950 951 if (written < _width) { 952 // Short line, move all to right 953 memmove(_buffer + _position + _width - written, _buffer + _position, written); 954 955 // Fill empty space 956 memset(_buffer + _position, ' ', _width - written); 957 } 958 959 return next(); 960 } 961 962 ZColumn center(const char* fmt, ...) ATTRIBUTE_PRINTF(2, 3) { 963 va_list va; 964 965 va_start(va, fmt); 966 const size_t written = print(_position, fmt, va); 967 va_end(va); 968 969 if (written > _width) { 970 // Line too long 971 return fill('?'); 972 } 973 974 if (written < _width) { 975 // Short line, move all to center 976 const size_t start_space = (_width - written) / 2; 977 const size_t end_space = _width - written - start_space; 978 memmove(_buffer + _position + start_space, _buffer + _position, written); 979 980 // Fill empty spaces 981 memset(_buffer + _position, ' ', start_space); 982 memset(_buffer + _position + start_space + written, ' ', end_space); 983 } 984 985 return next(); 986 } 987 988 ZColumn fill(char filler = ' ') { 989 memset(_buffer + _position, filler, _width); 990 return next(); 991 } 992 993 const char* end() { 994 _buffer[_position] = '\0'; 995 return _buffer; 996 } 997 }; 998 999 public: 1000 ZStatTablePrinter(size_t column0_width, size_t columnN_width) : 1001 _column0_width(column0_width), 1002 _columnN_width(columnN_width) {} 1003 1004 ZColumn operator()() { 1005 return ZColumn(_buffer, 0, _column0_width, _columnN_width); 1006 } 1007 }; 1008 1009 // 1010 // Stat cycle 1011 // 1012 uint64_t ZStatCycle::_ncycles = 0; 1013 Ticks ZStatCycle::_start_of_last; 1014 Ticks ZStatCycle::_end_of_last; 1015 NumberSeq ZStatCycle::_duration(0.3 /* alpha */); 1016 1017 void ZStatCycle::at_start() { 1018 _start_of_last = Ticks::now(); 1019 } 1020 1021 void ZStatCycle::at_end(double boost_factor) { 1022 _end_of_last = Ticks::now(); 1023 _ncycles++; 1024 1025 // Calculate cycle duration. The cycle duration is normalize using the 1026 // boost factor to avoid artificially deflate the duration when boost 1027 // mode is enabled. 1028 const double duration = TicksToTimeHelper::seconds(_end_of_last - _start_of_last); 1029 const double normalized_duration = duration * boost_factor; 1030 _duration.add(normalized_duration); 1031 } 1032 1033 uint64_t ZStatCycle::ncycles() { 1034 return _ncycles; 1035 } 1036 1037 const AbsSeq& ZStatCycle::duration() { 1038 return _duration; 1039 } 1040 1041 double ZStatCycle::time_since_last() { 1042 if (_ncycles == 0) { 1043 // Return time since VM start-up 1044 return os::elapsedTime(); 1045 } 1046 1047 const Ticks now = Ticks::now(); 1048 const Tickspan time_since_last = now - _end_of_last; 1049 return TicksToTimeHelper::seconds(time_since_last); 1050 } 1051 1052 // 1053 // Stat load 1054 // 1055 void ZStatLoad::print() { 1056 double loadavg[3] = {}; 1057 os::loadavg(loadavg, ARRAY_SIZE(loadavg)); 1058 log_info(gc, load)("Load: %.2f/%.2f/%.2f", loadavg[0], loadavg[1], loadavg[2]); 1059 } 1060 1061 // 1062 // Stat mark 1063 // 1064 size_t ZStatMark::_nstripes; 1065 size_t ZStatMark::_nproactiveflush; 1066 size_t ZStatMark::_nterminateflush; 1067 size_t ZStatMark::_ntrycomplete; 1068 size_t ZStatMark::_ncontinue; 1069 1070 void ZStatMark::print() { 1071 log_info(gc, marking)("Mark: " 1072 SIZE_FORMAT " stripe(s), " 1073 SIZE_FORMAT " proactive flush(es), " 1074 SIZE_FORMAT " terminate flush(es), " 1075 SIZE_FORMAT " completion(s), " 1076 SIZE_FORMAT " continuation(s) ", 1077 _nstripes, 1078 _nproactiveflush, 1079 _nterminateflush, 1080 _ntrycomplete, 1081 _ncontinue); 1082 } 1083 1084 // 1085 // Stat relocation 1086 // 1087 size_t ZStatRelocation::_relocating; 1088 bool ZStatRelocation::_success; 1089 1090 void ZStatRelocation::print() { 1091 if (_success) { 1092 log_info(gc, reloc)("Relocation: Successful, " SIZE_FORMAT "M relocated", _relocating / M); 1093 } else { 1094 log_info(gc, reloc)("Relocation: Incomplete"); 1095 } 1096 } 1097 1098 // 1099 // Stat nmethods 1100 // 1101 void ZStatNMethods::print() { 1102 log_info(gc, nmethod)("NMethods: " SIZE_FORMAT " registered, " SIZE_FORMAT " unregistered", 1103 ZNMethodTable::registered_nmethods(), 1104 ZNMethodTable::unregistered_nmethods()); 1105 } 1106 1107 // 1108 // Stat references 1109 // 1110 ZStatReferences::ZCount ZStatReferences::_soft; 1111 ZStatReferences::ZCount ZStatReferences::_weak; 1112 ZStatReferences::ZCount ZStatReferences::_final; 1113 ZStatReferences::ZCount ZStatReferences::_phantom; 1114 1115 void ZStatReferences::print(const char* name, const ZStatReferences::ZCount& ref) { 1116 log_info(gc, ref)("%s: " 1117 SIZE_FORMAT " encountered, " 1118 SIZE_FORMAT " discovered, " 1119 SIZE_FORMAT " dropped, " 1120 SIZE_FORMAT " enqueued", 1121 name, 1122 ref.encountered, 1123 ref.discovered, 1124 ref.dropped, 1125 ref.enqueued); 1126 } 1127 1128 void ZStatReferences::print() { 1129 print("Soft", _soft); 1130 print("Weak", _weak); 1131 print("Final", _final); 1132 print("Phantom", _phantom); 1133 } 1134 1135 // 1136 // Stat heap 1137 // 1138 ZStatHeap::ZAtInitialize ZStatHeap::_at_initialize; 1139 ZStatHeap::ZAtMarkStart ZStatHeap::_at_mark_start; 1140 ZStatHeap::ZAtMarkEnd ZStatHeap::_at_mark_end; 1141 ZStatHeap::ZAtRelocateStart ZStatHeap::_at_relocate_start; 1142 ZStatHeap::ZAtRelocateEnd ZStatHeap::_at_relocate_end; 1143 1144 #define ZSIZE_NA "%9s", "-" 1145 #define ZSIZE_ARGS(size) SIZE_FORMAT_W(8) "M (%.0lf%%)", \ 1146 ((size) / M), (percent_of<size_t>(size, _at_initialize.max_capacity)) 1147 1148 void ZStatHeap::print() { 1149 ZStatTablePrinter table(10, 18); 1150 log_info(gc, heap)("%s", table() 1151 .fill() 1152 .center("Mark Start") 1153 .center("Mark End") 1154 .center("Relocate Start") 1155 .center("Relocate End") 1156 .center("High") 1157 .center("Low") 1158 .end()); 1159 log_info(gc, heap)("%s", table() 1160 .right("Capacity:") 1161 .left(ZSIZE_ARGS(_at_mark_start.capacity)) 1162 .left(ZSIZE_ARGS(_at_mark_end.capacity)) 1163 .left(ZSIZE_ARGS(_at_relocate_start.capacity)) 1164 .left(ZSIZE_ARGS(_at_relocate_end.capacity)) 1165 .left(ZSIZE_ARGS(_at_relocate_end.capacity_high)) 1166 .left(ZSIZE_ARGS(_at_relocate_end.capacity_low)) 1167 .end()); 1168 log_info(gc, heap)("%s", table() 1169 .right("Reserve:") 1170 .left(ZSIZE_ARGS(_at_mark_start.reserve)) 1171 .left(ZSIZE_ARGS(_at_mark_end.reserve)) 1172 .left(ZSIZE_ARGS(_at_relocate_start.reserve)) 1173 .left(ZSIZE_ARGS(_at_relocate_end.reserve)) 1174 .left(ZSIZE_ARGS(_at_relocate_end.reserve_high)) 1175 .left(ZSIZE_ARGS(_at_relocate_end.reserve_low)) 1176 .end()); 1177 log_info(gc, heap)("%s", table() 1178 .right("Free:") 1179 .left(ZSIZE_ARGS(_at_mark_start.free)) 1180 .left(ZSIZE_ARGS(_at_mark_end.free)) 1181 .left(ZSIZE_ARGS(_at_relocate_start.free)) 1182 .left(ZSIZE_ARGS(_at_relocate_end.free)) 1183 .left(ZSIZE_ARGS(_at_relocate_end.free_high)) 1184 .left(ZSIZE_ARGS(_at_relocate_end.free_low)) 1185 .end()); 1186 log_info(gc, heap)("%s", table() 1187 .right("Used:") 1188 .left(ZSIZE_ARGS(_at_mark_start.used)) 1189 .left(ZSIZE_ARGS(_at_mark_end.used)) 1190 .left(ZSIZE_ARGS(_at_relocate_start.used)) 1191 .left(ZSIZE_ARGS(_at_relocate_end.used)) 1192 .left(ZSIZE_ARGS(_at_relocate_end.used_high)) 1193 .left(ZSIZE_ARGS(_at_relocate_end.used_low)) 1194 .end()); 1195 log_info(gc, heap)("%s", table() 1196 .right("Live:") 1197 .left(ZSIZE_NA) 1198 .left(ZSIZE_ARGS(_at_mark_end.live)) 1199 .left(ZSIZE_ARGS(_at_mark_end.live /* Same as at mark end */)) 1200 .left(ZSIZE_ARGS(_at_mark_end.live /* Same as at mark end */)) 1201 .left(ZSIZE_NA) 1202 .left(ZSIZE_NA) 1203 .end()); 1204 log_info(gc, heap)("%s", table() 1205 .right("Allocated:") 1206 .left(ZSIZE_NA) 1207 .left(ZSIZE_ARGS(_at_mark_end.allocated)) 1208 .left(ZSIZE_ARGS(_at_relocate_start.allocated)) 1209 .left(ZSIZE_ARGS(_at_relocate_end.allocated)) 1210 .left(ZSIZE_NA) 1211 .left(ZSIZE_NA) 1212 .end()); 1213 log_info(gc, heap)("%s", table() 1214 .right("Garbage:") 1215 .left(ZSIZE_NA) 1216 .left(ZSIZE_ARGS(_at_mark_end.garbage)) 1217 .left(ZSIZE_ARGS(_at_relocate_start.garbage)) 1218 .left(ZSIZE_ARGS(_at_relocate_end.garbage)) 1219 .left(ZSIZE_NA) 1220 .left(ZSIZE_NA) 1221 .end()); 1222 log_info(gc, heap)("%s", table() 1223 .right("Reclaimed:") 1224 .left(ZSIZE_NA) 1225 .left(ZSIZE_NA) 1226 .left(ZSIZE_ARGS(_at_relocate_start.reclaimed)) 1227 .left(ZSIZE_ARGS(_at_relocate_end.reclaimed)) 1228 .left(ZSIZE_NA) 1229 .left(ZSIZE_NA) 1230 .end()); 1231 }