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