src/share/vm/gc/shared/gcTraceTime.hpp

@@ -23,33 +23,122 @@
  */
 
 #ifndef SHARE_VM_GC_SHARED_GCTRACETIME_HPP
 #define SHARE_VM_GC_SHARED_GCTRACETIME_HPP
 
+#include "gc/shared/collectedHeap.hpp"
+#include "gc/shared/gcTimer.hpp"
 #include "gc/shared/gcTrace.hpp"
+#include "logging/log.hpp"
 #include "memory/allocation.hpp"
+#include "memory/resourceArea.hpp"
+#include "memory/universe.hpp"
 #include "prims/jni_md.h"
 #include "utilities/ticks.hpp"
+#include "runtime/timer.hpp"
+#include "utilities/ticks.hpp"
 
-class GCTimer;
+class GCTraceCPUTime : public StackObj {
+  bool _active;                 // true if times will be measured and printed
+  double _starting_user_time;   // user time at start of measurement
+  double _starting_system_time; // system time at start of measurement
+  double _starting_real_time;   // real time at start of measurement
+ public:
+  GCTraceCPUTime();
+  ~GCTraceCPUTime();
+};
 
-class GCTraceTimeImpl VALUE_OBJ_CLASS_SPEC {
+template <LogLevelType Level, LogTagType T0, LogTagType T1 = LogTag::__NO_TAG, LogTagType T2 = LogTag::__NO_TAG, LogTagType T3 = LogTag::__NO_TAG,
+    LogTagType T4 = LogTag::__NO_TAG, LogTagType GuardTag = LogTag::__NO_TAG>
+class GCTraceTimeImpl : public StackObj {
+ private:
+  bool _enabled;
+  Ticks _start_ticks;
   const char* _title;
-  bool _doit;
-  bool _print_cr;
+  GCCause::Cause _gc_cause;
   GCTimer* _timer;
-  Ticks _start_counter;
+  size_t _heap_usage_before;
 
- public:
-  GCTraceTimeImpl(const char* title, bool doit, bool print_cr, GCTimer* timer);
-  ~GCTraceTimeImpl();
-};
-
-class GCTraceTime : public StackObj {
-  GCTraceTimeImpl _gc_trace_time_impl;
+  void log_start(jlong start_counter) {
+    if (Log<LogTag::start, T0, T1, T2, T3>::is_level(Level)) {
+      FormatBuffer<> start_msg("%s", _title);
+      if (_gc_cause != GCCause::_no_gc) {
+        start_msg.append(" (%s)", GCCause::to_string(_gc_cause));
+      }
+      start_msg.append(" (%.3fs)", TimeHelper::counter_to_seconds(start_counter));
+      // Make sure to put the "start" tag last in the tag set
+      STATIC_ASSERT(T0 != LogTag::__NO_TAG); // Need some tag to log on.
+      STATIC_ASSERT(T4 == LogTag::__NO_TAG); // Need to leave at least the last tag for the "start" tag in log_start()
+      if (T1 == LogTag::__NO_TAG) {
+        Log<T0, LogTag::start>::template write<Level>("%s", start_msg.buffer());
+      } else if (T2 == LogTag::__NO_TAG) {
+        Log<T0, T1, LogTag::start>::template write<Level>("%s", start_msg.buffer());
+      } else if (T3 == LogTag::__NO_TAG) {
+        Log<T0, T1, T2, LogTag::start>::template write<Level>("%s", start_msg.buffer());
+      } else {
+        Log<T0, T1, T2, T3, LogTag::start>::template write<Level>("%s", start_msg.buffer());
+      }
+    }
+  }
+
+#define LOG_STOP_TIME_FORMAT "(%.3fs, %.3fs) %.3fms"
+#define LOG_STOP_HEAP_FORMAT SIZE_FORMAT "M->" SIZE_FORMAT "M("  SIZE_FORMAT "M)"
+
+  void log_stop(jlong start_counter, jlong stop_counter) {
+    double duration_in_ms = TimeHelper::counter_to_millis(stop_counter - start_counter);
+    double start_time_in_secs = TimeHelper::counter_to_seconds(start_counter);
+    double stop_time_in_secs = TimeHelper::counter_to_seconds(stop_counter);
+    FormatBuffer<> stop_msg("%s", _title);
+    if (_gc_cause != GCCause::_no_gc) {
+      stop_msg.append(" (%s)", GCCause::to_string(_gc_cause));
+    }
+    if (_heap_usage_before == SIZE_MAX) {
+      Log<T0, T1, T2, T3, T4>::template write<Level>("%s " LOG_STOP_TIME_FORMAT,
+          stop_msg.buffer(), start_time_in_secs, stop_time_in_secs, duration_in_ms);
+    } else {
+      CollectedHeap* heap = Universe::heap();
+      size_t used_before_m = _heap_usage_before / M;
+      size_t used_m = heap->used() / M;
+      size_t capacity_m = heap->capacity() / M;
+      Log<T0, T1, T2, T3, T4>::template write<Level>("%s " LOG_STOP_HEAP_FORMAT " " LOG_STOP_TIME_FORMAT,
+          stop_msg.buffer(), used_before_m, used_m, capacity_m, start_time_in_secs, stop_time_in_secs, duration_in_ms);
+    }
+  }
 
  public:
-  GCTraceTime(const char* title, bool doit, bool print_cr, GCTimer* timer) :
-    _gc_trace_time_impl(title, doit, print_cr, timer) {};
+  GCTraceTimeImpl(const char* title, GCTimer* timer = NULL, GCCause::Cause gc_cause = GCCause::_no_gc, bool log_heap_usage = false)
+   : _enabled(Log<T0, T1, T2, T3, T4, GuardTag>::is_level(Level)), _start_ticks(), _title(title), _gc_cause(gc_cause), _timer(timer) {
+    if (_enabled) {
+      _start_ticks.stamp();
+      if (log_heap_usage) {
+        _heap_usage_before = Universe::heap()->used();
+      } else {
+        _heap_usage_before = SIZE_MAX;
+      }
+      log_start(_start_ticks.value());
+    }
+    if (_timer != NULL) {
+      if (!_enabled) {
+        _start_ticks.stamp();
+      }
+      _timer->register_gc_phase_start(_title, _start_ticks);
+    }
+  }
+
+  ~GCTraceTimeImpl() {
+    Ticks stop_ticks;
+    if (_enabled) {
+      stop_ticks.stamp();
+      log_stop(_start_ticks.value(), stop_ticks.value());
+    }
+    if (_timer != NULL) {
+      if (!_enabled) {
+        stop_ticks.stamp();
+      }
+      _timer->register_gc_phase_end(stop_ticks);
+    }
+  }
 };
 
+#define GCTraceTime(Level, ...) GCTraceTimeImpl<LogLevel::Level, LOG_TAGS(__VA_ARGS__)>
+
 #endif // SHARE_VM_GC_SHARED_GCTRACETIME_HPP