1 /* 2 * Copyright (c) 2012, 2015, 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 25 #ifndef SHARE_VM_GC_SHARED_GCTRACETIME_HPP 26 #define SHARE_VM_GC_SHARED_GCTRACETIME_HPP 27 28 #include "gc/shared/collectedHeap.hpp" 29 #include "gc/shared/gcTimer.hpp" 30 #include "gc/shared/gcTrace.hpp" 31 #include "logging/log.hpp" 32 #include "memory/allocation.hpp" 33 #include "memory/resourceArea.hpp" 34 #include "memory/universe.hpp" 35 #include "prims/jni_md.h" 36 #include "utilities/ticks.hpp" 37 #include "runtime/timer.hpp" 38 #include "utilities/ticks.hpp" 39 40 class GCTraceCPUTime : public StackObj { 41 bool _active; // true if times will be measured and printed 42 double _starting_user_time; // user time at start of measurement 43 double _starting_system_time; // system time at start of measurement 44 double _starting_real_time; // real time at start of measurement 45 public: 46 GCTraceCPUTime(); 47 ~GCTraceCPUTime(); 48 }; 49 50 #define LOG_STOP_TIME_FORMAT "(%.3fs, %.3fs) %.3fms" 51 #define LOG_STOP_HEAP_FORMAT SIZE_FORMAT "M->" SIZE_FORMAT "M(" SIZE_FORMAT "M)" 52 53 template <LogLevelType Level, LogTagType T0, LogTagType T1 = LogTag::__NO_TAG, LogTagType T2 = LogTag::__NO_TAG, LogTagType T3 = LogTag::__NO_TAG, 54 LogTagType T4 = LogTag::__NO_TAG, LogTagType GuardTag = LogTag::__NO_TAG> 55 class GCTraceTimeImpl : public StackObj { 56 private: 57 bool _enabled; 58 Ticks _start_ticks; 59 const char* _title; 60 GCCause::Cause _gc_cause; 61 GCTimer* _timer; 62 size_t _heap_usage_before; 63 64 void log_start(jlong start_counter) { 65 if (Log<LogTag::start, T0, T1, T2, T3>::is_level(Level)) { 66 FormatBuffer<> start_msg("%s", _title); 67 if (_gc_cause != GCCause::_no_gc) { 68 start_msg.append(" (%s)", GCCause::to_string(_gc_cause)); 69 } 70 start_msg.append(" (%.3fs)", TimeHelper::counter_to_seconds(start_counter)); 71 // Make sure to put the "start" tag last in the tag set 72 STATIC_ASSERT(T0 != LogTag::__NO_TAG); // Need some tag to log on. 73 STATIC_ASSERT(T4 == LogTag::__NO_TAG); // Need to leave at least the last tag for the "start" tag in log_start() 74 if (T1 == LogTag::__NO_TAG) { 75 Log<T0, LogTag::start>::template write<Level>("%s", start_msg.buffer()); 76 } else if (T2 == LogTag::__NO_TAG) { 77 Log<T0, T1, LogTag::start>::template write<Level>("%s", start_msg.buffer()); 78 } else if (T3 == LogTag::__NO_TAG) { 79 Log<T0, T1, T2, LogTag::start>::template write<Level>("%s", start_msg.buffer()); 80 } else { 81 Log<T0, T1, T2, T3, LogTag::start>::template write<Level>("%s", start_msg.buffer()); 82 } 83 } 84 } 85 86 void log_stop(jlong start_counter, jlong stop_counter) { 87 double duration_in_ms = TimeHelper::counter_to_millis(stop_counter - start_counter); 88 double start_time_in_secs = TimeHelper::counter_to_seconds(start_counter); 89 double stop_time_in_secs = TimeHelper::counter_to_seconds(stop_counter); 90 FormatBuffer<> stop_msg("%s", _title); 91 if (_gc_cause != GCCause::_no_gc) { 92 stop_msg.append(" (%s)", GCCause::to_string(_gc_cause)); 93 } 94 if (_heap_usage_before == SIZE_MAX) { 95 Log<T0, T1, T2, T3, T4>::template write<Level>("%s " LOG_STOP_TIME_FORMAT, 96 stop_msg.buffer(), start_time_in_secs, stop_time_in_secs, duration_in_ms); 97 } else { 98 CollectedHeap* heap = Universe::heap(); 99 size_t used_before_m = _heap_usage_before / M; 100 size_t used_m = heap->used() / M; 101 size_t capacity_m = heap->capacity() / M; 102 Log<T0, T1, T2, T3, T4>::template write<Level>("%s " LOG_STOP_HEAP_FORMAT " " LOG_STOP_TIME_FORMAT, 103 stop_msg.buffer(), used_before_m, used_m, capacity_m, start_time_in_secs, stop_time_in_secs, duration_in_ms); 104 } 105 } 106 107 void time_stamp(Ticks& ticks) { 108 if (_enabled || _timer != NULL) { 109 ticks.stamp(); 110 } 111 } 112 113 public: 114 GCTraceTimeImpl(const char* title, GCTimer* timer = NULL, GCCause::Cause gc_cause = GCCause::_no_gc, bool log_heap_usage = false) : 115 _enabled(Log<T0, T1, T2, T3, T4, GuardTag>::is_level(Level)), 116 _start_ticks(), 117 _heap_usage_before(SIZE_MAX), 118 _title(title), 119 _gc_cause(gc_cause), 120 _timer(timer) { 121 122 time_stamp(_start_ticks); 123 if (_enabled) { 124 if (log_heap_usage) { 125 _heap_usage_before = Universe::heap()->used(); 126 } 127 log_start(_start_ticks.value()); 128 } 129 if (_timer != NULL) { 130 _timer->register_gc_phase_start(_title, _start_ticks); 131 } 132 } 133 134 ~GCTraceTimeImpl() { 135 Ticks stop_ticks; 136 time_stamp(stop_ticks); 137 if (_enabled) { 138 log_stop(_start_ticks.value(), stop_ticks.value()); 139 } 140 if (_timer != NULL) { 141 _timer->register_gc_phase_end(stop_ticks); 142 } 143 } 144 }; 145 146 // Similar to GCTraceTimeImpl but is intended for concurrent phase logging, 147 // which is a bit simpler and should always print the start line, i.e. not add the "start" tag. 148 template <LogLevelType Level, LogTagType T0, LogTagType T1 = LogTag::__NO_TAG, LogTagType T2 = LogTag::__NO_TAG, LogTagType T3 = LogTag::__NO_TAG, 149 LogTagType T4 = LogTag::__NO_TAG, LogTagType GuardTag = LogTag::__NO_TAG> 150 class GCTraceConcTimeImpl : public StackObj { 151 private: 152 bool _enabled; 153 jlong _start_time; 154 const char* _title; 155 public: 156 GCTraceConcTimeImpl(const char* title) : 157 _enabled(Log<T0, T1, T2, T3, T4, GuardTag>::is_level(Level)), _start_time(os::elapsed_counter()), _title(title) { 158 if (_enabled) { 159 Log<T0, T1, T2, T3, T4>::template write<Level>("%s (%.3fs)", _title, TimeHelper::counter_to_seconds(_start_time)); 160 } 161 } 162 163 ~GCTraceConcTimeImpl() { 164 if (_enabled) { 165 jlong stop_time = os::elapsed_counter(); 166 Log<T0, T1, T2, T3, T4>::template write<Level>("%s " LOG_STOP_TIME_FORMAT, 167 _title, 168 TimeHelper::counter_to_seconds(_start_time), 169 TimeHelper::counter_to_seconds(stop_time), 170 TimeHelper::counter_to_seconds(stop_time - _start_time)); 171 } 172 } 173 174 jlong start_time() { return _start_time; } 175 }; 176 177 178 #define GCTraceTime(Level, ...) GCTraceTimeImpl<LogLevel::Level, LOG_TAGS(__VA_ARGS__)> 179 #define GCTraceConcTime(Level, ...) GCTraceConcTimeImpl<LogLevel::Level, LOG_TAGS(__VA_ARGS__)> 180 181 #endif // SHARE_VM_GC_SHARED_GCTRACETIME_HPP