--- old/src/hotspot/share/gc/shared/gcTraceTime.hpp 2020-02-24 07:47:40.429082470 +0000 +++ new/src/hotspot/share/gc/shared/gcTraceTime.hpp 2020-02-24 07:47:40.169081051 +0000 @@ -1,5 +1,5 @@ /* - * Copyright (c) 2012, 2019, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2012, 2020, 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 @@ -43,10 +43,11 @@ class GCTimer; +template class GCTraceTimeImpl : public StackObj { private: - LogTargetHandle _out_start; - LogTargetHandle _out_stop; + Handle1 _out_start; + Handle2 _out_stop; bool _enabled; Ticks _start_ticks; const char* _title; @@ -59,18 +60,25 @@ void time_stamp(Ticks& ticks); public: - 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(Handle1 out_start, Handle2 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; + typedef GCTraceTimeImpl handle_t; + const handle_t _impl; public: GCTraceTimeImplWrapper(const char* title, GCTimer* timer = NULL, GCCause::Cause gc_cause = GCCause::_no_gc, bool log_heap_usage = false); - ~GCTraceTimeImplWrapper(); }; +template +class GCAsyncTraceTimeImplWrapper : public StackObj { + typedef GCTraceTimeImpl handle_t; + const handle_t _impl; +public: + GCAsyncTraceTimeImplWrapper(const char* title, GCTimer* timer = NULL, GCCause::Cause gc_cause = GCCause::_no_gc, bool log_heap_usage = false); +}; // 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)" -inline void GCTraceTimeImpl::log_start(jlong start_counter) { +template +inline void GCTraceTimeImpl::log_start(jlong start_counter) { if (_out_start.is_enabled()) { LogStream out(_out_start); @@ -48,7 +49,8 @@ } } -inline void GCTraceTimeImpl::log_stop(jlong start_counter, jlong stop_counter) { +template +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); @@ -72,13 +74,15 @@ out.print_cr(" %.3fms", duration_in_ms); } -inline void GCTraceTimeImpl::time_stamp(Ticks& ticks) { +template +inline void GCTraceTimeImpl::time_stamp(Ticks& ticks) { if (_enabled || _timer != NULL) { ticks.stamp(); } } -inline GCTraceTimeImpl::GCTraceTimeImpl(LogTargetHandle out_start, LogTargetHandle out_stop, const char* title, GCTimer* timer, GCCause::Cause gc_cause, bool log_heap_usage) : +template +inline GCTraceTimeImpl::GCTraceTimeImpl(Handle1 out_start, Handle2 out_stop, const char* title, GCTimer* timer, GCCause::Cause gc_cause, bool log_heap_usage) : _out_start(out_start), _out_stop(out_stop), _enabled(out_stop.is_enabled()), @@ -99,8 +103,8 @@ _timer->register_gc_phase_start(_title, _start_ticks); } } - -inline GCTraceTimeImpl::~GCTraceTimeImpl() { +template +inline GCTraceTimeImpl::~GCTraceTimeImpl() { Ticks stop_ticks; time_stamp(stop_ticks); if (_enabled) { @@ -150,10 +154,23 @@ STATIC_ASSERT(T4 == LogTag::__NO_TAG); // Need to leave at least the last tag for the "start" tag in log_start() } +template +GCAsyncTraceTimeImplWrapper::GCAsyncTraceTimeImplWrapper( + const char* title, GCTimer* timer, GCCause::Cause gc_cause, bool log_heap_usage) + : _impl( + AsyncLogTargetHandle::create(), + AsyncLogTargetHandle::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 --- old/src/hotspot/share/logging/logHandle.hpp 2020-02-24 07:47:41.705089434 +0000 +++ new/src/hotspot/share/logging/logHandle.hpp 2020-02-24 07:47:41.445088015 +0000 @@ -1,5 +1,5 @@ /* - * Copyright (c) 2016, 2019, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2016, 2020, 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 @@ -24,6 +24,7 @@ #ifndef SHARE_LOGGING_LOGHANDLE_HPP #define SHARE_LOGGING_LOGHANDLE_HPP +#include "logging/asynclog.hpp" #include "logging/log.hpp" // Wraps a Log instance and throws away the template information. @@ -70,18 +71,42 @@ // // This can be used to pass a Log instance as a parameter without // polluting the surrounding API with template functions. -class LogTargetHandle { -private: +template +class LogTargetHandleBase { +protected : const LogLevelType _level; LogTagSet* _tagset; + LogTargetHandleBase(LogLevelType level, LogTagSet* tagset) : _level(level), _tagset(tagset) {} + public: - LogTargetHandle(LogLevelType level, LogTagSet* tagset) : _level(level), _tagset(tagset) {} + void print(const char* fmt, ...) ATTRIBUTE_PRINTF(2, 3) { + va_list args; + va_start(args, fmt); + static_cast(this)->print(fmt,args); + va_end(args); + } + + bool is_enabled() const { + return _tagset->is_level(_level); + } + + LogLevelType level() const { + return _level; + } + + LogTagSet* tagset() const { + return _tagset; + } +}; + +class LogTargetHandle : public LogTargetHandleBase { +public: + LogTargetHandle(LogLevelType level, LogTagSet* tagset) : LogTargetHandleBase(level, tagset) {} template LogTargetHandle(const LogTargetImpl& type_carrier) : - _level(level), - _tagset(&LogTagSetMapping::tagset()) {} + LogTargetHandleBase(level, &LogTagSetMapping::tagset()) {} template static LogTargetHandle create() { @@ -94,11 +119,23 @@ _tagset->vwrite(_level, fmt, args); va_end(args); } +}; - bool is_enabled() const { - return _tagset->is_level(_level); +class AsyncLogTargetHandle : public LogTargetHandleBase { +public: + template + AsyncLogTargetHandle(const AsyncLogTargetImpl& type_carrier) : + LogTargetHandleBase(level, &LogTagSetMapping::tagset()) {} + + template + static AsyncLogTargetHandle create() { + return AsyncLogTargetHandle(AsyncLogTargetImpl()); } + void print(const char* fmt, ...) ATTRIBUTE_PRINTF(2, 3) { + DEBUG_ONLY(ShouldNotReachHere()); + } }; + #endif // SHARE_LOGGING_LOGHANDLE_HPP --- old/src/hotspot/share/logging/logMessageBuffer.cpp 2020-02-24 07:47:42.345092930 +0000 +++ new/src/hotspot/share/logging/logMessageBuffer.cpp 2020-02-24 07:47:42.085091509 +0000 @@ -1,5 +1,5 @@ /* - * Copyright (c) 2016, 2018, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2016, 2020, 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 @@ -26,17 +26,9 @@ #include "memory/allocation.inline.hpp" #include "runtime/thread.inline.hpp" -template -static void grow(T*& buffer, size_t& capacity, size_t minimum_length = 0) { - size_t new_size = capacity * 2; - if (new_size < minimum_length) { - new_size = minimum_length; - } - buffer = REALLOC_C_HEAP_ARRAY(T, buffer, new_size, mtLogging); - capacity = new_size; -} -LogMessageBuffer::LogMessageBuffer() : _message_buffer_size(0), +LogMessageBuffer::LogMessageBuffer(Arena* arena) : _arena(arena), + _message_buffer_size(0), _message_buffer_capacity(0), _message_buffer(NULL), _line_count(0), @@ -49,8 +41,13 @@ LogMessageBuffer::~LogMessageBuffer() { if (_allocated) { - FREE_C_HEAP_ARRAY(char, _message_buffer); - FREE_C_HEAP_ARRAY(LogLine, _lines); + if (!_arena) { + FREE_C_HEAP_ARRAY(char, _message_buffer); + FREE_C_HEAP_ARRAY(LogLine, _lines); + } else { + FREE_ARENA_ARRAY(_arena, char, _message_buffer, _message_buffer_capacity); + FREE_ARENA_ARRAY(_arena, LogLine, _lines, _line_capacity); + } } } @@ -61,13 +58,40 @@ void LogMessageBuffer::initialize_buffers() { assert(!_allocated, "buffer already initialized/allocated"); + if (!_arena) { + _message_buffer = NEW_C_HEAP_ARRAY(char, InitialMessageBufferCapacity, mtLogging); + _lines = NEW_C_HEAP_ARRAY(LogLine, InitialLineCapacity, mtLogging); + } + else { + _message_buffer = NEW_ARENA_ARRAY(_arena, char, InitialMessageBufferCapacity); + _lines = NEW_ARENA_ARRAY(_arena, LogLine, InitialLineCapacity); + } + _allocated = true; - _message_buffer = NEW_C_HEAP_ARRAY(char, InitialMessageBufferCapacity, mtLogging); - _lines = NEW_C_HEAP_ARRAY(LogLine, InitialLineCapacity, mtLogging); _message_buffer_capacity = InitialMessageBufferCapacity; _line_capacity = InitialLineCapacity; } +size_t LogMessageBuffer::initial_buffer_size() { + return sizeof(char) * InitialMessageBufferCapacity + + sizeof(LogLine) * InitialLineCapacity; +} + +template +void LogMessageBuffer::grow(T*& buffer, size_t& capacity, size_t minimum_length) { + size_t new_size = capacity * 2; + if (new_size < minimum_length) { + new_size = minimum_length; + } + if (!_arena) { + buffer = REALLOC_C_HEAP_ARRAY(T, buffer, new_size, mtLogging); + } + else { + buffer = REALLOC_ARENA_ARRAY(_arena, T, buffer, capacity, new_size); + } + capacity = new_size; +} + void LogMessageBuffer::Iterator::skip_messages_with_finer_level() { for (; _current_line_index < _message._line_count; _current_line_index++) { if (_message._lines[_current_line_index].level >= _level) { @@ -76,6 +100,46 @@ } } +void LogMessageBuffer::write_n(LogLevelType level, const char * s, size_t len) { + if (!_allocated) { + initialize_buffers(); + } + + if (level > _least_detailed_level) { + _least_detailed_level = level; + } + + size_t written; + for (int attempts = 0; attempts < 2; attempts++) { + written = 0; + size_t remain = _message_buffer_capacity - _message_buffer_size; + char* curr = _message_buffer + _message_buffer_size; + + if (_prefix_fn != NULL) { + written += _prefix_fn(curr, remain); + } + curr += written; + + written += len + 1; // add tailing zero + if (written > remain) { + grow(_message_buffer, _message_buffer_capacity, _message_buffer_size + written); + continue; + } + + strncpy(curr, s, len); + curr[len] = '\0'; + break; + } + + if (_line_count == _line_capacity) { + grow(_lines, _line_capacity); + } + _lines[_line_count].level = level; + _lines[_line_count].message_offset = _message_buffer_size; + _message_buffer_size += written; + _line_count++; +} + void LogMessageBuffer::write(LogLevelType level, const char* fmt, ...) { va_list args; va_start(args, fmt); --- old/src/hotspot/share/logging/logMessageBuffer.hpp 2020-02-24 07:47:42.985096429 +0000 +++ new/src/hotspot/share/logging/logMessageBuffer.hpp 2020-02-24 07:47:42.725095008 +0000 @@ -28,8 +28,9 @@ #include "logging/logLevel.hpp" #include "memory/allocation.hpp" -class LogMessageBuffer : public StackObj { - friend class LogMessageTest; +class LogMessageBuffer : public CHeapObj { + friend class LogMessageTest_nwrite_test_vm_Test; + protected: struct LogLine { LogLevelType level; @@ -38,6 +39,7 @@ static const size_t InitialLineCapacity = 10; static const size_t InitialMessageBufferCapacity = 1024; + Arena* _arena; size_t _message_buffer_size; size_t _message_buffer_capacity; char* _message_buffer; @@ -51,16 +53,18 @@ size_t (*_prefix_fn)(char*, size_t); void initialize_buffers(); + template + void grow(T*& buffer, size_t& capacity, size_t minimum_length = 0); private: - // Forbid copy assignment and copy constructor. - void operator=(const LogMessageBuffer& ref) {} - LogMessageBuffer(const LogMessageBuffer& ref) {} + NONCOPYABLE(LogMessageBuffer); public: - LogMessageBuffer(); + LogMessageBuffer(Arena* arena = NULL); ~LogMessageBuffer(); + static size_t initial_buffer_size(); + class Iterator { private: const LogMessageBuffer& _message; @@ -97,6 +101,10 @@ void reset(); + Arena* arena() const { + return _arena; + } + LogLevelType least_detailed_level() const { return _least_detailed_level; } @@ -115,6 +123,8 @@ _prefix_fn = prefix_fn; } + void write_n(LogLevelType level, const char * s, size_t written); + ATTRIBUTE_PRINTF(3, 4) void write(LogLevelType level, const char* fmt, ...); --- old/src/hotspot/share/logging/logStream.cpp 2020-02-24 07:47:43.621099908 +0000 +++ new/src/hotspot/share/logging/logStream.cpp 2020-02-24 07:47:43.361098486 +0000 @@ -25,6 +25,8 @@ #include "precompiled.hpp" #include "logging/log.hpp" #include "logging/logStream.hpp" +#include "logging/logMessageBuffer.hpp" +#include "logging/logAsyncFlusher.hpp" LogStream::LineBuffer::LineBuffer() : _buf(_smallbuf), _cap(sizeof(_smallbuf)), _pos(0) @@ -104,20 +106,44 @@ void LogStream::write(const char* s, size_t len) { if (len > 0 && s[len - 1] == '\n') { _current_line.append(s, len - 1); // omit the newline. - _log_handle.print("%s", _current_line.buffer()); + if (!_async_log) { + _log_handle.print("%s", _current_line.buffer()); + } else { + if (!_async_buffer) { + _async_buffer = new (mtLogging)LogMessageBuffer(); + } + _async_buffer->write_n(_log_handle.level(), _current_line.buffer(), _current_line.size()); + } _current_line.reset(); } else { _current_line.append(s, len); } + update_position(s, len); } // Destructor writes any unfinished output left in the line buffer. LogStream::~LogStream() { - if (_current_line.is_empty() == false) { - _log_handle.print("%s", _current_line.buffer()); + if (!_current_line.is_empty()) { + if (!_async_log) { + _log_handle.print("%s", _current_line.buffer()); + } + else { + if (!_async_buffer) { + _async_buffer = new (mtLogging)LogMessageBuffer(); + } + _async_buffer->write_n(_log_handle.level(), _current_line.buffer(), _current_line.size()); + } _current_line.reset(); } -} + if (_async_log && _async_buffer) { + LogAsyncFlusher* flusher = LogAsyncFlusher::instance(); + flusher->enqueue(_log_handle.tagset(), _async_buffer); + } +} +void LogStream::create_async_buffer() { + Arena* arena = new (mtLogging)Arena(mtLogging, LogMessageBuffer::initial_buffer_size()); + _async_buffer = new (mtLogging)LogMessageBuffer(arena); +} --- old/src/hotspot/share/logging/logStream.hpp 2020-02-24 07:47:44.261103412 +0000 +++ new/src/hotspot/share/logging/logStream.hpp 2020-02-24 07:47:44.001101988 +0000 @@ -1,5 +1,5 @@ /* - * Copyright (c) 2016, 2019, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2016, 2020, 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 @@ -27,9 +27,10 @@ #include "logging/log.hpp" #include "logging/logHandle.hpp" -#include "memory/resourceArea.hpp" #include "utilities/ostream.hpp" +template +class AsyncLogTargetImpl; class LogStream : public outputStream { friend class LogStreamTest_TestLineBufferAllocation_test_vm_Test; // see test/native/logging/test_logStream.cpp @@ -52,14 +53,20 @@ const char* buffer() const { return _buf; } void append(const char* s, size_t len); void reset(); + size_t size() const { return _pos; } }; LineBuffer _current_line; LogTargetHandle _log_handle; + bool _async_log; + LogMessageBuffer* _async_buffer; + // Prevent operator new for LogStream. static void* operator new (size_t); static void* operator new[] (size_t); + void create_async_buffer(); + public: // Constructor to support creation from a LogTarget instance. // @@ -67,7 +74,7 @@ // LogStreamBase(log) stream; template LogStream(const LogTargetImpl& type_carrier) : - _log_handle(level, &LogTagSetMapping::tagset()) {} + _log_handle(level, &LogTagSetMapping::tagset()), _async_log(false) {} // Constructor to support creation from typed (likely NULL) pointer. Mostly used by the logging framework. // @@ -76,7 +83,7 @@ // LogStreamBase stream((LogTargetImpl*)NULL); template LogStream(const LogTargetImpl* type_carrier) : - _log_handle(level, &LogTagSetMapping::tagset()) {} + _log_handle(level, &LogTagSetMapping::tagset()), _async_log(false) {} // Destructor writes any unfinished output left in the line buffer. ~LogStream(); @@ -86,12 +93,23 @@ // LogTarget(Debug, gc) log; // LogTargetHandle(log) handle; // LogStreamBase stream(handle); - LogStream(LogTargetHandle handle) : _log_handle(handle) {} + LogStream(LogTargetHandle handle) : _log_handle(handle), _async_log(false) {} // Constructor to support creation from a log level and tagset. // // LogStreamBase(level, tageset); - LogStream(LogLevelType level, LogTagSet* tagset) : _log_handle(level, tagset) {} + LogStream(LogLevelType level, LogTagSet* tagset) : _log_handle(level, tagset), _async_log(false) {} + + template + LogStream(const AsyncLogTargetImpl& type_carrier) : + _log_handle(level, &LogTagSetMapping::tagset()), _async_log(true), _async_buffer(NULL) {} + + template + LogStream(const AsyncLogTargetImpl* type_carrier) : + _log_handle(level, &LogTagSetMapping::tagset()), _async_log(true), _async_buffer(NULL) {} + + LogStream(AsyncLogTargetHandle h) : + _log_handle(h.level(), h.tagset()), _async_log(true), _async_buffer(NULL) {} void write(const char* s, size_t len); }; --- old/src/hotspot/share/runtime/globals.hpp 2020-02-24 07:47:44.901106917 +0000 +++ new/src/hotspot/share/runtime/globals.hpp 2020-02-24 07:47:44.641105493 +0000 @@ -2493,6 +2493,10 @@ product(bool, UseEmptySlotsInSupers, true, \ "Allow allocating fields in empty slots of super-classes") \ \ + product(intx, LogAsyncInterval, 200, \ + "Milliseconds between asynchronous log flushing") \ + \ + // Interface macros --- old/src/hotspot/share/runtime/init.cpp 2020-02-24 07:47:45.557110512 +0000 +++ new/src/hotspot/share/runtime/init.cpp 2020-02-24 07:47:45.297109087 +0000 @@ -32,6 +32,7 @@ #endif #include "interpreter/bytecodes.hpp" #include "logging/log.hpp" +#include "logging/logAsyncFlusher.hpp" #include "logging/logTag.hpp" #include "memory/universe.hpp" #include "prims/methodHandles.hpp" @@ -119,6 +120,7 @@ if (status != JNI_OK) return status; + LogAsyncFlusher::initialize(); gc_barrier_stubs_init(); // depends on universe_init, must be before interpreter_init interpreter_init(); // before any methods loaded invocationCounter_init(); // before any methods loaded --- old/src/hotspot/share/utilities/ostream.cpp 2020-02-24 07:47:46.197114022 +0000 +++ new/src/hotspot/share/utilities/ostream.cpp 2020-02-24 07:47:45.933112574 +0000 @@ -25,6 +25,7 @@ #include "precompiled.hpp" #include "jvm.h" #include "compiler/compileLog.hpp" +#include "logging/logAsyncFlusher.hpp" #include "memory/allocation.inline.hpp" #include "oops/oop.inline.hpp" #include "runtime/arguments.hpp" @@ -725,6 +726,8 @@ // called by ostream_abort() after a fatal error. // void defaultStream::finish_log() { + LogAsyncFlusher::cleanup(); + xmlStream* xs = _outer_xmlStream; xs->done("tty"); @@ -939,6 +942,8 @@ // ostream_abort() is called by os::abort() when VM is about to die. void ostream_abort() { + LogAsyncFlusher::cleanup(); + // Here we can't delete tty, just flush its output if (tty) tty->flush(); --- old/test/hotspot/gtest/logging/test_logMessageTest.cpp 2020-02-24 07:47:46.841117556 +0000 +++ new/test/hotspot/gtest/logging/test_logMessageTest.cpp 2020-02-24 07:47:46.581116130 +0000 @@ -215,6 +215,39 @@ << "error in prefixed output"; } +TEST_VM_F(LogMessageTest, nwrite) { + const char* msg = "The quick brown fox jumps over the lazy dog"; + const char* msg2 = "test-without-prefix"; + Arena* arena = new (mtLogging)Arena(mtLogging); + LogMessageBuffer buf(arena); + + buf.set_prefix(dummy_prefixer); + size_t len = strlen(msg); + // keep writing until reallocation + while (buf._message_buffer_size + < LogMessageBuffer::InitialMessageBufferCapacity * 3) { + buf.write_n(LogLevel::Trace, msg, len); + } + + buf.set_prefix(NULL); + len = strlen(msg2); + buf.write_n(LogLevel::Trace, msg2, len); + _log.write(buf); + + const char* expected[] = { + "] some prefix: The quick brown fox jumps over the lazy dog", + "] some prefix: The quick brown fox jumps over the lazy dog", + "] some prefix: The quick brown fox jumps over the lazy dog", + "] test-without-prefix", + NULL + }; + + EXPECT_TRUE(file_contains_substrings_in_order(_level_filename[LogLevel::Trace], expected)) + << "error in prefixed output"; + + delete arena; +} + TEST_VM_F(LogMessageTest, scoped_messages) { { LogMessage(logging) msg; --- /dev/null 2020-02-13 04:30:26.348000000 +0000 +++ new/src/hotspot/share/logging/asynclog.hpp 2020-02-24 07:47:47.217119620 +0000 @@ -0,0 +1,171 @@ +/* + * Copyright (c) 2020, 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_LOGGING_ASYNCLOG_HPP +#define SHARE_LOGGING_ASYNCLOG_HPP +#include "logging/logLevel.hpp" +#include "logging/logPrefix.hpp" +#include "logging/logTagSet.hpp" +#include "logging/logTag.hpp" +#include "logging/logAsyncFlusher.hpp" +#include "logging/logMessageBuffer.hpp" + +#define asynclog_error(...) (!asynclog_is_enabled(Error, __VA_ARGS__)) ? (void)0 : AsyncLogImpl().write +#define asynclog_warning(...) (!asynclog_is_enabled(Warning, __VA_ARGS__)) ? (void)0 : AsyncLogImpl().write +#define asynclog_info(...) (!asynclog_is_enabled(Info, __VA_ARGS__)) ? (void)0 : AsyncLogImpl().write +#define asynclog_debug(...) (!asynclog_is_enabled(Debug, __VA_ARGS__)) ? (void)0 : AsyncLogImpl().write +#define asynclog_trace(...) (!asynclog_is_enabled(Trace, __VA_ARGS__)) ? (void)0 : AsyncLogImpl().write + +// Macros for logging that should be excluded in product builds. +// Available for levels Info, Debug and Trace. Includes test macro that +// evaluates to false in product builds. +#ifndef PRODUCT +#define asynclog_develop_info(...) (!asynclog_is_enabled(Info, __VA_ARGS__)) ? (void)0 : AsyncLogImpl().write +#define asynclog_develop_debug(...) (!asynclog_is_enabled(Debug, __VA_ARGS__)) ? (void)0 : AsyncLogImpl().write +#define asynclog_develop_trace(...) (!asynclog_is_enabled(Trace, __VA_ARGS__)) ? (void)0 : AsyncLogImpl().write +#define asynclog_develop_is_enabled(level, ...) asynclog_is_enabled(level, __VA_ARGS__) +#else +#define DUMMY_ARGUMENT_CONSUMER(...) +#define asynclog_develop_info(...) DUMMY_ARGUMENT_CONSUMER +#define asynclog_develop_debug(...) DUMMY_ARGUMENT_CONSUMER +#define asynclog_develop_trace(...) DUMMY_ARGUMENT_CONSUMER +#define asynclog_develop_is_enabled(...) false +#endif + +// Convenience macro to test if the logging is enabled on the specified level for given tags. +#define asynclog_is_enabled(level, ...) (AsyncLogImpl::is_level(LogLevel::level)) + +#define AsyncLog(...) AsyncLogImpl +#define AsyncLogTarget(level, ...) AsyncLogTargetImpl + +template +class AsyncLogTargetImpl; + +class Arena; + +template +class AsyncLogImpl { + private: + Arena* _arena; + LogMessageBuffer* _buf; + void create_async_buffer() { + Arena* arena = new (mtLogging)Arena(mtLogging, LogMessageBuffer::initial_buffer_size()); + _buf = new (mtLogging)LogMessageBuffer(arena); + _buf->set_prefix(LogPrefix::prefix); + } + + public: + // Make sure no more than the maximum number of tags have been given. + // The GuardTag allows this to be detected if/when it happens. If the GuardTag + // is not __NO_TAG, the number of tags given exceeds the maximum allowed. + STATIC_ASSERT(GuardTag == LogTag::__NO_TAG); // Number of logging tags exceeds maximum supported! + + AsyncLogImpl() : _arena(NULL), _buf(NULL) { + } + + ~AsyncLogImpl() { + if (_buf != NULL) { + LogAsyncFlusher* flusher = LogAsyncFlusher::instance(); + flusher->enqueue(&LogTagSetMapping::tagset(), _buf); + } + } + + static bool is_level(LogLevelType level) { + return LogTagSetMapping::tagset().is_level(level); + } + + ATTRIBUTE_PRINTF(3, 4) + void write(LogLevelType level, const char* fmt, ...) { + va_list args; + va_start(args, fmt); + vwrite(level, fmt, args); + va_end(args); + } + + // to be implemented or deleted. + void write(const LogMessageBuffer& msg); + + template + ATTRIBUTE_PRINTF(2, 3) + void write(const char* fmt, ...) { + va_list args; + va_start(args, fmt); + vwrite(Level, fmt, args); + va_end(args); + } + + ATTRIBUTE_PRINTF(3, 0) + void vwrite(LogLevelType level, const char* fmt, va_list args) { + if (!_buf) create_async_buffer(); + _buf->vwrite(level, fmt, args); + } + +#define LOG_LEVEL(level, name) ATTRIBUTE_PRINTF(2, 0) \ + AsyncLogImpl& v##name(const char* fmt, va_list args) { \ + vwrite(LogLevel::level, fmt, args); \ + return *this; \ + } \ + AsyncLogImpl& name(const char* fmt, ...) ATTRIBUTE_PRINTF(2, 3) { \ + va_list args; \ + va_start(args, fmt); \ + vwrite(LogLevel::level, fmt, args); \ + va_end(args); \ + return *this; \ + } \ + static bool is_##name() { \ + return is_level(LogLevel::level); \ + } \ + static AsyncLogTargetImpl* name() { \ + return (AsyncLogTargetImpl*)NULL; \ + } + LOG_LEVEL_LIST +#undef LOG_LEVEL +}; + +// Combines logging tags and a logging level. +template +class AsyncLogTargetImpl { +public: + // Empty constructor to avoid warnings on MSVC about unused variables + // when the log instance is only used for static functions. + AsyncLogTargetImpl() { + } + + static bool is_enabled() { + return AsyncLogImpl::is_level(level); + } + + static void print(const char* fmt, ...) ATTRIBUTE_PRINTF(1, 2) { + AsyncLogImpl impl; + va_list args; + + va_start(args, fmt); + impl.vwrite(level, fmt, args); + va_end(args); + } + +}; + +#endif // SHARE_LOGGING_ASYNCLOG_HPP --- /dev/null 2020-02-13 04:30:26.348000000 +0000 +++ new/src/hotspot/share/logging/logAsyncFlusher.cpp 2020-02-24 07:47:47.881123267 +0000 @@ -0,0 +1,78 @@ +/* + * Copyright (c) 2020, 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/logAsyncFlusher.hpp" +#include "logging/logHandle.hpp" +#include "logging/logMessageBuffer.hpp" + +LogAsyncFlusher::~LogAsyncFlusher() { + disenroll(); + flush(); +} + +void LogAsyncFlusher::task() { + LinkedListImpl logs; + { + MutexLocker ml(&_lock, Mutex::_no_safepoint_check_flag); + _fifo.pop_all(&logs); + } + + LinkedListIterator it(logs.head()); + while (!it.is_empty()) { + AsyncLogMessage* e = it.next(); + LogTagSet* tagset = e->tagset(); + LogMessageBuffer* buf = e->buffer(); + Arena* arena; + if (buf != NULL) { + tagset->log(*buf); + arena = buf->arena(); + delete buf; + delete arena; + } + } +} + +void LogAsyncFlusher::enqueue(LogTagSet* tagset, LogMessageBuffer* buf) { + MutexLocker ml(&_lock, Mutex::_no_safepoint_check_flag); + _fifo.push(AsyncLogMessage::create(tagset, buf)); +} + +LogAsyncFlusher* LogAsyncFlusher::_instance = NULL; + +void LogAsyncFlusher::initialize() { + if (!_instance) { + _instance = new (mtLogging)LogAsyncFlusher(LogAsyncInterval); + } +} + +void LogAsyncFlusher::cleanup() { + if (_instance != NULL) { + delete _instance; + _instance = NULL; + } +} + +LogAsyncFlusher* LogAsyncFlusher::instance() { + return _instance; +} --- /dev/null 2020-02-13 04:30:26.348000000 +0000 +++ new/src/hotspot/share/logging/logAsyncFlusher.hpp 2020-02-24 07:47:48.541126895 +0000 @@ -0,0 +1,103 @@ +/* + * Copyright (c) 2020, 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_LOGGING_ASYNC_FLUSHER_HPP +#define SHARE_LOGGING_ASYNC_FLUSHER_HPP + +#include "memory/resourceArea.hpp" +#include "runtime/mutexLocker.hpp" +#include "runtime/task.hpp" +#include "utilities/linkedlist.hpp" +#include "utilities/pair.hpp" + +template +class LinkedListFIFO : private LinkedListImpl { + private: + LinkedListNode* _tail; + + // this is not a generic FIFO, template parameter is only for testing. + public: + LinkedListFIFO() : _tail(NULL) {} + void push(const E& e) { + if (!_tail) + _tail = this->add(e); + else + _tail = this->insert_after(e, _tail); + } + + void pop_all(LinkedList* logs) { + logs->move(static_cast* >(this)); + _tail = NULL; + } +}; + +class LogMessageBuffer; +class LogTagSet; +class AsyncLogMessage : private Pair { + AsyncLogMessage(LogTagSet* t, LogMessageBuffer* b) + : Pair(t, b) {} + +public: + static AsyncLogMessage create(LogTagSet* t, LogMessageBuffer* b) { + return AsyncLogMessage(t, b); + } + + bool equals(const AsyncLogMessage& o) const { + return first == o.first && second == o.second; + } + + LogTagSet* tagset() { return first; } + LogMessageBuffer* buffer() { return second; } +}; + +typedef LinkedListFIFO AsyncLogFIFO; + +class LogAsyncFlusher : public PeriodicTask { + friend class AsyncLogTest_flusher_test_vm_Test; + private: + static LogAsyncFlusher* _instance; + Mutex _lock; + AsyncLogFIFO _fifo; + + LogAsyncFlusher(size_t interval/*ms*/) : PeriodicTask(interval), + _lock(Mutex::tty, "logAsyncFlusher", + Mutex::_allow_vm_block_flag, Mutex::_safepoint_check_never) { + this->enroll(); + } + + ~LogAsyncFlusher(); + + public: + void enqueue(LogTagSet* tagset, LogMessageBuffer* buf); + + virtual void task(); + void flush() { task(); } + + // none of following functions are thread-safe. + // Meyer's singleton is not thread-safe until C++11. + static void initialize(); + static void cleanup(); + static LogAsyncFlusher* instance(); +}; + +#endif // SHARE_LOGGING_ASYNC_FLUSHER_HPP --- /dev/null 2020-02-13 04:30:26.348000000 +0000 +++ new/test/hotspot/gtest/logging/test_asynclog.cpp 2020-02-24 07:47:49.201130525 +0000 @@ -0,0 +1,129 @@ +/* + * Copyright (c) 2020, 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 "logTestFixture.hpp" +#include "logTestUtils.inline.hpp" +#include "logging/asynclog.hpp" +#include "logging/logAsyncFlusher.hpp" +#include "runtime/interfaceSupport.inline.hpp" +#include "runtime/vmOperations.hpp" +#include "runtime/vmThread.hpp" +#include "unittest.hpp" + + +class AsyncLogTest : public LogTestFixture { + protected: + void verify_stream(outputStream* stream); +}; + +void AsyncLogTest::verify_stream(outputStream* stream) { +} + +TEST_VM_F(AsyncLogTest, fifo) { + LinkedListFIFO fifo; + LinkedListImpl result; + + fifo.push(1); + fifo.pop_all(&result); + EXPECT_EQ(result.size(), (size_t)1); + EXPECT_EQ(*(result.head()->data()), 1); + result.clear(); + + fifo.push(2); + fifo.push(1); + fifo.pop_all(&result); + EXPECT_EQ(result.size(), (size_t)2); + EXPECT_EQ(*(result.head()->data()), 2); + EXPECT_EQ(*(result.head()->next()->data()), 1); + result.clear(); + + const int N = 1000; + for (int i=0; i it(result.head()); + for (int i=0; iprint_cr("LogStreamWithAsyncLogImpl"); + os->print_cr("LogStreamWithAsyncLogImpl secondline"); + + //multi-lines + os->print("logStream msg1-"); + os->print("msg2-"); + os->print("msg3\n"); + os->print_cr("logStream newline"); + + test_asynclog_raw(); + } + + void test_asynclog_raw() { + AsyncLog(logging) logger; +#define LOG_LEVEL(level, name) logger.name("1" #level); +LOG_LEVEL_LIST +#undef LOG_LEVEL + + AsyncLogTarget(Trace, logging) t; + AsyncLogTarget(Debug, logging) d; + EXPECT_FALSE(t.is_enabled()); + EXPECT_TRUE(d.is_enabled()); + + d.print("AsyncLogTarget.print = %d", 1); + asynclog_trace(logging)("log_trace-test"); + asynclog_debug(logging)("log_debug-test"); + } +}; + +TEST_VM_F(AsyncLogTest, asynclog) { + set_log_config(TestLogFileName, "logging=debug"); + + VM_TestFlusher op; + ThreadInVMfromNative invm(JavaThread::current()); + VMThread::execute(&op); + + LogAsyncFlusher::cleanup(); + EXPECT_TRUE(file_contains_substring(TestLogFileName, "LogStreamWithAsyncLogImpl")); + EXPECT_TRUE(file_contains_substring(TestLogFileName, "logStream msg1-msg2-msg3")); + EXPECT_TRUE(file_contains_substring(TestLogFileName, "logStream newline")); + + EXPECT_TRUE(file_contains_substring(TestLogFileName, "1Debug")); + EXPECT_TRUE(file_contains_substring(TestLogFileName, "1Info")); + EXPECT_TRUE(file_contains_substring(TestLogFileName, "1Warning")); + EXPECT_TRUE(file_contains_substring(TestLogFileName, "1Error")); + EXPECT_FALSE(file_contains_substring(TestLogFileName, "1Trace")); // trace message is masked out + + EXPECT_TRUE(file_contains_substring(TestLogFileName, "AsyncLogTarget.print = 1")); + EXPECT_FALSE(file_contains_substring(TestLogFileName, "log_trace-test")); // trace message is masked out + EXPECT_TRUE(file_contains_substring(TestLogFileName, "log_debug-test")); +}