1 /* 2 * Copyright (c) 2012, 2020, 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_GC_SHARED_GCTRACETIME_INLINE_HPP 26 #define SHARE_GC_SHARED_GCTRACETIME_INLINE_HPP 27 28 #include "gc/shared/collectedHeap.hpp" 29 #include "gc/shared/gcTimer.hpp" 30 #include "gc/shared/gcTrace.hpp" 31 #include "gc/shared/gcTraceTime.hpp" 32 #include "logging/log.hpp" 33 #include "logging/logStream.hpp" 34 #include "memory/universe.hpp" 35 #include "utilities/ticks.hpp" 36 37 #define LOG_STOP_HEAP_FORMAT SIZE_FORMAT "M->" SIZE_FORMAT "M(" SIZE_FORMAT "M)" 38 39 template <typename Handle1, typename Handle2> 40 inline void GCTraceTimeImpl<Handle1, Handle2>::log_start(jlong start_counter) { 41 if (_out_start.is_enabled()) { 42 LogStream out(_out_start); 43 44 out.print("%s", _title); 45 if (_gc_cause != GCCause::_no_gc) { 46 out.print(" (%s)", GCCause::to_string(_gc_cause)); 47 } 48 out.cr(); 49 } 50 } 51 52 template <typename Handle1, typename Handle2> 53 inline void GCTraceTimeImpl<Handle1, Handle2>::log_stop(jlong start_counter, jlong stop_counter) { 54 double duration_in_ms = TimeHelper::counter_to_millis(stop_counter - start_counter); 55 double start_time_in_secs = TimeHelper::counter_to_seconds(start_counter); 56 double stop_time_in_secs = TimeHelper::counter_to_seconds(stop_counter); 57 58 LogStream out(_out_stop); 59 60 out.print("%s", _title); 61 62 if (_gc_cause != GCCause::_no_gc) { 63 out.print(" (%s)", GCCause::to_string(_gc_cause)); 64 } 65 66 if (_heap_usage_before != SIZE_MAX) { 67 CollectedHeap* heap = Universe::heap(); 68 size_t used_before_m = _heap_usage_before / M; 69 size_t used_m = heap->used() / M; 70 size_t capacity_m = heap->capacity() / M; 71 out.print(" " LOG_STOP_HEAP_FORMAT, used_before_m, used_m, capacity_m); 72 } 73 74 out.print_cr(" %.3fms", duration_in_ms); 75 } 76 77 template <typename Handle1, typename Handle2> 78 inline void GCTraceTimeImpl<Handle1, Handle2>::time_stamp(Ticks& ticks) { 79 if (_enabled || _timer != NULL) { 80 ticks.stamp(); 81 } 82 } 83 84 template <typename Handle1, typename Handle2> 85 inline GCTraceTimeImpl<Handle1, Handle2>::GCTraceTimeImpl(Handle1 out_start, Handle2 out_stop, const char* title, GCTimer* timer, GCCause::Cause gc_cause, bool log_heap_usage) : 86 _out_start(out_start), 87 _out_stop(out_stop), 88 _enabled(out_stop.is_enabled()), 89 _start_ticks(), 90 _title(title), 91 _gc_cause(gc_cause), 92 _timer(timer), 93 _heap_usage_before(SIZE_MAX) { 94 95 time_stamp(_start_ticks); 96 if (_enabled) { 97 if (log_heap_usage) { 98 _heap_usage_before = Universe::heap()->used(); 99 } 100 log_start(_start_ticks.value()); 101 } 102 if (_timer != NULL) { 103 _timer->register_gc_phase_start(_title, _start_ticks); 104 } 105 } 106 template <typename Handle1, typename Handle2> 107 inline GCTraceTimeImpl<Handle1, Handle2>::~GCTraceTimeImpl() { 108 Ticks stop_ticks; 109 time_stamp(stop_ticks); 110 if (_enabled) { 111 log_stop(_start_ticks.value(), stop_ticks.value()); 112 } 113 if (_timer != NULL) { 114 _timer->register_gc_phase_end(stop_ticks); 115 } 116 } 117 118 template <LogLevelType Level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag > 119 GCTraceConcTimeImpl<Level, T0, T1, T2, T3, T4, GuardTag>::GCTraceConcTimeImpl(const char* title) : 120 _enabled(LogImpl<T0, T1, T2, T3, T4, GuardTag>::is_level(Level)), _start_time(os::elapsed_counter()), _title(title) { 121 if (_enabled) { 122 LogImpl<T0, T1, T2, T3, T4>::template write<Level>("%s", _title); 123 } 124 } 125 126 template <LogLevelType Level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag > 127 GCTraceConcTimeImpl<Level, T0, T1, T2, T3, T4, GuardTag>::~GCTraceConcTimeImpl() { 128 if (_enabled) { 129 jlong stop_time = os::elapsed_counter(); 130 LogImpl<T0, T1, T2, T3, T4>::template write<Level>("%s %0.3fms", _title, 131 TimeHelper::counter_to_millis(stop_time - _start_time)); 132 } 133 } 134 135 // Figure out the first __NO_TAG position and replace it with 'start'. 136 #define INJECT_START_TAG(T1, T2, T3, T4) \ 137 (( T1 == LogTag::__NO_TAG) ? PREFIX_LOG_TAG(start) : T1), \ 138 ((T1 != LogTag::__NO_TAG && T2 == LogTag::__NO_TAG) ? PREFIX_LOG_TAG(start) : T2), \ 139 ((T2 != LogTag::__NO_TAG && T3 == LogTag::__NO_TAG) ? PREFIX_LOG_TAG(start) : T3), \ 140 ((T3 != LogTag::__NO_TAG && T4 == LogTag::__NO_TAG) ? PREFIX_LOG_TAG(start) : T4) 141 142 template <LogLevelType level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag> 143 GCTraceTimeImplWrapper<level, T0, T1, T2, T3, T4, GuardTag>::GCTraceTimeImplWrapper( 144 const char* title, GCTimer* timer, GCCause::Cause gc_cause, bool log_heap_usage) 145 : _impl( 146 LogTargetHandle::create<level, T0, INJECT_START_TAG(T1, T2, T3, T4), GuardTag>(), 147 LogTargetHandle::create<level, T0, T1, T2, T3, T4, GuardTag>(), 148 title, 149 timer, 150 gc_cause, 151 log_heap_usage) { 152 153 STATIC_ASSERT(T0 != LogTag::__NO_TAG); // Need some tag to log on. 154 STATIC_ASSERT(T4 == LogTag::__NO_TAG); // Need to leave at least the last tag for the "start" tag in log_start() 155 } 156 157 template <LogLevelType level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag> 158 GCAsyncTraceTimeImplWrapper<level, T0, T1, T2, T3, T4, GuardTag>::GCAsyncTraceTimeImplWrapper( 159 const char* title, GCTimer* timer, GCCause::Cause gc_cause, bool log_heap_usage) 160 : _impl( 161 AsyncLogTargetHandle::create<level, T0, INJECT_START_TAG(T1, T2, T3, T4), GuardTag>(), 162 AsyncLogTargetHandle::create<level, T0, T1, T2, T3, T4, GuardTag>(), 163 title, 164 timer, 165 gc_cause, 166 log_heap_usage) { 167 168 STATIC_ASSERT(T0 != LogTag::__NO_TAG); // Need some tag to log on. 169 STATIC_ASSERT(T4 == LogTag::__NO_TAG); // Need to leave at least the last tag for the "start" tag in log_start() 170 } 171 172 #undef INJECT_START_TAG 173 174 175 #define GCTraceTime(Level, ...) GCTraceTimeImplWrapper<LogLevel::Level, LOG_TAGS(__VA_ARGS__)> 176 #define GCTraceConcTime(Level, ...) GCTraceConcTimeImpl<LogLevel::Level, LOG_TAGS(__VA_ARGS__)> 177 178 #endif // SHARE_GC_SHARED_GCTRACETIME_INLINE_HPP