# HG changeset patch # User stefank # Date 1459846822 -7200 # Node ID 8707ab133d7bbc4494ee9ac4cfefe4d51d365ba1 # Parent 45e69c7b0bac85a217e0d34f1dca292d0659cdc5# Parent 568ff1f6631c73ddcac76614e705e7b78b87b824 Merge diff -r 45e69c7b0bac -r 8707ab133d7b hotspot/src/share/vm/gc/shared/gcTraceTime.hpp --- 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 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 +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 " SIZE_FORMAT "M(" SIZE_FORMAT "M)" -template -void GCTraceTimeImpl::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 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("%s", start_msg.buffer()); + out.print_cr(" (%.3fs)", TimeHelper::counter_to_seconds(start_counter)); } } -template -void GCTraceTimeImpl::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::template write("%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::template write("%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 -void GCTraceTimeImpl::time_stamp(Ticks& ticks) { +inline void GCTraceTimeImpl::time_stamp(Ticks& ticks) { if (_enabled || _timer != NULL) { ticks.stamp(); } } -template -GCTraceTimeImpl::GCTraceTimeImpl(const char* title, GCTimer* timer, GCCause::Cause gc_cause, bool log_heap_usage) : - _enabled(LogImpl::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 -GCTraceTimeImpl::~GCTraceTimeImpl() { +inline GCTraceTimeImpl::~GCTraceTimeImpl() { Ticks stop_ticks; time_stamp(stop_ticks); if (_enabled) { @@ -145,7 +133,34 @@ } } -#define GCTraceTime(Level, ...) GCTraceTimeImpl +// 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 +GCTraceTimeImplWrapper::GCTraceTimeImplWrapper( + const char* title, GCTimer* timer, GCCause::Cause gc_cause, bool log_heap_usage) + : _impl( + LogTargetHandle::create(), + LogTargetHandle::create(), + 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 +GCTraceTimeImplWrapper::~GCTraceTimeImplWrapper() {} + +#define GCTraceTime(Level, ...) GCTraceTimeImplWrapper #define GCTraceConcTime(Level, ...) GCTraceConcTimeImpl #endif // SHARE_VM_GC_SHARED_GCTRACETIME_INLINE_HPP diff -r 45e69c7b0bac -r 8707ab133d7b hotspot/src/share/vm/logging/log.cpp --- 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 diff -r 45e69c7b0bac -r 8707ab133d7b hotspot/src/share/vm/logging/log.hpp --- 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 +// Forward declaration to decouple this file from the outputStream API. +class outputStream; +outputStream* create_log_stream(LogLevelType level, LogTagSet* tagset); + +template +class LogTargetImpl; + template class LogImpl VALUE_OBJ_CLASS_SPEC { @@ -162,7 +168,10 @@ return is_level(LogLevel::level); \ } \ static outputStream* name##_stream() { \ - return new logStream(write); \ + return create_log_stream(LogLevel::level, &LogTagSetMapping::tagset()); \ + } \ + static LogTargetImpl* name() { \ + return (LogTargetImpl*)NULL; \ } LOG_LEVEL_LIST #undef LOG_LEVEL @@ -190,7 +199,7 @@ } static outputStream* stream() { - return new logStream(&LogImpl::template write); + return create_log_stream(level, &LogTagSetMapping::tagset()); } }; diff -r 45e69c7b0bac -r 8707ab133d7b hotspot/src/share/vm/logging/logHandle.hpp --- /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 + LogHandle(const LogImpl& type_carrier) : + _tagset(&LogTagSetMapping::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 + LogTargetHandle(const LogTargetImpl& type_carrier) : + _level(level), + _tagset(&LogTagSetMapping::tagset()) {} + + template + static LogTargetHandle create() { + return LogTargetHandle(LogTargetImpl()); + } + + 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 diff -r 45e69c7b0bac -r 8707ab133d7b hotspot/src/share/vm/logging/logStream.cpp --- /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); +} + diff -r 45e69c7b0bac -r 8707ab133d7b hotspot/src/share/vm/logging/logStream.hpp --- /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 diff -r 45e69c7b0bac -r 8707ab133d7b hotspot/src/share/vm/logging/logStream.inline.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 + LogStream(const LogTargetImpl& type_carrier) : + _embedded_resource_mark(), + _stream(level, &LogTagSetMapping::tagset()) {} + + // Constructor to support creation from typed (likely NULL) pointer. Mostly used by the logging framework. + // + // LogStream stream(log.debug()); + // LogStream stream((LogTargetImpl*)NULL); + template + LogStream(const LogTargetImpl* type_carrier) : + _embedded_resource_mark(), + _stream(level, &LogTagSetMapping::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 + +template +class LogStreamTemplate : public LogStream { +public: + LogStreamTemplate() : LogStream((LogTargetImpl*)NULL) {} +}; + +#endif // SHARE_VM_LOGGING_LOGSTREAM_INLINE_HPP diff -r 45e69c7b0bac -r 8707ab133d7b hotspot/src/share/vm/memory/binaryTreeDictionary.cpp --- 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* 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* 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() ); diff -r 45e69c7b0bac -r 8707ab133d7b hotspot/src/share/vm/utilities/internalVMTests.cpp --- 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); diff -r 45e69c7b0bac -r 8707ab133d7b hotspot/src/share/vm/utilities/ostream.cpp --- 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); -} diff -r 45e69c7b0bac -r 8707ab133d7b hotspot/src/share/vm/utilities/ostream.hpp --- 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();