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