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
--- EOF ---