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 _accumulated(),
87 _total() {}
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<ZStatSampler>(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<ZStatCounter>(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<ZStatUnsampledCounter>("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 (Minimum 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)("MMU: 2ms/%.1f%%, 5ms/%.1f%%, 10ms/%.1f%%, 20ms/%.1f%%, 50ms/%.1f%%, 100ms/%.1f%%",
564 _mmu_2ms, _mmu_5ms, _mmu_10ms, _mmu_20ms, _mmu_50ms, _mmu_100ms);
565 }
566
567 //
568 // Stat phases
569 //
570 ConcurrentGCTimer ZStatPhase::_timer;
571
572 ZStatPhase::ZStatPhase(const char* group, const char* name) :
573 _sampler(group, name, ZStatUnitTime) {}
574
575 void ZStatPhase::log_start(LogTargetHandle log, bool thread) const {
576 if (!log.is_enabled()) {
577 return;
578 }
579
580 if (thread) {
581 ResourceMark rm;
582 log.print("%s (%s)", name(), Thread::current()->name());
583 } else {
584 log.print("%s", name());
585 }
586 }
587
588 void ZStatPhase::log_end(LogTargetHandle log, const Tickspan& duration, bool thread) const {
589 if (!log.is_enabled()) {
590 return;
591 }
592
593 if (thread) {
594 ResourceMark rm;
595 log.print("%s (%s) %.3fms", name(), Thread::current()->name(), TimeHelper::counter_to_millis(duration.value()));
596 } else {
597 log.print("%s %.3fms", name(), TimeHelper::counter_to_millis(duration.value()));
598 }
599 }
600
601 ConcurrentGCTimer* ZStatPhase::timer() {
602 return &_timer;
603 }
604
605 const char* ZStatPhase::name() const {
606 return _sampler.name();
607 }
608
609 ZStatPhaseCycle::ZStatPhaseCycle(const char* name) :
610 ZStatPhase("Collector", name) {}
611
612 void ZStatPhaseCycle::register_start(const Ticks& start) const {
613 timer()->register_gc_start(start);
614
615 ZTracer::tracer()->report_gc_start(ZCollectedHeap::heap()->gc_cause(), start);
616
617 ZCollectedHeap::heap()->print_heap_before_gc();
618 ZCollectedHeap::heap()->trace_heap_before_gc(ZTracer::tracer());
619
620 log_info(gc, start)("Garbage Collection (%s)",
621 GCCause::to_string(ZCollectedHeap::heap()->gc_cause()));
622 }
623
624 #define ZUSED_FMT SIZE_FORMAT "M(%.0lf%%)"
625 #define ZUSED_ARGS(size, max_capacity) ((size) / M), (percent_of(size, max_capacity))
626
627 void ZStatPhaseCycle::register_end(const Ticks& start, const Ticks& end) const {
628 timer()->register_gc_end(end);
629
630 ZCollectedHeap::heap()->print_heap_after_gc();
631 ZCollectedHeap::heap()->trace_heap_after_gc(ZTracer::tracer());
632
633 ZTracer::tracer()->report_gc_end(end, timer()->time_partitions());
634
635 const Tickspan duration = end - start;
636 ZStatSample(_sampler, duration.value());
637
638 ZStatLoad::print();
639 ZStatMMU::print();
640 ZStatMark::print();
641 ZStatRelocation::print();
642 ZStatNMethods::print();
643 ZStatMetaspace::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 timer
753 //
754 __thread uint32_t ZStatTimerDisable::_active = 0;
755
756 //
757 // Stat sample/inc
758 //
759 void ZStatSample(const ZStatSampler& sampler, uint64_t value, bool trace) {
760 ZStatSamplerData* const cpu_data = sampler.get();
761 Atomic::add(1u, &cpu_data->_nsamples);
762 Atomic::add(value, &cpu_data->_sum);
763
764 uint64_t max = cpu_data->_max;
765 for (;;) {
766 if (max >= value) {
767 // Not max
768 break;
769 }
770
771 const uint64_t new_max = value;
772 const uint64_t prev_max = Atomic::cmpxchg(new_max, &cpu_data->_max, max);
773 if (prev_max == max) {
774 // Success
775 break;
776 }
777
778 // Retry
779 max = prev_max;
780 }
781
782 if (trace) {
783 ZTracer::tracer()->report_stat_sampler(sampler, value);
784 }
785 }
786
787 void ZStatInc(const ZStatCounter& counter, uint64_t increment, bool trace) {
788 ZStatCounterData* const cpu_data = counter.get();
789 const uint64_t value = Atomic::add(increment, &cpu_data->_counter);
790
791 if (trace) {
792 ZTracer::tracer()->report_stat_counter(counter, increment, value);
793 }
794 }
795
796 void ZStatInc(const ZStatUnsampledCounter& counter, uint64_t increment) {
797 ZStatCounterData* const cpu_data = counter.get();
798 Atomic::add(increment, &cpu_data->_counter);
799 }
800
801 //
802 // Stat allocation rate
803 //
804 const ZStatUnsampledCounter ZStatAllocRate::_counter("Allocation Rate");
805 TruncatedSeq ZStatAllocRate::_rate(ZStatAllocRate::sample_window_sec * ZStatAllocRate::sample_hz);
806 TruncatedSeq ZStatAllocRate::_rate_avg(ZStatAllocRate::sample_window_sec * ZStatAllocRate::sample_hz);
807
808 const ZStatUnsampledCounter& ZStatAllocRate::counter() {
809 return _counter;
810 }
811
812 uint64_t ZStatAllocRate::sample_and_reset() {
813 const ZStatCounterData bytes_per_sample = _counter.collect_and_reset();
814 const uint64_t bytes_per_second = bytes_per_sample._counter * sample_hz;
815
816 _rate.add(bytes_per_second);
817 _rate_avg.add(_rate.avg());
818
819 return bytes_per_second;
820 }
821
822 double ZStatAllocRate::avg() {
823 return _rate.avg();
824 }
825
826 double ZStatAllocRate::avg_sd() {
827 return _rate_avg.sd();
828 }
829
830 //
831 // Stat thread
832 //
833 ZStat::ZStat() :
834 _metronome(sample_hz) {
835 set_name("ZStat");
836 create_and_start();
837 }
838
839 void ZStat::sample_and_collect(ZStatSamplerHistory* history) const {
840 // Sample counters
841 for (const ZStatCounter* counter = ZStatCounter::first(); counter != NULL; counter = counter->next()) {
842 counter->sample_and_reset();
843 }
844
845 // Collect samples
846 for (const ZStatSampler* sampler = ZStatSampler::first(); sampler != NULL; sampler = sampler->next()) {
847 ZStatSamplerHistory& sampler_history = history[sampler->id()];
848 sampler_history.add(sampler->collect_and_reset());
849 }
850 }
851
852 bool ZStat::should_print(LogTargetHandle log) const {
853 return log.is_enabled() && (_metronome.nticks() % ZStatisticsInterval == 0);
854 }
855
856 void ZStat::print(LogTargetHandle log, const ZStatSamplerHistory* history) const {
857 // Print
858 log.print("=== Garbage Collection Statistics =======================================================================================================================");
859 log.print(" Last 10s Last 10m Last 10h Total");
860 log.print(" Avg / Max Avg / Max Avg / Max Avg / Max");
861
862 for (const ZStatSampler* sampler = ZStatSampler::first(); sampler != NULL; sampler = sampler->next()) {
863 const ZStatSamplerHistory& sampler_history = history[sampler->id()];
864 const ZStatUnitPrinter printer = sampler->printer();
865 printer(log, *sampler, sampler_history);
866 }
867
868 log.print("=========================================================================================================================================================");
869 }
870
871 void ZStat::run_service() {
872 ZStatSamplerHistory* const history = new ZStatSamplerHistory[ZStatSampler::count()];
873 LogTarget(Info, gc, stats) log;
874
875 // Main loop
876 while (_metronome.wait_for_tick()) {
877 sample_and_collect(history);
878 if (should_print(log)) {
879 print(log, history);
880 }
881 }
882
883 delete [] history;
884 }
885
886 void ZStat::stop_service() {
887 _metronome.stop();
888 }
889
890 //
891 // Stat table
892 //
893 class ZStatTablePrinter {
894 private:
895 static const size_t _buffer_size = 256;
896
897 const size_t _column0_width;
898 const size_t _columnN_width;
899 char _buffer[_buffer_size];
900
901 public:
902 class ZColumn {
903 private:
904 char* const _buffer;
905 const size_t _position;
906 const size_t _width;
907 const size_t _width_next;
908
909 ZColumn next() const {
910 // Insert space between columns
911 _buffer[_position + _width] = ' ';
912 return ZColumn(_buffer, _position + _width + 1, _width_next, _width_next);
913 }
914
915 size_t print(size_t position, const char* fmt, va_list va) {
916 const int res = jio_vsnprintf(_buffer + position, _buffer_size - position, fmt, va);
917 if (res < 0) {
918 return 0;
919 }
920
921 return (size_t)res;
922 }
923
924 public:
925 ZColumn(char* buffer, size_t position, size_t width, size_t width_next) :
926 _buffer(buffer),
927 _position(position),
928 _width(width),
929 _width_next(width_next) {}
930
931 ZColumn left(const char* fmt, ...) ATTRIBUTE_PRINTF(2, 3) {
932 va_list va;
933
934 va_start(va, fmt);
935 const size_t written = print(_position, fmt, va);
936 va_end(va);
937
938 if (written < _width) {
939 // Fill empty space
940 memset(_buffer + _position + written, ' ', _width - written);
941 }
942
943 return next();
944 }
945
946 ZColumn right(const char* fmt, ...) ATTRIBUTE_PRINTF(2, 3) {
947 va_list va;
948
949 va_start(va, fmt);
950 const size_t written = print(_position, fmt, va);
951 va_end(va);
952
953 if (written > _width) {
954 // Line too long
955 return fill('?');
956 }
957
958 if (written < _width) {
959 // Short line, move all to right
960 memmove(_buffer + _position + _width - written, _buffer + _position, written);
961
962 // Fill empty space
963 memset(_buffer + _position, ' ', _width - written);
964 }
965
966 return next();
967 }
968
969 ZColumn center(const char* fmt, ...) ATTRIBUTE_PRINTF(2, 3) {
970 va_list va;
971
972 va_start(va, fmt);
973 const size_t written = print(_position, fmt, va);
974 va_end(va);
975
976 if (written > _width) {
977 // Line too long
978 return fill('?');
979 }
980
981 if (written < _width) {
982 // Short line, move all to center
983 const size_t start_space = (_width - written) / 2;
984 const size_t end_space = _width - written - start_space;
985 memmove(_buffer + _position + start_space, _buffer + _position, written);
986
987 // Fill empty spaces
988 memset(_buffer + _position, ' ', start_space);
989 memset(_buffer + _position + start_space + written, ' ', end_space);
990 }
991
992 return next();
993 }
994
995 ZColumn fill(char filler = ' ') {
996 memset(_buffer + _position, filler, _width);
997 return next();
998 }
999
1000 const char* end() {
1001 _buffer[_position] = '\0';
1002 return _buffer;
1003 }
1004 };
1005
1006 public:
1007 ZStatTablePrinter(size_t column0_width, size_t columnN_width) :
1008 _column0_width(column0_width),
1009 _columnN_width(columnN_width) {}
1010
1011 ZColumn operator()() {
1012 return ZColumn(_buffer, 0, _column0_width, _columnN_width);
1013 }
1014 };
1015
1016 //
1017 // Stat cycle
1018 //
1019 uint64_t ZStatCycle::_ncycles = 0;
1020 Ticks ZStatCycle::_start_of_last;
1021 Ticks ZStatCycle::_end_of_last;
1022 NumberSeq ZStatCycle::_normalized_duration(0.3 /* alpha */);
1023
1024 void ZStatCycle::at_start() {
1025 _start_of_last = Ticks::now();
1026 }
1027
1028 void ZStatCycle::at_end(double boost_factor) {
1029 _end_of_last = Ticks::now();
1030 _ncycles++;
1031
1032 // Calculate normalized cycle duration. The measured duration is
1033 // normalized using the boost factor to avoid artificial deflation
1034 // of the duration when boost mode is enabled.
1035 const double duration = (_end_of_last - _start_of_last).seconds();
1036 const double normalized_duration = duration * boost_factor;
1037 _normalized_duration.add(normalized_duration);
1038 }
1039
1040 uint64_t ZStatCycle::ncycles() {
1041 return _ncycles;
1042 }
1043
1044 const AbsSeq& ZStatCycle::normalized_duration() {
1045 return _normalized_duration;
1046 }
1047
1048 double ZStatCycle::time_since_last() {
1049 if (_ncycles == 0) {
1050 // Return time since VM start-up
1051 return os::elapsedTime();
1052 }
1053
1054 const Ticks now = Ticks::now();
1055 const Tickspan time_since_last = now - _end_of_last;
1056 return time_since_last.seconds();
1057 }
1058
1059 //
1060 // Stat load
1061 //
1062 void ZStatLoad::print() {
1063 double loadavg[3] = {};
1064 os::loadavg(loadavg, ARRAY_SIZE(loadavg));
1065 log_info(gc, load)("Load: %.2f/%.2f/%.2f", loadavg[0], loadavg[1], loadavg[2]);
1066 }
1067
1068 //
1069 // Stat mark
1070 //
1071 size_t ZStatMark::_nstripes;
1072 size_t ZStatMark::_nproactiveflush;
1073 size_t ZStatMark::_nterminateflush;
1074 size_t ZStatMark::_ntrycomplete;
1075 size_t ZStatMark::_ncontinue;
1076
1077 void ZStatMark::set_at_mark_start(size_t nstripes) {
1078 _nstripes = nstripes;
1079 }
1080
1081 void ZStatMark::set_at_mark_end(size_t nproactiveflush,
1082 size_t nterminateflush,
1083 size_t ntrycomplete,
1084 size_t ncontinue) {
1085 _nproactiveflush = nproactiveflush;
1086 _nterminateflush = nterminateflush;
1087 _ntrycomplete = ntrycomplete;
1088 _ncontinue = ncontinue;
1089 }
1090
1091 void ZStatMark::print() {
1092 log_info(gc, marking)("Mark: "
1093 SIZE_FORMAT " stripe(s), "
1094 SIZE_FORMAT " proactive flush(es), "
1095 SIZE_FORMAT " terminate flush(es), "
1096 SIZE_FORMAT " completion(s), "
1097 SIZE_FORMAT " continuation(s) ",
1098 _nstripes,
1099 _nproactiveflush,
1100 _nterminateflush,
1101 _ntrycomplete,
1102 _ncontinue);
1103 }
1104
1105 //
1106 // Stat relocation
1107 //
1108 size_t ZStatRelocation::_relocating;
1109 bool ZStatRelocation::_success;
1110
1111 void ZStatRelocation::set_at_select_relocation_set(size_t relocating) {
1112 _relocating = relocating;
1113 }
1114
1115 void ZStatRelocation::set_at_relocate_end(bool success) {
1116 _success = success;
1117 }
1118
1119 void ZStatRelocation::print() {
1120 if (_success) {
1121 log_info(gc, reloc)("Relocation: Successful, " SIZE_FORMAT "M relocated", _relocating / M);
1122 } else {
1123 log_info(gc, reloc)("Relocation: Incomplete");
1124 }
1125 }
1126
1127 //
1128 // Stat nmethods
1129 //
1130 void ZStatNMethods::print() {
1131 log_info(gc, nmethod)("NMethods: " SIZE_FORMAT " registered, " SIZE_FORMAT " unregistered",
1132 ZNMethodTable::registered_nmethods(),
1133 ZNMethodTable::unregistered_nmethods());
1134 }
1135
1136 //
1137 // Stat metaspace
1138 //
1139 void ZStatMetaspace::print() {
1140 log_info(gc, metaspace)("Metaspace: "
1141 SIZE_FORMAT "M used, " SIZE_FORMAT "M capacity, "
1142 SIZE_FORMAT "M committed, " SIZE_FORMAT "M reserved",
1143 MetaspaceUtils::used_bytes() / M,
1144 MetaspaceUtils::capacity_bytes() / M,
1145 MetaspaceUtils::committed_bytes() / M,
1146 MetaspaceUtils::reserved_bytes() / M);
1147 }
1148
1149 //
1150 // Stat references
1151 //
1152 ZStatReferences::ZCount ZStatReferences::_soft;
1153 ZStatReferences::ZCount ZStatReferences::_weak;
1154 ZStatReferences::ZCount ZStatReferences::_final;
1155 ZStatReferences::ZCount ZStatReferences::_phantom;
1156
1157 void ZStatReferences::set(ZCount* count, size_t encountered, size_t discovered, size_t enqueued) {
1158 count->encountered = encountered;
1159 count->discovered = discovered;
1160 count->enqueued = enqueued;
1161 }
1162
1163 void ZStatReferences::set_soft(size_t encountered, size_t discovered, size_t enqueued) {
1164 set(&_soft, encountered, discovered, enqueued);
1165 }
1166
1167 void ZStatReferences::set_weak(size_t encountered, size_t discovered, size_t enqueued) {
1168 set(&_weak, encountered, discovered, enqueued);
1169 }
1170
1171 void ZStatReferences::set_final(size_t encountered, size_t discovered, size_t enqueued) {
1172 set(&_final, encountered, discovered, enqueued);
1173 }
1174
1175 void ZStatReferences::set_phantom(size_t encountered, size_t discovered, size_t enqueued) {
1176 set(&_phantom, encountered, discovered, enqueued);
1177 }
1178
1179 void ZStatReferences::print(const char* name, const ZStatReferences::ZCount& ref) {
1180 log_info(gc, ref)("%s: "
1181 SIZE_FORMAT " encountered, "
1182 SIZE_FORMAT " discovered, "
1183 SIZE_FORMAT " enqueued",
1184 name,
1185 ref.encountered,
1186 ref.discovered,
1187 ref.enqueued);
1188 }
1189
1190 void ZStatReferences::print() {
1191 print("Soft", _soft);
1192 print("Weak", _weak);
1193 print("Final", _final);
1194 print("Phantom", _phantom);
1195 }
1196
1197 //
1198 // Stat heap
1199 //
1200 ZStatHeap::ZAtInitialize ZStatHeap::_at_initialize;
1201 ZStatHeap::ZAtMarkStart ZStatHeap::_at_mark_start;
1202 ZStatHeap::ZAtMarkEnd ZStatHeap::_at_mark_end;
1203 ZStatHeap::ZAtRelocateStart ZStatHeap::_at_relocate_start;
1204 ZStatHeap::ZAtRelocateEnd ZStatHeap::_at_relocate_end;
1205
1206 #define ZSIZE_NA "%9s", "-"
1207 #define ZSIZE_ARGS(size) SIZE_FORMAT_W(8) "M (%.0lf%%)", \
1208 ((size) / M), (percent_of(size, _at_initialize.max_capacity))
1209
1210 size_t ZStatHeap::available(size_t used) {
1211 return _at_initialize.max_capacity - used;
1212 }
1213
1214 size_t ZStatHeap::reserve(size_t used) {
1215 return MIN2(_at_initialize.max_reserve, available(used));
1216 }
1217
1218 size_t ZStatHeap::free(size_t used) {
1219 return available(used) - reserve(used);
1220 }
1221
1222 void ZStatHeap::set_at_initialize(size_t max_capacity,
1223 size_t max_reserve) {
1224 _at_initialize.max_capacity = max_capacity;
1225 _at_initialize.max_reserve = max_reserve;
1226 }
1227
1228 void ZStatHeap::set_at_mark_start(size_t capacity,
1229 size_t used) {
1230 _at_mark_start.capacity = capacity;
1231 _at_mark_start.reserve = reserve(used);
1232 _at_mark_start.used = used;
1233 _at_mark_start.free = free(used);
1234 }
1235
1236 void ZStatHeap::set_at_mark_end(size_t capacity,
1237 size_t allocated,
1238 size_t used) {
1239 _at_mark_end.capacity = capacity;
1240 _at_mark_end.reserve = reserve(used);
1241 _at_mark_end.allocated = allocated;
1242 _at_mark_end.used = used;
1243 _at_mark_end.free = free(used);
1244 }
1245
1246 void ZStatHeap::set_at_select_relocation_set(size_t live,
1247 size_t garbage,
1248 size_t reclaimed) {
1249 _at_mark_end.live = live;
1250 _at_mark_end.garbage = garbage;
1251
1252 _at_relocate_start.garbage = garbage - reclaimed;
1253 _at_relocate_start.reclaimed = reclaimed;
1254 }
1255
1256 void ZStatHeap::set_at_relocate_start(size_t capacity,
1257 size_t allocated,
1258 size_t used) {
1259 _at_relocate_start.capacity = capacity;
1260 _at_relocate_start.reserve = reserve(used);
1261 _at_relocate_start.allocated = allocated;
1262 _at_relocate_start.used = used;
1263 _at_relocate_start.free = free(used);
1264 }
1265
1266 void ZStatHeap::set_at_relocate_end(size_t capacity,
1267 size_t allocated,
1268 size_t reclaimed,
1269 size_t used,
1270 size_t used_high,
1271 size_t used_low) {
1272 _at_relocate_end.capacity = capacity;
1273 _at_relocate_end.capacity_high = capacity;
1274 _at_relocate_end.capacity_low = _at_mark_start.capacity;
1275 _at_relocate_end.reserve = reserve(used);
1276 _at_relocate_end.reserve_high = reserve(used_low);
1277 _at_relocate_end.reserve_low = reserve(used_high);
1278 _at_relocate_end.garbage = _at_mark_end.garbage - reclaimed;
1279 _at_relocate_end.allocated = allocated;
1280 _at_relocate_end.reclaimed = reclaimed;
1281 _at_relocate_end.used = used;
1282 _at_relocate_end.used_high = used_high;
1283 _at_relocate_end.used_low = used_low;
1284 _at_relocate_end.free = free(used);
1285 _at_relocate_end.free_high = free(used_low);
1286 _at_relocate_end.free_low = free(used_high);
1287 }
1288
1289 size_t ZStatHeap::max_capacity() {
1290 return _at_initialize.max_capacity;
1291 }
1292
1293 size_t ZStatHeap::used_at_mark_start() {
1294 return _at_mark_start.used;
1295 }
1296
1297 size_t ZStatHeap::used_at_relocate_end() {
1298 return _at_relocate_end.used;
1299 }
1300
1301 void ZStatHeap::print() {
1302 ZStatTablePrinter table(10, 18);
1303 log_info(gc, heap)("%s", table()
1304 .fill()
1305 .center("Mark Start")
1306 .center("Mark End")
1307 .center("Relocate Start")
1308 .center("Relocate End")
1309 .center("High")
1310 .center("Low")
1311 .end());
1312 log_info(gc, heap)("%s", table()
1313 .right("Capacity:")
1314 .left(ZSIZE_ARGS(_at_mark_start.capacity))
1315 .left(ZSIZE_ARGS(_at_mark_end.capacity))
1316 .left(ZSIZE_ARGS(_at_relocate_start.capacity))
1317 .left(ZSIZE_ARGS(_at_relocate_end.capacity))
1318 .left(ZSIZE_ARGS(_at_relocate_end.capacity_high))
1319 .left(ZSIZE_ARGS(_at_relocate_end.capacity_low))
1320 .end());
1321 log_info(gc, heap)("%s", table()
1322 .right("Reserve:")
1323 .left(ZSIZE_ARGS(_at_mark_start.reserve))
1324 .left(ZSIZE_ARGS(_at_mark_end.reserve))
1325 .left(ZSIZE_ARGS(_at_relocate_start.reserve))
1326 .left(ZSIZE_ARGS(_at_relocate_end.reserve))
1327 .left(ZSIZE_ARGS(_at_relocate_end.reserve_high))
1328 .left(ZSIZE_ARGS(_at_relocate_end.reserve_low))
1329 .end());
1330 log_info(gc, heap)("%s", table()
1331 .right("Free:")
1332 .left(ZSIZE_ARGS(_at_mark_start.free))
1333 .left(ZSIZE_ARGS(_at_mark_end.free))
1334 .left(ZSIZE_ARGS(_at_relocate_start.free))
1335 .left(ZSIZE_ARGS(_at_relocate_end.free))
1336 .left(ZSIZE_ARGS(_at_relocate_end.free_high))
1337 .left(ZSIZE_ARGS(_at_relocate_end.free_low))
1338 .end());
1339 log_info(gc, heap)("%s", table()
1340 .right("Used:")
1341 .left(ZSIZE_ARGS(_at_mark_start.used))
1342 .left(ZSIZE_ARGS(_at_mark_end.used))
1343 .left(ZSIZE_ARGS(_at_relocate_start.used))
1344 .left(ZSIZE_ARGS(_at_relocate_end.used))
1345 .left(ZSIZE_ARGS(_at_relocate_end.used_high))
1346 .left(ZSIZE_ARGS(_at_relocate_end.used_low))
1347 .end());
1348 log_info(gc, heap)("%s", table()
1349 .right("Live:")
1350 .left(ZSIZE_NA)
1351 .left(ZSIZE_ARGS(_at_mark_end.live))
1352 .left(ZSIZE_ARGS(_at_mark_end.live /* Same as at mark end */))
1353 .left(ZSIZE_ARGS(_at_mark_end.live /* Same as at mark end */))
1354 .left(ZSIZE_NA)
1355 .left(ZSIZE_NA)
1356 .end());
1357 log_info(gc, heap)("%s", table()
1358 .right("Allocated:")
1359 .left(ZSIZE_NA)
1360 .left(ZSIZE_ARGS(_at_mark_end.allocated))
1361 .left(ZSIZE_ARGS(_at_relocate_start.allocated))
1362 .left(ZSIZE_ARGS(_at_relocate_end.allocated))
1363 .left(ZSIZE_NA)
1364 .left(ZSIZE_NA)
1365 .end());
1366 log_info(gc, heap)("%s", table()
1367 .right("Garbage:")
1368 .left(ZSIZE_NA)
1369 .left(ZSIZE_ARGS(_at_mark_end.garbage))
1370 .left(ZSIZE_ARGS(_at_relocate_start.garbage))
1371 .left(ZSIZE_ARGS(_at_relocate_end.garbage))
1372 .left(ZSIZE_NA)
1373 .left(ZSIZE_NA)
1374 .end());
1375 log_info(gc, heap)("%s", table()
1376 .right("Reclaimed:")
1377 .left(ZSIZE_NA)
1378 .left(ZSIZE_NA)
1379 .left(ZSIZE_ARGS(_at_relocate_start.reclaimed))
1380 .left(ZSIZE_ARGS(_at_relocate_end.reclaimed))
1381 .left(ZSIZE_NA)
1382 .left(ZSIZE_NA)
1383 .end());
1384 }