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() {
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() {
|
588 if (!log.is_enabled()) {
589 return;
590 }
591
592 if (thread) {
593 ResourceMark rm;
594 log.print("%s (%s) %.3fms", name(), Thread::current()->name(), TimeHelper::counter_to_millis(duration.value()));
595 } else {
596 log.print("%s %.3fms", name(), TimeHelper::counter_to_millis(duration.value()));
597 }
598 }
599
600 ConcurrentGCTimer* ZStatPhase::timer() {
601 return &_timer;
602 }
603
604 const char* ZStatPhase::name() const {
605 return _sampler.name();
606 }
607
608 ZStatPhaseCycle::ZStatPhaseCycle(const char* name) :
609 ZStatPhase("Collector", name) {}
610
611 void ZStatPhaseCycle::register_start(const Ticks& start) const {
612 timer()->register_gc_start(start);
613
614 ZTracer::tracer()->report_gc_start(ZCollectedHeap::heap()->gc_cause(), start);
615
616 ZCollectedHeap::heap()->print_heap_before_gc();
617 ZCollectedHeap::heap()->trace_heap_before_gc(ZTracer::tracer());
618
619 log_info(gc, start)("Garbage Collection (%s)",
620 GCCause::to_string(ZCollectedHeap::heap()->gc_cause()));
621 }
622
623 #define ZUSED_FMT SIZE_FORMAT "M(%.0lf%%)"
624 #define ZUSED_ARGS(size, max_capacity) ((size) / M), (percent_of<size_t>(size, max_capacity))
625
626 void ZStatPhaseCycle::register_end(const Ticks& start, const Ticks& end) const {
627 timer()->register_gc_end(end);
628
629 ZCollectedHeap::heap()->print_heap_after_gc();
630 ZCollectedHeap::heap()->trace_heap_after_gc(ZTracer::tracer());
631
632 ZTracer::tracer()->report_gc_end(end, timer()->time_partitions());
633
634 const Tickspan duration = end - start;
635 ZStatSample(_sampler, duration.value());
636
637 ZStatLoad::print();
638 ZStatMMU::print();
639 ZStatMark::print();
640 ZStatRelocation::print();
641 ZStatNMethods::print();
642 ZStatReferences::print();
643 ZStatHeap::print();
644
645 log_info(gc)("Garbage Collection (%s) " ZUSED_FMT "->" ZUSED_FMT,
646 GCCause::to_string(ZCollectedHeap::heap()->gc_cause()),
647 ZUSED_ARGS(ZStatHeap::used_at_mark_start(), ZStatHeap::max_capacity()),
648 ZUSED_ARGS(ZStatHeap::used_at_relocate_end(), ZStatHeap::max_capacity()));
649 }
650
651 Tickspan ZStatPhasePause::_max;
652
653 ZStatPhasePause::ZStatPhasePause(const char* name) :
654 ZStatPhase("Phase", name) {}
655
656 const Tickspan& ZStatPhasePause::max() {
988 ZColumn fill(char filler = ' ') {
989 memset(_buffer + _position, filler, _width);
990 return next();
991 }
992
993 const char* end() {
994 _buffer[_position] = '\0';
995 return _buffer;
996 }
997 };
998
999 public:
1000 ZStatTablePrinter(size_t column0_width, size_t columnN_width) :
1001 _column0_width(column0_width),
1002 _columnN_width(columnN_width) {}
1003
1004 ZColumn operator()() {
1005 return ZColumn(_buffer, 0, _column0_width, _columnN_width);
1006 }
1007 };
1008
1009 //
1010 // Stat cycle
1011 //
1012 uint64_t ZStatCycle::_ncycles = 0;
1013 Ticks ZStatCycle::_start_of_last;
1014 Ticks ZStatCycle::_end_of_last;
1015 NumberSeq ZStatCycle::_duration(0.3 /* alpha */);
1016
1017 void ZStatCycle::at_start() {
1018 _start_of_last = Ticks::now();
1019 }
1020
1021 void ZStatCycle::at_end(double boost_factor) {
1022 _end_of_last = Ticks::now();
1023 _ncycles++;
1024
1025 // Calculate cycle duration. The duration is normalized using the boost
1026 // factor to avoid artificial deflation of the duration when boost mode
1027 // is enabled.
1028 const double duration = TicksToTimeHelper::seconds(_end_of_last - _start_of_last);
1029 const double normalized_duration = duration * boost_factor;
1030 _duration.add(normalized_duration);
1031 }
1032
1033 uint64_t ZStatCycle::ncycles() {
1034 return _ncycles;
1035 }
1036
1037 const AbsSeq& ZStatCycle::duration() {
1038 return _duration;
1039 }
1040
1041 double ZStatCycle::time_since_last() {
1042 if (_ncycles == 0) {
1043 // Return time since VM start-up
1044 return os::elapsedTime();
1045 }
1046
1047 const Ticks now = Ticks::now();
1048 const Tickspan time_since_last = now - _end_of_last;
1049 return TicksToTimeHelper::seconds(time_since_last);
1050 }
1051
1052 //
1053 // Stat load
1054 //
1055 void ZStatLoad::print() {
1056 double loadavg[3] = {};
1057 os::loadavg(loadavg, ARRAY_SIZE(loadavg));
1058 log_info(gc, load)("Load: %.2f/%.2f/%.2f", loadavg[0], loadavg[1], loadavg[2]);
1059 }
1060
1061 //
1062 // Stat mark
1063 //
1064 size_t ZStatMark::_nstripes;
1065 size_t ZStatMark::_nproactiveflush;
1066 size_t ZStatMark::_nterminateflush;
1067 size_t ZStatMark::_ntrycomplete;
1068 size_t ZStatMark::_ncontinue;
1069
1070 void ZStatMark::print() {
|