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 uint64_t ZStatPhaseCycle::_ncycles = 0;
609 Ticks ZStatPhaseCycle::_end_of_last;
610 NumberSeq ZStatPhaseCycle::_duration(0.3 /* alpha */);
611
612 ZStatPhaseCycle::ZStatPhaseCycle(const char* name) :
613 ZStatPhase("Collector", name) {}
614
615 uint64_t ZStatPhaseCycle::ncycles() {
616 return _ncycles;
617 }
618
619 const AbsSeq& ZStatPhaseCycle::duration() {
620 return _duration;
621 }
622
623 double ZStatPhaseCycle::time_since_last() {
624 if (_ncycles == 0) {
625 // Return time since VM start-up
626 return os::elapsedTime();
627 }
628
629 const Ticks now = Ticks::now();
630 const Tickspan time_since_last = now - _end_of_last;
631 return TicksToTimeHelper::seconds(time_since_last);
632 }
633
634 void ZStatPhaseCycle::register_start(const Ticks& start) const {
635 timer()->register_gc_start(start);
636
637 ZTracer::tracer()->report_gc_start(ZCollectedHeap::heap()->gc_cause(), start);
638
639 ZCollectedHeap::heap()->print_heap_before_gc();
640 ZCollectedHeap::heap()->trace_heap_before_gc(ZTracer::tracer());
641
642 log_info(gc, start)("Garbage Collection (%s)",
643 GCCause::to_string(ZCollectedHeap::heap()->gc_cause()));
644 }
645
646 #define ZUSED_FMT SIZE_FORMAT "M(%.0lf%%)"
647 #define ZUSED_ARGS(size, max_capacity) ((size) / M), (percent_of<size_t>(size, max_capacity))
648
649 void ZStatPhaseCycle::register_end(const Ticks& start, const Ticks& end) const {
650 timer()->register_gc_end(end);
651
652 ZCollectedHeap::heap()->print_heap_after_gc();
653 ZCollectedHeap::heap()->trace_heap_after_gc(ZTracer::tracer());
654
655 ZTracer::tracer()->report_gc_end(end, timer()->time_partitions());
656
657 const Tickspan duration = end - start;
658 ZStatSample(_sampler, duration.value());
659
660 _duration.add(TicksToTimeHelper::seconds(duration));
661 _end_of_last = end;
662 _ncycles++;
663
664 ZStatLoad::print();
665 ZStatMMU::print();
666 ZStatMark::print();
667 ZStatRelocation::print();
668 ZStatNMethods::print();
669 ZStatReferences::print();
670 ZStatHeap::print();
671
672 log_info(gc)("Garbage Collection (%s) " ZUSED_FMT "->" ZUSED_FMT,
673 GCCause::to_string(ZCollectedHeap::heap()->gc_cause()),
674 ZUSED_ARGS(ZStatHeap::used_at_mark_start(), ZStatHeap::max_capacity()),
675 ZUSED_ARGS(ZStatHeap::used_at_relocate_end(), ZStatHeap::max_capacity()));
676 }
677
678 Tickspan ZStatPhasePause::_max;
679
680 ZStatPhasePause::ZStatPhasePause(const char* name) :
681 ZStatPhase("Phase", name) {}
682
683 const Tickspan& ZStatPhasePause::max() {
684 return _max;
685 }
686
687 void ZStatPhasePause::register_start(const Ticks& start) const {
688 timer()->register_gc_pause_start(name(), start);
689
690 LogTarget(Debug, gc, phases, start) log;
691 log_start(log);
692 }
693
694 void ZStatPhasePause::register_end(const Ticks& start, const Ticks& end) const {
695 timer()->register_gc_pause_end(end);
696
697 const Tickspan duration = end - start;
698 ZStatSample(_sampler, duration.value());
699
700 // Track max pause time
701 if (_max < duration) {
702 _max = duration;
703 }
704
705 // Track minimum mutator utilization
706 ZStatMMU::register_pause(start, end);
707
708 LogTarget(Info, gc, phases) log;
709 log_end(log, duration);
710 }
711
712 ZStatPhaseConcurrent::ZStatPhaseConcurrent(const char* name) :
713 ZStatPhase("Phase", name) {}
714
715 void ZStatPhaseConcurrent::register_start(const Ticks& start) const {
716 timer()->register_gc_concurrent_start(name(), start);
717
718 LogTarget(Debug, gc, phases, start) log;
719 log_start(log);
720 }
721
722 void ZStatPhaseConcurrent::register_end(const Ticks& start, const Ticks& end) const {
723 timer()->register_gc_concurrent_end(end);
724
725 const Tickspan duration = end - start;
726 ZStatSample(_sampler, duration.value());
727
728 LogTarget(Info, gc, phases) log;
729 log_end(log, duration);
730 }
731
732 ZStatSubPhase::ZStatSubPhase(const char* name) :
733 ZStatPhase("Subphase", name) {}
734
735 void ZStatSubPhase::register_start(const Ticks& start) const {
736 LogTarget(Debug, gc, phases, start) log;
737 log_start(log, true /* thread */);
738 }
739
740 void ZStatSubPhase::register_end(const Ticks& start, const Ticks& end) const {
741 ZTracer::tracer()->report_thread_phase(*this, start, end);
742
743 const Tickspan duration = end - start;
744 ZStatSample(_sampler, duration.value());
745
746 LogTarget(Debug, gc, phases) log;
747 log_end(log, duration, true /* thread */);
748 }
749
750 ZStatCriticalPhase::ZStatCriticalPhase(const char* name, bool verbose) :
751 ZStatPhase("Critical", name),
752 _counter("Critical", name, ZStatUnitOpsPerSecond),
753 _verbose(verbose) {}
754
755 void ZStatCriticalPhase::register_start(const Ticks& start) const {
756 LogTarget(Debug, gc, start) log;
757 log_start(log, true /* thread */);
758 }
759
760 void ZStatCriticalPhase::register_end(const Ticks& start, const Ticks& end) const {
761 ZTracer::tracer()->report_thread_phase(*this, start, end);
762
763 const Tickspan duration = end - start;
764 ZStatSample(_sampler, duration.value());
765 ZStatInc(_counter);
766
767 if (_verbose) {
768 LogTarget(Info, gc) log;
769 log_end(log, duration, true /* thread */);
770 } else {
771 LogTarget(Debug, gc) log;
772 log_end(log, duration, true /* thread */);
773 }
774 }
775
776 //
777 // Stat sample/inc
778 //
779 void ZStatSample(const ZStatSampler& sampler, uint64_t value, bool trace) {
780 ZStatSamplerData* const cpu_data = sampler.get();
781 Atomic::add(1u, &cpu_data->_nsamples);
782 Atomic::add(value, &cpu_data->_sum);
783
784 uint64_t max = cpu_data->_max;
785 for (;;) {
786 if (max >= value) {
787 // Not max
788 break;
789 }
790
791 const uint64_t new_max = value;
792 const uint64_t prev_max = Atomic::cmpxchg(new_max, &cpu_data->_max, max);
793 if (prev_max == max) {
794 // Success
795 break;
796 }
797
798 // Retry
799 max = prev_max;
800 }
801
802 if (trace) {
803 ZTracer::tracer()->report_stat_sampler(sampler, value);
804 }
805 }
806
807 void ZStatInc(const ZStatCounter& counter, uint64_t increment, bool trace) {
808 ZStatCounterData* const cpu_data = counter.get();
809 const uint64_t value = Atomic::add(increment, &cpu_data->_counter);
810
811 if (trace) {
812 ZTracer::tracer()->report_stat_counter(counter, increment, value);
813 }
814 }
815
816 void ZStatInc(const ZStatUnsampledCounter& counter, uint64_t increment) {
817 ZStatCounterData* const cpu_data = counter.get();
818 Atomic::add(increment, &cpu_data->_counter);
819 }
820
821 //
822 // Stat allocation rate
823 //
824 const ZStatUnsampledCounter ZStatAllocRate::_counter("Allocation Rate");
825 TruncatedSeq ZStatAllocRate::_rate(ZStatAllocRate::sample_window_sec * ZStatAllocRate::sample_hz);
826 TruncatedSeq ZStatAllocRate::_rate_avg(ZStatAllocRate::sample_window_sec * ZStatAllocRate::sample_hz);
827
828 const ZStatUnsampledCounter& ZStatAllocRate::counter() {
829 return _counter;
830 }
831
832 uint64_t ZStatAllocRate::sample_and_reset() {
833 const ZStatCounterData bytes_per_sample = _counter.collect_and_reset();
834 const uint64_t bytes_per_second = bytes_per_sample._counter * sample_hz;
835
836 _rate.add(bytes_per_second);
837 _rate_avg.add(_rate.avg());
838
839 return bytes_per_second;
840 }
841
842 double ZStatAllocRate::avg() {
843 return _rate.avg();
844 }
845
846 double ZStatAllocRate::avg_sd() {
847 return _rate_avg.sd();
848 }
849
850 //
851 // Stat thread
852 //
853 ZStat::ZStat() :
854 _metronome(sample_hz) {
855 set_name("ZStat");
856 create_and_start();
857 }
858
859 void ZStat::sample_and_collect(ZStatSamplerHistory* history) const {
860 // Sample counters
861 for (const ZStatCounter* counter = ZStatCounter::first(); counter != NULL; counter = counter->next()) {
862 counter->sample_and_reset();
863 }
864
865 // Collect samples
866 for (const ZStatSampler* sampler = ZStatSampler::first(); sampler != NULL; sampler = sampler->next()) {
867 ZStatSamplerHistory& sampler_history = history[sampler->id()];
868 sampler_history.add(sampler->collect_and_reset());
869 }
870 }
871
872 bool ZStat::should_print(LogTargetHandle log) const {
873 return log.is_enabled() && (_metronome.nticks() % ZStatisticsInterval == 0);
874 }
875
876 void ZStat::print(LogTargetHandle log, const ZStatSamplerHistory* history) const {
877 // Print
878 log.print("=== Garbage Collection Statistics =======================================================================================================================");
879 log.print(" Last 10s Last 10m Last 10h Total");
880 log.print(" Avg / Max Avg / Max Avg / Max Avg / Max");
881
882 for (const ZStatSampler* sampler = ZStatSampler::first(); sampler != NULL; sampler = sampler->next()) {
883 const ZStatSamplerHistory& sampler_history = history[sampler->id()];
884 const ZStatUnitPrinter printer = sampler->printer();
885 printer(log, *sampler, sampler_history);
886 }
887
888 log.print("=========================================================================================================================================================");
889 }
890
891 void ZStat::run_service() {
892 ZStatSamplerHistory* const history = new ZStatSamplerHistory[ZStatSampler::count()];
893 LogTarget(Info, gc, stats) log;
894
895 // Main loop
896 while (_metronome.wait_for_tick()) {
897 sample_and_collect(history);
898 if (should_print(log)) {
899 print(log, history);
900 }
901 }
902
903 delete [] history;
904 }
905
906 void ZStat::stop_service() {
907 _metronome.stop();
908 }
909
910 //
911 // Stat table
912 //
913 class ZStatTablePrinter {
914 private:
915 static const size_t _buffer_size = 256;
916
917 const size_t _column0_width;
918 const size_t _columnN_width;
919 char _buffer[_buffer_size];
920
921 public:
922 class ZColumn {
923 private:
924 char* const _buffer;
925 const size_t _position;
926 const size_t _width;
927 const size_t _width_next;
928
929 ZColumn next() const {
930 // Insert space between columns
931 _buffer[_position + _width] = ' ';
932 return ZColumn(_buffer, _position + _width + 1, _width_next, _width_next);
933 }
934
935 size_t print(size_t position, const char* fmt, va_list va) {
936 const int res = jio_vsnprintf(_buffer + position, _buffer_size - position, fmt, va);
937 if (res < 0) {
938 return 0;
939 }
940
941 return (size_t)res;
942 }
943
944 public:
945 ZColumn(char* buffer, size_t position, size_t width, size_t width_next) :
946 _buffer(buffer),
947 _position(position),
948 _width(width),
949 _width_next(width_next) {}
950
951 ZColumn left(const char* fmt, ...) ATTRIBUTE_PRINTF(2, 3) {
952 va_list va;
953
954 va_start(va, fmt);
955 const size_t written = print(_position, fmt, va);
956 va_end(va);
957
958 if (written < _width) {
959 // Fill empty space
960 memset(_buffer + _position + written, ' ', _width - written);
961 }
962
963 return next();
964 }
965
966 ZColumn right(const char* fmt, ...) ATTRIBUTE_PRINTF(2, 3) {
967 va_list va;
968
969 va_start(va, fmt);
970 const size_t written = print(_position, fmt, va);
971 va_end(va);
972
973 if (written > _width) {
974 // Line too long
975 return fill('?');
976 }
977
978 if (written < _width) {
979 // Short line, move all to right
980 memmove(_buffer + _position + _width - written, _buffer + _position, written);
981
982 // Fill empty space
983 memset(_buffer + _position, ' ', _width - written);
984 }
985
986 return next();
987 }
988
989 ZColumn center(const char* fmt, ...) ATTRIBUTE_PRINTF(2, 3) {
990 va_list va;
991
992 va_start(va, fmt);
993 const size_t written = print(_position, fmt, va);
994 va_end(va);
995
996 if (written > _width) {
997 // Line too long
998 return fill('?');
999 }
1000
1001 if (written < _width) {
1002 // Short line, move all to center
1003 const size_t start_space = (_width - written) / 2;
1004 const size_t end_space = _width - written - start_space;
1005 memmove(_buffer + _position + start_space, _buffer + _position, written);
1006
1007 // Fill empty spaces
1008 memset(_buffer + _position, ' ', start_space);
1009 memset(_buffer + _position + start_space + written, ' ', end_space);
1010 }
1011
1012 return next();
1013 }
1014
1015 ZColumn fill(char filler = ' ') {
1016 memset(_buffer + _position, filler, _width);
1017 return next();
1018 }
1019
1020 const char* end() {
1021 _buffer[_position] = '\0';
1022 return _buffer;
1023 }
1024 };
1025
1026 public:
1027 ZStatTablePrinter(size_t column0_width, size_t columnN_width) :
1028 _column0_width(column0_width),
1029 _columnN_width(columnN_width) {}
1030
1031 ZColumn operator()() {
1032 return ZColumn(_buffer, 0, _column0_width, _columnN_width);
1033 }
1034 };
1035
1036 //
1037 // Stat load
1038 //
1039 void ZStatLoad::print() {
1040 double loadavg[3] = {};
1041 os::loadavg(loadavg, ARRAY_SIZE(loadavg));
1042 log_info(gc, load)("Load: %.2f/%.2f/%.2f", loadavg[0], loadavg[1], loadavg[2]);
1043 }
1044
1045 //
1046 // Stat mark
1047 //
1048 size_t ZStatMark::_nstripes;
1049 size_t ZStatMark::_nproactiveflush;
1050 size_t ZStatMark::_nterminateflush;
1051 size_t ZStatMark::_ntrycomplete;
1052 size_t ZStatMark::_ncontinue;
1053
1054 void ZStatMark::print() {
1055 log_info(gc, marking)("Mark: "
1056 SIZE_FORMAT " stripe(s), "
1057 SIZE_FORMAT " proactive flush(es), "
1058 SIZE_FORMAT " terminate flush(es), "
1059 SIZE_FORMAT " completion(s), "
1060 SIZE_FORMAT " continuation(s) ",
1061 _nstripes,
1062 _nproactiveflush,
1063 _nterminateflush,
1064 _ntrycomplete,
1065 _ncontinue);
1066 }
1067
1068 //
1069 // Stat relocation
1070 //
1071 size_t ZStatRelocation::_relocating;
1072 bool ZStatRelocation::_success;
1073
1074 void ZStatRelocation::print() {
1075 if (_success) {
1076 log_info(gc, reloc)("Relocation: Successful, " SIZE_FORMAT "M relocated", _relocating / M);
1077 } else {
1078 log_info(gc, reloc)("Relocation: Incomplete");
1079 }
1080 }
1081
1082 //
1083 // Stat nmethods
1084 //
1085 void ZStatNMethods::print() {
1086 log_info(gc, nmethod)("NMethods: " SIZE_FORMAT " registered, " SIZE_FORMAT " unregistered",
1087 ZNMethodTable::registered_nmethods(),
1088 ZNMethodTable::unregistered_nmethods());
1089 }
1090
1091 //
1092 // Stat references
1093 //
1094 ZStatReferences::ZCount ZStatReferences::_soft;
1095 ZStatReferences::ZCount ZStatReferences::_weak;
1096 ZStatReferences::ZCount ZStatReferences::_final;
1097 ZStatReferences::ZCount ZStatReferences::_phantom;
1098
1099 void ZStatReferences::print(const char* name, const ZStatReferences::ZCount& ref) {
1100 log_info(gc, ref)("%s: "
1101 SIZE_FORMAT " encountered, "
1102 SIZE_FORMAT " discovered, "
1103 SIZE_FORMAT " dropped, "
1104 SIZE_FORMAT " enqueued",
1105 name,
1106 ref.encountered,
1107 ref.discovered,
1108 ref.dropped,
1109 ref.enqueued);
1110 }
1111
1112 void ZStatReferences::print() {
1113 print("Soft", _soft);
1114 print("Weak", _weak);
1115 print("Final", _final);
1116 print("Phantom", _phantom);
1117 }
1118
1119 //
1120 // Stat heap
1121 //
1122 ZStatHeap::ZAtInitialize ZStatHeap::_at_initialize;
1123 ZStatHeap::ZAtMarkStart ZStatHeap::_at_mark_start;
1124 ZStatHeap::ZAtMarkEnd ZStatHeap::_at_mark_end;
1125 ZStatHeap::ZAtRelocateStart ZStatHeap::_at_relocate_start;
1126 ZStatHeap::ZAtRelocateEnd ZStatHeap::_at_relocate_end;
1127
1128 #define ZSIZE_NA "%9s", "-"
1129 #define ZSIZE_ARGS(size) SIZE_FORMAT_W(8) "M (%.0lf%%)", \
1130 ((size) / M), (percent_of<size_t>(size, _at_initialize.max_capacity))
1131
1132 void ZStatHeap::print() {
1133 ZStatTablePrinter table(10, 18);
1134 log_info(gc, heap)("%s", table()
1135 .fill()
1136 .center("Mark Start")
1137 .center("Mark End")
1138 .center("Relocate Start")
1139 .center("Relocate End")
1140 .center("High")
1141 .center("Low")
1142 .end());
1143 log_info(gc, heap)("%s", table()
1144 .right("Capacity:")
1145 .left(ZSIZE_ARGS(_at_mark_start.capacity))
1146 .left(ZSIZE_ARGS(_at_mark_end.capacity))
1147 .left(ZSIZE_ARGS(_at_relocate_start.capacity))
1148 .left(ZSIZE_ARGS(_at_relocate_end.capacity))
1149 .left(ZSIZE_ARGS(_at_relocate_end.capacity_high))
1150 .left(ZSIZE_ARGS(_at_relocate_end.capacity_low))
1151 .end());
1152 log_info(gc, heap)("%s", table()
1153 .right("Reserve:")
1154 .left(ZSIZE_ARGS(_at_mark_start.reserve))
1155 .left(ZSIZE_ARGS(_at_mark_end.reserve))
1156 .left(ZSIZE_ARGS(_at_relocate_start.reserve))
1157 .left(ZSIZE_ARGS(_at_relocate_end.reserve))
1158 .left(ZSIZE_ARGS(_at_relocate_end.reserve_high))
1159 .left(ZSIZE_ARGS(_at_relocate_end.reserve_low))
1160 .end());
1161 log_info(gc, heap)("%s", table()
1162 .right("Free:")
1163 .left(ZSIZE_ARGS(_at_mark_start.free))
1164 .left(ZSIZE_ARGS(_at_mark_end.free))
1165 .left(ZSIZE_ARGS(_at_relocate_start.free))
1166 .left(ZSIZE_ARGS(_at_relocate_end.free))
1167 .left(ZSIZE_ARGS(_at_relocate_end.free_high))
1168 .left(ZSIZE_ARGS(_at_relocate_end.free_low))
1169 .end());
1170 log_info(gc, heap)("%s", table()
1171 .right("Used:")
1172 .left(ZSIZE_ARGS(_at_mark_start.used))
1173 .left(ZSIZE_ARGS(_at_mark_end.used))
1174 .left(ZSIZE_ARGS(_at_relocate_start.used))
1175 .left(ZSIZE_ARGS(_at_relocate_end.used))
1176 .left(ZSIZE_ARGS(_at_relocate_end.used_high))
1177 .left(ZSIZE_ARGS(_at_relocate_end.used_low))
1178 .end());
1179 log_info(gc, heap)("%s", table()
1180 .right("Live:")
1181 .left(ZSIZE_NA)
1182 .left(ZSIZE_ARGS(_at_mark_end.live))
1183 .left(ZSIZE_ARGS(_at_mark_end.live /* Same as at mark end */))
1184 .left(ZSIZE_ARGS(_at_mark_end.live /* Same as at mark end */))
1185 .left(ZSIZE_NA)
1186 .left(ZSIZE_NA)
1187 .end());
1188 log_info(gc, heap)("%s", table()
1189 .right("Allocated:")
1190 .left(ZSIZE_NA)
1191 .left(ZSIZE_ARGS(_at_mark_end.allocated))
1192 .left(ZSIZE_ARGS(_at_relocate_start.allocated))
1193 .left(ZSIZE_ARGS(_at_relocate_end.allocated))
1194 .left(ZSIZE_NA)
1195 .left(ZSIZE_NA)
1196 .end());
1197 log_info(gc, heap)("%s", table()
1198 .right("Garbage:")
1199 .left(ZSIZE_NA)
1200 .left(ZSIZE_ARGS(_at_mark_end.garbage))
1201 .left(ZSIZE_ARGS(_at_relocate_start.garbage))
1202 .left(ZSIZE_ARGS(_at_relocate_end.garbage))
1203 .left(ZSIZE_NA)
1204 .left(ZSIZE_NA)
1205 .end());
1206 log_info(gc, heap)("%s", table()
1207 .right("Reclaimed:")
1208 .left(ZSIZE_NA)
1209 .left(ZSIZE_NA)
1210 .left(ZSIZE_ARGS(_at_relocate_start.reclaimed))
1211 .left(ZSIZE_ARGS(_at_relocate_end.reclaimed))
1212 .left(ZSIZE_NA)
1213 .left(ZSIZE_NA)
1214 .end());
1215 }