--- a/hotspot/src/share/vm/gc/shared/gcTraceTime.hpp Tue Apr 05 09:05:19 2016 +0200
+++ b/hotspot/src/share/vm/gc/shared/gcTraceTime.hpp Tue Apr 05 11:00:22 2016 +0200
@@ -26,6 +26,8 @@
#define SHARE_VM_GC_SHARED_GCTRACETIME_HPP
#include "logging/log.hpp"
+#include "logging/logHandle.hpp"
+#include "logging/logStream.hpp"
#include "memory/allocation.hpp"
#include "utilities/ticks.hpp"
@@ -41,10 +43,10 @@
class GCTimer;
-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:
+ LogTargetHandle _out_start;
+ LogTargetHandle _out_stop;
bool _enabled;
Ticks _start_ticks;
const char* _title;
@@ -57,10 +59,18 @@
void time_stamp(Ticks& ticks);
public:
- GCTraceTimeImpl(const char* title, GCTimer* timer = NULL, GCCause::Cause gc_cause = GCCause::_no_gc, bool log_heap_usage = false);
+ GCTraceTimeImpl(LogTargetHandle out_start, LogTargetHandle out_end, const char* title, GCTimer* timer = NULL, GCCause::Cause gc_cause = GCCause::_no_gc, bool log_heap_usage = false);
~GCTraceTimeImpl();
};
+template <LogLevelType Level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag>
+class GCTraceTimeImplWrapper : public StackObj {
+ GCTraceTimeImpl _impl;
+public:
+ GCTraceTimeImplWrapper(const char* title, GCTimer* timer = NULL, GCCause::Cause gc_cause = GCCause::_no_gc, bool log_heap_usage = false);
+ ~GCTraceTimeImplWrapper();
+};
+
// Similar to GCTraceTimeImpl but is intended for concurrent phase logging,
// which is a bit simpler and should always print the start line, i.e. not add the "start" tag.
template <LogLevelType Level, LogTagType T0, LogTagType T1 = LogTag::__NO_TAG, LogTagType T2 = LogTag::__NO_TAG, LogTagType T3 = LogTag::__NO_TAG,
--- a/hotspot/src/share/vm/gc/shared/gcTraceTime.inline.hpp Tue Apr 05 09:05:19 2016 +0200
+++ b/hotspot/src/share/vm/gc/shared/gcTraceTime.inline.hpp Tue Apr 05 11:00:22 2016 +0200
@@ -30,6 +30,7 @@
#include "gc/shared/gcTrace.hpp"
#include "gc/shared/gcTraceTime.hpp"
#include "logging/log.hpp"
+#include "logging/logStream.inline.hpp"
#include "memory/universe.hpp"
#include "prims/jni_md.h"
#include "utilities/ticks.hpp"
@@ -37,64 +38,52 @@
#define LOG_STOP_TIME_FORMAT "(%.3fs, %.3fs) %.3fms"
#define LOG_STOP_HEAP_FORMAT SIZE_FORMAT "M->" SIZE_FORMAT "M(" SIZE_FORMAT "M)"
-template <LogLevelType Level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag >
-void GCTraceTimeImpl<Level, T0, T1, T2, T3, T4, GuardTag>::log_start(jlong start_counter) {
- 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()
+inline void GCTraceTimeImpl::log_start(jlong start_counter) {
+ if (_out_start.is_enabled()) {
+ LogStream out(_out_start);
- // Get log with start tag appended (replace first occurrence of NO_TAG)
- const LogTagType start_tag = PREFIX_LOG_TAG(start);
- const LogTagType no_tag = PREFIX_LOG_TAG(_NO_TAG);
- LogImpl<T0,
- T1 == no_tag ? start_tag : T1,
- T1 != no_tag && T2 == no_tag ? start_tag : T2,
- T2 != no_tag && T3 == no_tag ? start_tag : T3,
- T3 != no_tag && T4 == no_tag ? start_tag : T4
- > log;
-
- if (log.is_level(Level)) {
- FormatBuffer<> start_msg("%s", _title);
+ out.print("%s", _title);
if (_gc_cause != GCCause::_no_gc) {
- start_msg.append(" (%s)", GCCause::to_string(_gc_cause));
+ out.print(" (%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
- log.template write<Level>("%s", start_msg.buffer());
+ out.print_cr(" (%.3fs)", TimeHelper::counter_to_seconds(start_counter));
}
}
-template <LogLevelType Level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag >
-void GCTraceTimeImpl<Level, T0, T1, T2, T3, T4, GuardTag>::log_stop(jlong start_counter, jlong stop_counter) {
+inline void GCTraceTimeImpl::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);
+
+ LogStream out(_out_stop);
+
+ out.print("%s", _title);
+
if (_gc_cause != GCCause::_no_gc) {
- stop_msg.append(" (%s)", GCCause::to_string(_gc_cause));
+ out.print(" (%s)", GCCause::to_string(_gc_cause));
}
- if (_heap_usage_before == SIZE_MAX) {
- LogImpl<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 {
+
+ if (_heap_usage_before != SIZE_MAX) {
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;
- LogImpl<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);
+ out.print(" " LOG_STOP_HEAP_FORMAT, used_before_m, used_m, capacity_m);
}
+
+ out.print_cr(" " LOG_STOP_TIME_FORMAT, start_time_in_secs, stop_time_in_secs, duration_in_ms);
}
-template <LogLevelType Level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag >
-void GCTraceTimeImpl<Level, T0, T1, T2, T3, T4, GuardTag>::time_stamp(Ticks& ticks) {
+inline void GCTraceTimeImpl::time_stamp(Ticks& ticks) {
if (_enabled || _timer != NULL) {
ticks.stamp();
}
}
-template <LogLevelType Level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag >
-GCTraceTimeImpl<Level, T0, T1, T2, T3, T4, GuardTag>::GCTraceTimeImpl(const char* title, GCTimer* timer, GCCause::Cause gc_cause, bool log_heap_usage) :
- _enabled(LogImpl<T0, T1, T2, T3, T4, GuardTag>::is_level(Level)),
+inline GCTraceTimeImpl::GCTraceTimeImpl(LogTargetHandle out_start, LogTargetHandle out_stop, const char* title, GCTimer* timer, GCCause::Cause gc_cause, bool log_heap_usage) :
+ _enabled(out_stop.is_enabled()),
+ _out_start(out_start),
+ _out_stop(out_stop),
_start_ticks(),
_heap_usage_before(SIZE_MAX),
_title(title),
@@ -113,8 +102,7 @@
}
}
-template <LogLevelType Level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag >
-GCTraceTimeImpl<Level, T0, T1, T2, T3, T4, GuardTag>::~GCTraceTimeImpl() {
+inline GCTraceTimeImpl::~GCTraceTimeImpl() {
Ticks stop_ticks;
time_stamp(stop_ticks);
if (_enabled) {
@@ -145,7 +133,34 @@
}
}
-#define GCTraceTime(Level, ...) GCTraceTimeImpl<LogLevel::Level, LOG_TAGS(__VA_ARGS__)>
+// Figure out the first __NO_TAG position and replace it with 'start'.
+#define INJECT_START_TAG(T1, T2, T3, T4) \
+ (( T1 == LogTag::__NO_TAG) ? PREFIX_LOG_TAG(start) : T1), \
+ ((T1 != LogTag::__NO_TAG && T2 == LogTag::__NO_TAG) ? PREFIX_LOG_TAG(start) : T2), \
+ ((T2 != LogTag::__NO_TAG && T3 == LogTag::__NO_TAG) ? PREFIX_LOG_TAG(start) : T3), \
+ ((T3 != LogTag::__NO_TAG && T4 == LogTag::__NO_TAG) ? PREFIX_LOG_TAG(start) : T4)
+
+template <LogLevelType level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag>
+GCTraceTimeImplWrapper<level, T0, T1, T2, T3, T4, GuardTag>::GCTraceTimeImplWrapper(
+ const char* title, GCTimer* timer, GCCause::Cause gc_cause, bool log_heap_usage)
+ : _impl(
+ LogTargetHandle::create<level, T0, INJECT_START_TAG(T1, T2, T3, T4), GuardTag>(),
+ LogTargetHandle::create<level, T0, T1, T2, T3, T4, GuardTag>(),
+ title,
+ timer,
+ gc_cause,
+ log_heap_usage) {
+
+ 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()
+}
+
+#undef INJECT_START_TAG
+
+template <LogLevelType Level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag>
+GCTraceTimeImplWrapper<Level, T0, T1, T2, T3, T4, GuardTag>::~GCTraceTimeImplWrapper() {}
+
+#define GCTraceTime(Level, ...) GCTraceTimeImplWrapper<LogLevel::Level, LOG_TAGS(__VA_ARGS__)>
#define GCTraceConcTime(Level, ...) GCTraceConcTimeImpl<LogLevel::Level, LOG_TAGS(__VA_ARGS__)>
#endif // SHARE_VM_GC_SHARED_GCTRACETIME_INLINE_HPP
--- a/hotspot/src/share/vm/logging/log.cpp Tue Apr 05 09:05:19 2016 +0200
+++ b/hotspot/src/share/vm/logging/log.cpp Tue Apr 05 11:00:22 2016 +0200
@@ -28,9 +28,11 @@
#ifndef PRODUCT
+#include "gc/shared/gcTraceTime.inline.hpp"
#include "logging/log.hpp"
#include "logging/logConfiguration.hpp"
#include "logging/logOutput.hpp"
+#include "logging/logStream.inline.hpp"
#include "memory/resourceArea.hpp"
#define assert_str_eq(s1, s2) \
@@ -102,7 +104,6 @@
};
void Test_configure_stdout() {
- ResourceMark rm;
LogOutput* stdoutput = LogOutput::Stdout;
TestLogSavedConfig tlsc;
@@ -167,7 +168,6 @@
}
void Test_log_prefix() {
- ResourceMark rm;
TestLogFile log_file("log_prefix");
TestLogSavedConfig log_cfg(log_file.name(), "logging+test=trace");
@@ -186,7 +186,6 @@
char big_msg[4096] = {0};
char Xchar = '~';
- ResourceMark rm;
TestLogFile log_file("log_big");
TestLogSavedConfig log_cfg(log_file.name(), "logging+test=trace");
@@ -315,4 +314,401 @@
Test_logtarget_off();
}
+
+static void Test_logstream_helper(outputStream* stream) {
+ TestLogFile log_file("log_stream");
+ TestLogSavedConfig tlsc(log_file.name(), "gc=debug");
+
+ // Try to log, but expect this to be filtered out.
+ stream->print("%d ", 3); stream->print("workers"); stream->cr();
+
+ FILE* fp = fopen(log_file.name(), "r");
+ assert(fp != NULL, "File read error");
+
+ char output[256 /* Large enough buffer */];
+ char* res = fgets(output, sizeof(output), fp);
+ assert(res != NULL, "assert");
+
+ assert(strstr(output, "3 workers") != NULL, "log line missing");
+
+ fclose(fp);
+}
+
+static void Test_logstream_log() {
+ Log(gc) log;
+ LogStream stream(log.debug());
+
+ Test_logstream_helper(&stream);
+}
+
+static void Test_logstream_logtarget() {
+ LogTarget(Debug, gc) log;
+ LogStream stream(log);
+
+ Test_logstream_helper(&stream);
+}
+
+static void Test_logstream_logstreamhandle() {
+ LogStreamHandle(Debug, gc) stream;
+
+ Test_logstream_helper(&stream);
+}
+
+static void Test_logstream_no_rm() {
+ ResourceMark rm;
+ outputStream* stream = LogTarget(Debug, gc)::stream();
+
+ Test_logstream_helper(stream);
+}
+
+void Test_logstream() {
+ Test_logstream_log();
+ Test_logstream_logtarget();
+ Test_logstream_logstreamhandle();
+ Test_logstream_no_rm();
+}
+
+void Test_loghandle_on() {
+ TestLogFile log_file("log_handle");
+ TestLogSavedConfig tlsc(log_file.name(), "gc=debug");
+
+ Log(gc) log;
+ LogHandle log_handle(log);
+
+ assert(log_handle.is_debug(), "assert");
+
+ // Try to log trough a LogHandle.
+ log_handle.debug("%d workers", 3);
+
+ FILE* fp = fopen(log_file.name(), "r");
+ assert(fp, "File read error");
+
+ char output[256 /* Large enough buffer */];
+ char* res = fgets(output, sizeof(output), fp);
+ assert(res != NULL, "assert");
+
+ assert(strstr(output, "3 workers") != NULL, "log line missing");
+
+ fclose(fp);
+}
+
+void Test_loghandle_off() {
+ TestLogFile log_file("log_handle");
+ TestLogSavedConfig tlsc(log_file.name(), "gc=info");
+
+ Log(gc) log;
+ LogHandle log_handle(log);
+
+ if (log_handle.is_debug()) {
+ // The log config could have been redirected gc=debug to a file. If gc=debug
+ // is enabled, we can only test that the LogTarget returns the same value
+ // as the log_is_enabled function. The rest of the test will be ignored.
+ assert(log_handle.is_debug() == log_is_enabled(Debug, gc), "assert");
+ log_warning(logging)("This test doesn't support runs with -Xlog");
+ return;
+ }
+
+ // Try to log trough a LogHandle. Should fail, since only info is turned on.
+ log_handle.debug("%d workers", 3);
+
+ // Log a dummy line so that fgets doesn't return NULL because the file is empty.
+ log_info(gc)("Dummy line");
+
+ FILE* fp = fopen(log_file.name(), "r");
+ assert(fp, "File read error");
+
+ char output[256 /* Large enough buffer */];
+ char* res = fgets(output, sizeof(output), fp);
+ assert(res != NULL, "assert");
+
+ assert(strstr(output, "3 workers") == NULL, "log line missing");
+
+ fclose(fp);
+}
+
+void Test_loghandle() {
+ Test_loghandle_on();
+ Test_loghandle_off();
+}
+
+static void Test_logtargethandle_on() {
+ TestLogFile log_file("log_handle");
+ TestLogSavedConfig tlsc(log_file.name(), "gc=debug");
+
+ LogTarget(Debug, gc) log;
+ LogTargetHandle log_handle(log);
+
+ assert(log_handle.is_enabled(), "assert");
+
+ // Try to log trough a LogHandle.
+ log_handle.print("%d workers", 3);
+
+ FILE* fp = fopen(log_file.name(), "r");
+ assert(fp, "File read error");
+
+ char output[256 /* Large enough buffer */];
+ char* res = fgets(output, sizeof(output), fp);
+ assert(res != NULL, "assert");
+
+ assert(strstr(output, "3 workers") != NULL, "log line missing");
+
+ fclose(fp);
+}
+
+static void Test_logtargethandle_off() {
+ TestLogFile log_file("log_handle");
+ TestLogSavedConfig tlsc(log_file.name(), "gc=info");
+
+ LogTarget(Debug, gc) log;
+ LogTargetHandle log_handle(log);
+
+ if (log_handle.is_enabled()) {
+ // The log config could have been redirected gc=debug to a file. If gc=debug
+ // is enabled, we can only test that the LogTarget returns the same value
+ // as the log_is_enabled function. The rest of the test will be ignored.
+ assert(log_handle.is_enabled() == log_is_enabled(Debug, gc), "assert");
+ log_warning(logging)("This test doesn't support runs with -Xlog");
+ return;
+ }
+
+ // Try to log trough a LogHandle. Should fail, since only info is turned on.
+ log_handle.print("%d workers", 3);
+
+ // Log a dummy line so that fgets doesn't return NULL because the file is empty.
+ log_info(gc)("Dummy line");
+
+ FILE* fp = fopen(log_file.name(), "r");
+ assert(fp, "File read error");
+
+ char output[256 /* Large enough buffer */];
+ char* res = fgets(output, sizeof(output), fp);
+ assert(res != NULL, "assert");
+
+ assert(strstr(output, "3 workers") == NULL, "log line missing");
+
+ fclose(fp);
+}
+
+void Test_logtargethandle() {
+ Test_logtargethandle_on();
+ Test_logtargethandle_off();
+}
+
+static void Test_log_gctracetime_full() {
+ TestLogFile log_file("log_gctracetime");
+ TestLogSavedConfig tlsc(log_file.name(), "gc=debug,gc+start=debug");
+
+ LogTarget(Debug, gc) gc_debug;
+ LogTarget(Debug, gc, start) gc_start_debug;
+
+ assert(gc_debug.is_enabled(), "assert");
+ assert(gc_start_debug.is_enabled(), "assert");
+
+ {
+ MutexLocker lock(Heap_lock); // Needed to read heap usage
+ GCTraceTime(Debug, gc) timer("Test GC", NULL, GCCause::_allocation_failure, true);
+ }
+
+ FILE* fp = fopen(log_file.name(), "r");
+ assert(fp, "File read error");
+
+ char output[256 /* Large enough buffer */];
+
+ char* res = fgets(output, sizeof(output), fp);
+ assert(res != NULL, "assert");
+
+ // [2.975s][debug][gc,start] Test GC (Allocation Failure) (2.975s)
+ assert(strstr(output, "[gc,start") != NULL, "Incorrect tag set");
+ assert(strstr(output, "] Test GC (Allocation Failure) (") != NULL, "Incorrect log line");
+ assert(strstr(output, "s)") != NULL, "Incorrect log line");
+
+ res = fgets(output, sizeof(output), fp);
+ assert(res != NULL, "assert");
+
+ // [2.975s][debug][gc ] Test GC (Allocation Failure) 59M->59M(502M) (2.975s, 2.975s) 0.026ms
+ assert(strstr(output, "[gc ") != NULL, "Incorrect tag set");
+ assert(strstr(output, "] Test GC (Allocation Failure) ") != NULL, "Incorrect log line");
+ assert(strstr(output, "M) (") != NULL, "Incorrect log line");
+ assert(strstr(output, "s, ") != NULL, "Incorrect log line");
+ assert(strstr(output, "s) ") != NULL, "Incorrect log line");
+ assert(strstr(output, "ms") != NULL, "Incorrect log line");
+
+ fclose(fp);
+}
+
+static void Test_log_gctracetime_full_multitag() {
+ TestLogFile log_file("log_gctracetime");
+ TestLogSavedConfig tlsc(log_file.name(), "gc+ref=debug,gc+ref+start=debug");
+
+ LogTarget(Debug, gc, ref) gc_debug;
+ LogTarget(Debug, gc, ref, start) gc_start_debug;
+
+ assert(gc_debug.is_enabled(), "assert");
+ assert(gc_start_debug.is_enabled(), "assert");
+
+ {
+ MutexLocker lock(Heap_lock); // Needed to read heap usage
+ GCTraceTime(Debug, gc, ref) timer("Test GC", NULL, GCCause::_allocation_failure, true);
+ }
+
+ FILE* fp = fopen(log_file.name(), "r");
+ assert(fp, "File read error");
+
+ char output[256 /* Large enough buffer */];
+
+ char* res = fgets(output, sizeof(output), fp);
+ assert(res != NULL, "assert");
+
+ // [2.975s][debug][gc,start] Test GC (Allocation Failure) (2.975s)
+ assert(strstr(output, "[gc,ref,start") != NULL, "Incorrect tag set");
+ assert(strstr(output, "] Test GC (Allocation Failure) (") != NULL, "Incorrect log line");
+ assert(strstr(output, "s)") != NULL, "Incorrect log line");
+
+ res = fgets(output, sizeof(output), fp);
+ assert(res != NULL, "assert");
+
+ // [2.975s][debug][gc ] Test GC (Allocation Failure) 59M->59M(502M) (2.975s, 2.975s) 0.026ms
+ assert(strstr(output, "[gc,ref ") != NULL, "Incorrect tag set");
+ assert(strstr(output, "] Test GC (Allocation Failure) ") != NULL, "Incorrect log line");
+ assert(strstr(output, "M) (") != NULL, "Incorrect log line");
+ assert(strstr(output, "s, ") != NULL, "Incorrect log line");
+ assert(strstr(output, "s) ") != NULL, "Incorrect log line");
+ assert(strstr(output, "ms") != NULL, "Incorrect log line");
+
+ fclose(fp);
+}
+
+static void Test_log_gctracetime_no_heap() {
+ TestLogFile log_file("log_gctracetime");
+ TestLogSavedConfig tlsc(log_file.name(), "gc=debug,gc+start=debug");
+
+ LogTarget(Debug, gc) gc_debug;
+ LogTarget(Debug, gc, start) gc_start_debug;
+
+ assert(gc_debug.is_enabled(), "assert");
+ assert(gc_start_debug.is_enabled(), "assert");
+
+ {
+ GCTraceTime(Debug, gc) timer("Test GC", NULL, GCCause::_allocation_failure, false);
+ }
+
+ FILE* fp = fopen(log_file.name(), "r");
+ assert(fp, "File read error");
+
+ char output[256 /* Large enough buffer */];
+
+ char* res = fgets(output, sizeof(output), fp);
+ assert(res != NULL, "assert");
+
+ // [2.975s][debug][gc,start] Test GC (Allocation Failure) (2.975s)
+ assert(strstr(output, "[gc,start") != NULL, "Incorrect tag set");
+ assert(strstr(output, "] Test GC (Allocation Failure) (") != NULL, "Incorrect log line");
+ assert(strstr(output, "s)") != NULL, "Incorrect log line");
+
+ res = fgets(output, sizeof(output), fp);
+ assert(res != NULL, "assert");
+
+ // [2.975s][debug][gc ] Test GC (Allocation Failure) (2.975s, 2.975s) 0.026ms
+ assert(strstr(output, "[gc ") != NULL, "Incorrect tag set");
+ assert(strstr(output, "] Test GC (Allocation Failure) (") != NULL, "Incorrect log line");
+ assert(strstr(output, "M) (") == NULL, "Incorrect log line");
+ assert(strstr(output, "s, ") != NULL, "Incorrect log line");
+ assert(strstr(output, "s) ") != NULL, "Incorrect log line");
+ assert(strstr(output, "ms") != NULL, "Incorrect log line");
+
+ fclose(fp);
+}
+
+static void Test_log_gctracetime_no_cause() {
+ TestLogFile log_file("log_gctracetime");
+ TestLogSavedConfig tlsc(log_file.name(), "gc=debug,gc+start=debug");
+
+ LogTarget(Debug, gc) gc_debug;
+ LogTarget(Debug, gc, start) gc_start_debug;
+
+ assert(gc_debug.is_enabled(), "assert");
+ assert(gc_start_debug.is_enabled(), "assert");
+
+ {
+ MutexLocker lock(Heap_lock); // Needed to read heap usage
+ GCTraceTime(Debug, gc) timer("Test GC", NULL, GCCause::_no_gc, true);
+ }
+
+ FILE* fp = fopen(log_file.name(), "r");
+ assert(fp, "File read error");
+
+ char output[256 /* Large enough buffer */];
+
+ char* res = fgets(output, sizeof(output), fp);
+ assert(res != NULL, "assert");
+
+ // [2.975s][debug][gc,start] Test GC (2.975s)
+ assert(strstr(output, "[gc,start") != NULL, "Incorrect tag set");
+ assert(strstr(output, "] Test GC (") != NULL, "Incorrect log line");
+ assert(strstr(output, "s)") != NULL, "Incorrect log line");
+
+ res = fgets(output, sizeof(output), fp);
+ assert(res != NULL, "assert");
+
+ // [2.975s][debug][gc ] Test GC 59M->59M(502M) (2.975s, 2.975s) 0.026ms
+ assert(strstr(output, "[gc ") != NULL, "Incorrect tag set");
+ assert(strstr(output, "] Test GC ") != NULL, "Incorrect log line");
+ assert(strstr(output, "M) (") != NULL, "Incorrect log line");
+ assert(strstr(output, "s, ") != NULL, "Incorrect log line");
+ assert(strstr(output, "s) ") != NULL, "Incorrect log line");
+ assert(strstr(output, "ms") != NULL, "Incorrect log line");
+
+ fclose(fp);
+}
+
+static void Test_log_gctracetime_no_heap_no_cause() {
+ TestLogFile log_file("log_gctracetime");
+ TestLogSavedConfig tlsc(log_file.name(), "gc=debug,gc+start=debug");
+
+ LogTarget(Debug, gc) gc_debug;
+ LogTarget(Debug, gc, start) gc_start_debug;
+
+ assert(gc_debug.is_enabled(), "assert");
+ assert(gc_start_debug.is_enabled(), "assert");
+
+ {
+ MutexLocker lock(Heap_lock); // Needed to read heap usage
+ GCTraceTime(Debug, gc) timer("Test GC", NULL, GCCause::_no_gc, false);
+ }
+
+ FILE* fp = fopen(log_file.name(), "r");
+ assert(fp, "File read error");
+
+ char output[256 /* Large enough buffer */];
+
+ char* res = fgets(output, sizeof(output), fp);
+ assert(res != NULL, "assert");
+
+ // [2.975s][debug][gc,start] Test GC (2.975s)
+ assert(strstr(output, "[gc,start") != NULL, "Incorrect tag set");
+ assert(strstr(output, "] Test GC (") != NULL, "Incorrect log line");
+ assert(strstr(output, "s)") != NULL, "Incorrect log line");
+
+ res = fgets(output, sizeof(output), fp);
+ assert(res != NULL, "assert");
+
+ // [2.975s][debug][gc ] Test GC (2.975s, 2.975s) 0.026ms
+ assert(strstr(output, "[gc ") != NULL, "Incorrect tag set");
+ assert(strstr(output, "] Test GC (") != NULL, "Incorrect log line");
+ assert(strstr(output, "M) (") == NULL, "Incorrect log line");
+ assert(strstr(output, "s, ") != NULL, "Incorrect log line");
+ assert(strstr(output, "s) ") != NULL, "Incorrect log line");
+ assert(strstr(output, "ms") != NULL, "Incorrect log line");
+
+ fclose(fp);
+}
+
+void Test_log_gctracetime() {
+ Test_log_gctracetime_full();
+ Test_log_gctracetime_full_multitag();
+ Test_log_gctracetime_no_heap();
+ Test_log_gctracetime_no_cause();
+ Test_log_gctracetime_no_heap_no_cause();
+}
+
#endif // PRODUCT
--- a/hotspot/src/share/vm/logging/log.hpp Tue Apr 05 09:05:19 2016 +0200
+++ b/hotspot/src/share/vm/logging/log.hpp Tue Apr 05 11:00:22 2016 +0200
@@ -31,7 +31,6 @@
#include "memory/allocation.hpp"
#include "runtime/os.hpp"
#include "utilities/debug.hpp"
-#include "utilities/ostream.hpp"
//
// Logging macros
@@ -104,6 +103,13 @@
//
#define LogTarget(level, ...) LogTargetImpl<LogLevel::level, LOG_TAGS(__VA_ARGS__)>
+// Forward declaration to decouple this file from the outputStream API.
+class outputStream;
+outputStream* create_log_stream(LogLevelType level, LogTagSet* tagset);
+
+template <LogLevelType level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag>
+class LogTargetImpl;
+
template <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 LogImpl VALUE_OBJ_CLASS_SPEC {
@@ -162,7 +168,10 @@
return is_level(LogLevel::level); \
} \
static outputStream* name##_stream() { \
- return new logStream(write<LogLevel::level>); \
+ return create_log_stream(LogLevel::level, &LogTagSetMapping<T0, T1, T2, T3, T4>::tagset()); \
+ } \
+ static LogTargetImpl<LogLevel::level, T0, T1, T2, T3, T4, GuardTag>* name() { \
+ return (LogTargetImpl<LogLevel::level, T0, T1, T2, T3, T4, GuardTag>*)NULL; \
}
LOG_LEVEL_LIST
#undef LOG_LEVEL
@@ -190,7 +199,7 @@
}
static outputStream* stream() {
- return new logStream(&LogImpl<T0, T1, T2, T3, T4, GuardTag>::template write<level>);
+ return create_log_stream(level, &LogTagSetMapping<T0, T1, T2, T3, T4>::tagset());
}
};
--- /dev/null Thu Jan 01 00:00:00 1970 +0000
+++ b/hotspot/src/share/vm/logging/logHandle.hpp Tue Apr 05 11:00:22 2016 +0200
@@ -0,0 +1,105 @@
+/*
+ * Copyright (c) 2016, Oracle and/or its affiliates. All rights reserved.
+ * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
+ *
+ * This code is free software; you can redistribute it and/or modify it
+ * under the terms of the GNU General Public License version 2 only, as
+ * published by the Free Software Foundation.
+ *
+ * This code is distributed in the hope that it will be useful, but WITHOUT
+ * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
+ * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
+ * version 2 for more details (a copy is included in the LICENSE file that
+ * accompanied this code).
+ *
+ * You should have received a copy of the GNU General Public License version
+ * 2 along with this work; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
+ *
+ * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
+ * or visit www.oracle.com if you need additional information or have any
+ * questions.
+ *
+ */
+#ifndef SHARE_VM_LOGGING_LOGHANDLE_HPP
+#define SHARE_VM_LOGGING_LOGHANDLE_HPP
+
+#include "logging/log.hpp"
+
+// Wraps a Log instance and throws away the template information.
+//
+// This can be used to pass a Log instance as a parameter without
+// polluting the surrounding API with template functions.
+class LogHandle {
+private:
+ LogTagSet* _tagset;
+
+public:
+ template <LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag>
+ LogHandle(const LogImpl<T0, T1, T2, T3, T4, GuardTag>& type_carrier) :
+ _tagset(&LogTagSetMapping<T0, T1, T2, T3, T4>::tagset()) {}
+
+ bool is_level(LogLevelType level) {
+ return _tagset->is_level(level);
+ }
+
+#define LOG_LEVEL(level, name) ATTRIBUTE_PRINTF(2, 0) \
+ LogHandle& v##name(const char* fmt, va_list args) { \
+ _tagset->vwrite(LogLevel::level, fmt, args); \
+ return *this; \
+ } \
+ LogHandle& name(const char* fmt, ...) ATTRIBUTE_PRINTF(2, 3) { \
+ va_list args; \
+ va_start(args, fmt); \
+ _tagset->vwrite(LogLevel::level, fmt, args); \
+ va_end(args); \
+ return *this; \
+ } \
+ bool is_##name() { \
+ return _tagset->is_level(LogLevel::level); \
+ }
+ LOG_LEVEL_LIST
+#undef LOG_LEVEL
+};
+
+// Wraps a LogTarget instance and throws away the template information.
+//
+// This can be used to pass a Log instance as a parameter without
+// polluting the surrounding API with template functions.
+class LogTargetHandle {
+ friend class LogStream;
+
+private:
+ const LogLevelType _level;
+ LogTagSet* _tagset;
+
+public:
+ template <LogLevelType level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag>
+ LogTargetHandle(const LogTargetImpl<level, T0, T1, T2, T3, T4, GuardTag>& type_carrier) :
+ _level(level),
+ _tagset(&LogTagSetMapping<T0, T1, T2, T3, T4>::tagset()) {}
+
+ template <LogLevelType level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag>
+ static LogTargetHandle create() {
+ return LogTargetHandle(LogTargetImpl<level, T0, T1, T2, T3, T4, GuardTag>());
+ }
+
+ void print(const char* fmt, ...) ATTRIBUTE_PRINTF(2, 3) {
+ va_list args;
+ va_start(args, fmt);
+ _tagset->vwrite(_level, fmt, args);
+ va_end(args);
+ }
+
+ bool is_enabled() const {
+ return _tagset->is_level(_level);
+ }
+
+ // Creates a log stream from the information stored in this instance.
+ // Callers need a ResourceMark on the stack.
+ outputStream* stream() {
+ return create_log_stream(_level, _tagset);;
+ }
+};
+
+#endif // SHARE_VM_LOGGING_LOGHANDLE_HPP
--- /dev/null Thu Jan 01 00:00:00 1970 +0000
+++ b/hotspot/src/share/vm/logging/logStream.cpp Tue Apr 05 11:00:22 2016 +0200
@@ -0,0 +1,34 @@
+/*
+ * Copyright (c) 2016, Oracle and/or its affiliates. All rights reserved.
+ * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
+ *
+ * This code is free software; you can redistribute it and/or modify it
+ * under the terms of the GNU General Public License version 2 only, as
+ * published by the Free Software Foundation.
+ *
+ * This code is distributed in the hope that it will be useful, but WITHOUT
+ * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
+ * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
+ * version 2 for more details (a copy is included in the LICENSE file that
+ * accompanied this code).
+ *
+ * You should have received a copy of the GNU General Public License version
+ * 2 along with this work; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
+ *
+ * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
+ * or visit www.oracle.com if you need additional information or have any
+ * questions.
+ *
+ */
+
+#include "precompiled.hpp"
+#include "logging/log.hpp"
+#include "logging/logStream.hpp"
+
+// Create a log stream without an embedded ResourceMark.
+// The function is placed here to be called out-of-line in log.hpp.
+outputStream* create_log_stream(LogLevelType level, LogTagSet* tagset) {
+ return new LogStreamNoResourceMark(level, tagset);
+}
+
--- /dev/null Thu Jan 01 00:00:00 1970 +0000
+++ b/hotspot/src/share/vm/logging/logStream.hpp Tue Apr 05 11:00:22 2016 +0200
@@ -0,0 +1,48 @@
+/*
+ * Copyright (c) 2016, Oracle and/or its affiliates. All rights reserved.
+ * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
+ *
+ * This code is free software; you can redistribute it and/or modify it
+ * under the terms of the GNU General Public License version 2 only, as
+ * published by the Free Software Foundation.
+ *
+ * This code is distributed in the hope that it will be useful, but WITHOUT
+ * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
+ * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
+ * version 2 for more details (a copy is included in the LICENSE file that
+ * accompanied this code).
+ *
+ * You should have received a copy of the GNU General Public License version
+ * 2 along with this work; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
+ *
+ * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
+ * or visit www.oracle.com if you need additional information or have any
+ * questions.
+ *
+ */
+
+#ifndef SHARE_VM_LOGGING_LOGSTREAM_HPP
+#define SHARE_VM_LOGGING_LOGSTREAM_HPP
+
+#include "logging/log.hpp"
+#include "utilities/ostream.hpp"
+
+// An output stream that logs to the logging framework.
+// Requires a ResourceMark on the stack.
+class LogStreamNoResourceMark : public outputStream {
+private:
+ stringStream _current_line;
+ LogLevelType _level;
+ LogTagSet* _tagset;
+
+public:
+ LogStreamNoResourceMark(LogLevelType level, LogTagSet* tagset) : _level(level), _tagset(tagset) {}
+ ~LogStreamNoResourceMark() {
+ guarantee(_current_line.size() == 0, "Buffer not flushed. Missing call to print_cr()?");
+ }
+
+ void write(const char* s, size_t len);
+};
+
+#endif // SHARE_VM_LOGGING_LOGSTREAM_HPP
--- /dev/null Thu Jan 01 00:00:00 1970 +0000
+++ b/hotspot/src/share/vm/logging/logStream.inline.hpp Tue Apr 05 11:00:22 2016 +0200
@@ -0,0 +1,94 @@
+/*
+ * Copyright (c) 2016, Oracle and/or its affiliates. All rights reserved.
+ * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
+ *
+ * This code is free software; you can redistribute it and/or modify it
+ * under the terms of the GNU General Public License version 2 only, as
+ * published by the Free Software Foundation.
+ *
+ * This code is distributed in the hope that it will be useful, but WITHOUT
+ * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
+ * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
+ * version 2 for more details (a copy is included in the LICENSE file that
+ * accompanied this code).
+ *
+ * You should have received a copy of the GNU General Public License version
+ * 2 along with this work; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
+ *
+ * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
+ * or visit www.oracle.com if you need additional information or have any
+ * questions.
+ *
+ */
+#ifndef SHARE_VM_LOGGING_LOGSTREAM_INLINE_HPP
+#define SHARE_VM_LOGGING_LOGSTREAM_INLINE_HPP
+
+#include "logging/log.hpp"
+#include "logging/logHandle.hpp"
+#include "logging/logStream.hpp"
+#include "memory/resourceArea.hpp"
+#include "utilities/ostream.hpp"
+
+inline void LogStreamNoResourceMark::write(const char* s, size_t len) {
+ if (len > 0 && s[len - 1] == '\n') {
+ _current_line.write(s, len - 1);
+ _tagset->write(_level, "%s", _current_line.as_string());
+ _current_line.reset();
+ } else {
+ _current_line.write(s, len);
+ }
+ update_position(s, len);
+}
+
+// An output stream that logs to the logging framework, and embeds a ResourceMark.
+//
+// The class is intended to be stack allocated.
+// Care needs to be taken when nested ResourceMarks are used.
+class LogStream : public outputStream {
+private:
+ ResourceMark _embedded_resource_mark;
+ LogStreamNoResourceMark _stream;
+
+public:
+ // Constructor to support creation from a LogTarget instance.
+ //
+ // LogTarget(Debug, gc) log;
+ // LogStream(log) stream;
+ template <LogLevelType level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag>
+ LogStream(const LogTargetImpl<level, T0, T1, T2, T3, T4, GuardTag>& type_carrier) :
+ _embedded_resource_mark(),
+ _stream(level, &LogTagSetMapping<T0, T1, T2, T3, T4>::tagset()) {}
+
+ // Constructor to support creation from typed (likely NULL) pointer. Mostly used by the logging framework.
+ //
+ // LogStream stream(log.debug());
+ // LogStream stream((LogTargetImpl<level, T0, T1, T2, T3, T4, GuardTag>*)NULL);
+ template <LogLevelType level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag>
+ LogStream(const LogTargetImpl<level, T0, T1, T2, T3, T4, GuardTag>* type_carrier) :
+ _embedded_resource_mark(),
+ _stream(level, &LogTagSetMapping<T0, T1, T2, T3, T4>::tagset()) {}
+
+ // Constructor to support creation from a LogTargetHandle.
+ //
+ // LogTarget(Debug, gc) log;
+ // LogTargetHandle(log) handle;
+ // LogStream stream(handle);
+ LogStream(LogTargetHandle handle) :
+ _embedded_resource_mark(),
+ _stream(handle._level, handle._tagset) {}
+
+ // Override of outputStream::write.
+ void write(const char* s, size_t len) { _stream.write(s, len); }
+};
+
+// Support creation of a LogStream without having to provide a LogTarget pointer.
+#define LogStreamHandle(level, ...) LogStreamTemplate<LogLevel::level, LOG_TAGS(__VA_ARGS__)>
+
+template <LogLevelType level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag>
+class LogStreamTemplate : public LogStream {
+public:
+ LogStreamTemplate() : LogStream((LogTargetImpl<level, T0, T1, T2, T3, T4, GuardTag>*)NULL) {}
+};
+
+#endif // SHARE_VM_LOGGING_LOGSTREAM_INLINE_HPP
--- a/hotspot/src/share/vm/memory/binaryTreeDictionary.cpp Tue Apr 05 09:05:19 2016 +0200
+++ b/hotspot/src/share/vm/memory/binaryTreeDictionary.cpp Tue Apr 05 11:00:22 2016 +0200
@@ -25,6 +25,7 @@
#include "precompiled.hpp"
#include "gc/cms/allocationStats.hpp"
#include "gc/shared/spaceDecorator.hpp"
+#include "logging/logStream.inline.hpp"
#include "memory/binaryTreeDictionary.hpp"
#include "memory/freeBlockDictionary.hpp"
#include "memory/freeList.hpp"
@@ -1190,10 +1191,10 @@
// Does walking the tree 3 times hurt?
set_tree_surplus(splitSurplusPercent);
set_tree_hints();
- Log(gc, freelist, stats) log;
- if (log.is_trace()) {
- ResourceMark rm;
- report_statistics(log.trace_stream());
+ LogTarget(Trace, gc, freelist, stats) log;
+ if (log.is_enabled()) {
+ LogStream out(log);
+ report_statistics(&out);
}
clear_tree_census();
}
@@ -1232,27 +1233,26 @@
FreeList_t* total() { return &_total; }
size_t total_free() { return _total_free; }
void do_list(FreeList<Chunk_t>* fl) {
- Log(gc, freelist, census) log;
- outputStream* out = log.debug_stream();
+ LogStreamHandle(Debug, gc, freelist, census) out;
+
if (++_print_line >= 40) {
- ResourceMark rm;
- FreeList_t::print_labels_on(out, "size");
+ FreeList_t::print_labels_on(&out, "size");
_print_line = 0;
}
- fl->print_on(out);
+ fl->print_on(&out);
_total_free += fl->count() * fl->size();
total()->set_count(total()->count() + fl->count());
}
#if INCLUDE_ALL_GCS
void do_list(AdaptiveFreeList<Chunk_t>* fl) {
- Log(gc, freelist, census) log;
- outputStream* out = log.debug_stream();
+ LogStreamHandle(Debug, gc, freelist, census) out;
+
if (++_print_line >= 40) {
- FreeList_t::print_labels_on(out, "size");
+ FreeList_t::print_labels_on(&out, "size");
_print_line = 0;
}
- fl->print_on(out);
+ fl->print_on(&out);
_total_free += fl->count() * fl->size() ;
total()->set_count( total()->count() + fl->count() );
total()->set_bfr_surp( total()->bfr_surp() + fl->bfr_surp() );
--- a/hotspot/src/share/vm/utilities/internalVMTests.cpp Tue Apr 05 09:05:19 2016 +0200
+++ b/hotspot/src/share/vm/utilities/internalVMTests.cpp Tue Apr 05 11:00:22 2016 +0200
@@ -68,6 +68,10 @@
run_unit_test(TestChunkedList_test);
run_unit_test(JSON_test);
run_unit_test(Test_logtarget);
+ run_unit_test(Test_logstream);
+ run_unit_test(Test_loghandle);
+ run_unit_test(Test_logtargethandle);
+ run_unit_test(Test_log_gctracetime);
run_unit_test(Test_configure_stdout);
run_unit_test(Test_logconfiguration_subscribe);
run_unit_test(Test_log_prefix);
--- a/hotspot/src/share/vm/utilities/ostream.cpp Tue Apr 05 09:05:19 2016 +0200
+++ b/hotspot/src/share/vm/utilities/ostream.cpp Tue Apr 05 11:00:22 2016 +0200
@@ -1097,14 +1097,3 @@
}
#endif
-
-void logStream::write(const char* s, size_t len) {
- if (len > 0 && s[len - 1] == '\n') {
- _current_line.write(s, len - 1);
- _log_func("%s", _current_line.as_string());
- _current_line.reset();
- } else {
- _current_line.write(s, len);
- }
- update_position(s, len);
-}
--- a/hotspot/src/share/vm/utilities/ostream.hpp Tue Apr 05 09:05:19 2016 +0200
+++ b/hotspot/src/share/vm/utilities/ostream.hpp Tue Apr 05 11:00:22 2016 +0200
@@ -246,18 +246,6 @@
void flush() {};
};
-class logStream : public outputStream {
-private:
- stringStream _current_line;
- void (*_log_func)(const char* fmt, ...) ATTRIBUTE_PRINTF(1, 2);
-public:
- void write(const char* s, size_t len);
- logStream(void (*log_func)(const char* fmt, ...)) : _log_func(log_func) {}
- ~logStream() {
- guarantee(_current_line.size() == 0, "Buffer not flushed. Missing call to print_cr()?");
- }
-};
-
void ostream_init();
void ostream_init_log();
void ostream_exit();