diff --git a/src/hotspot/share/logging/logAsyncWriter.cpp b/src/hotspot/share/logging/logAsyncWriter.cpp index e7c9ff8c7f9..e5099b70858 100644 --- a/src/hotspot/share/logging/logAsyncWriter.cpp +++ b/src/hotspot/share/logging/logAsyncWriter.cpp @@ -25,6 +25,7 @@ #include "logging/logAsyncWriter.hpp" #include "logging/logConfiguration.hpp" #include "logging/logFileOutput.hpp" +#include "logging/logFileStreamOutput.hpp" #include "logging/logHandle.hpp" #include "runtime/atomic.hpp" #include "runtime/os.inline.hpp" @@ -56,7 +57,7 @@ void AsyncLogWriter::enqueue_locked(const AsyncLogMessage& msg) { _lock.notify(); } -void AsyncLogWriter::enqueue(LogFileOutput& output, const LogDecorations& decorations, const char* msg) { +void AsyncLogWriter::enqueue(LogFileStreamOutput& output, const LogDecorations& decorations, const char* msg) { AsyncLogMessage m(&output, decorations, os::strdup(msg)); { // critical area @@ -67,7 +68,7 @@ void AsyncLogWriter::enqueue(LogFileOutput& output, const LogDecorations& decora // LogMessageBuffer consists of a multiple-part/multiple-line messsage. // The lock here guarantees its integrity. -void AsyncLogWriter::enqueue(LogFileOutput& output, LogMessageBuffer::Iterator msg_iterator) { +void AsyncLogWriter::enqueue(LogFileStreamOutput& output, LogMessageBuffer::Iterator msg_iterator) { AsyncLogLocker locker; for (; !msg_iterator.is_at_end(); msg_iterator++) { @@ -95,7 +96,7 @@ class AsyncLogMapIterator { public: AsyncLogMapIterator(AsyncLogBuffer& logs) :_logs(logs) {} - bool do_entry(LogFileOutput* output, uint32_t* counter) { + bool do_entry(LogFileStreamOutput* output, uint32_t* counter) { using none = LogTagSetMapping; if (*counter > 0) { diff --git a/src/hotspot/share/logging/logAsyncWriter.hpp b/src/hotspot/share/logging/logAsyncWriter.hpp index 1d8e4d26e67..858dd6ddbac 100644 --- a/src/hotspot/share/logging/logAsyncWriter.hpp +++ b/src/hotspot/share/logging/logAsyncWriter.hpp @@ -25,10 +25,10 @@ #define SHARE_LOGGING_LOGASYNCWRITER_HPP #include "logging/log.hpp" #include "logging/logDecorations.hpp" -#include "logging/logFileOutput.hpp" #include "logging/logMessageBuffer.hpp" #include "memory/resourceArea.hpp" #include "runtime/nonJavaThread.hpp" +#include "runtime/semaphore.hpp" #include "utilities/hashtable.hpp" #include "utilities/linkedlist.hpp" @@ -90,25 +90,28 @@ class LinkedListDeque : private LinkedListImpl { } }; +// Forward declaration +class LogFileStreamOutput; + class AsyncLogMessage { - LogFileOutput* _output; + LogFileStreamOutput* _output; const LogDecorations _decorations; char* _message; public: - AsyncLogMessage(LogFileOutput* output, const LogDecorations& decorations, char* msg) + AsyncLogMessage(LogFileStreamOutput* output, const LogDecorations& decorations, char* msg) : _output(output), _decorations(decorations), _message(msg) {} // placeholder for LinkedListImpl. bool equals(const AsyncLogMessage& o) const { return false; } - LogFileOutput* output() const { return _output; } + LogFileStreamOutput* output() const { return _output; } const LogDecorations& decorations() const { return _decorations; } char* message() const { return _message; } }; typedef LinkedListDeque AsyncLogBuffer; -typedef KVHashtable AsyncLogMap; +typedef KVHashtable AsyncLogMap; // // ASYNC LOGGING SUPPORT @@ -163,8 +166,8 @@ class AsyncLogWriter : public NonJavaThread { } public: - void enqueue(LogFileOutput& output, const LogDecorations& decorations, const char* msg); - void enqueue(LogFileOutput& output, LogMessageBuffer::Iterator msg_iterator); + void enqueue(LogFileStreamOutput& output, const LogDecorations& decorations, const char* msg); + void enqueue(LogFileStreamOutput& output, LogMessageBuffer::Iterator msg_iterator); static AsyncLogWriter* instance(); static void initialize(); diff --git a/src/hotspot/share/logging/logFileOutput.cpp b/src/hotspot/share/logging/logFileOutput.cpp index 856907f8be4..4b8065f686e 100644 --- a/src/hotspot/share/logging/logFileOutput.cpp +++ b/src/hotspot/share/logging/logFileOutput.cpp @@ -305,7 +305,9 @@ int LogFileOutput::write_blocking(const LogDecorations& decorations, const char* return 0; } - int written = LogFileStreamOutput::write(decorations, msg); + int written = write_internal(decorations, msg); + // Need to flush to the filesystem before should_rotate() + written = flush() ? written : -1; if (written > 0) { _current_size += written; diff --git a/src/hotspot/share/logging/logFileOutput.hpp b/src/hotspot/share/logging/logFileOutput.hpp index 9b22969368e..0932a9402c2 100644 --- a/src/hotspot/share/logging/logFileOutput.hpp +++ b/src/hotspot/share/logging/logFileOutput.hpp @@ -85,7 +85,7 @@ class LogFileOutput : public LogFileStreamOutput { virtual bool initialize(const char* options, outputStream* errstream); virtual int write(const LogDecorations& decorations, const char* msg); virtual int write(LogMessageBuffer::Iterator msg_iterator); - int write_blocking(const LogDecorations& decorations, const char* msg); + virtual int write_blocking(const LogDecorations& decorations, const char* msg); virtual void force_rotate(); virtual void describe(outputStream* out); diff --git a/src/hotspot/share/logging/logFileStreamOutput.cpp b/src/hotspot/share/logging/logFileStreamOutput.cpp index 8ce465ed1ed..b1133c30dd3 100644 --- a/src/hotspot/share/logging/logFileStreamOutput.cpp +++ b/src/hotspot/share/logging/logFileStreamOutput.cpp @@ -23,6 +23,7 @@ */ #include "precompiled.hpp" #include "jvm.h" +#include "logging/logAsyncWriter.hpp" #include "logging/logDecorators.hpp" #include "logging/logDecorations.hpp" #include "logging/logFileStreamOutput.hpp" @@ -117,31 +118,47 @@ bool LogFileStreamOutput::flush() { total += result; \ } -int LogFileStreamOutput::write(const LogDecorations& decorations, const char* msg) { +int LogFileStreamOutput::write_internal(const LogDecorations& decorations, const char* msg) { + int written = 0; const bool use_decorations = !_decorators.is_empty(); - int written = 0; - FileLocker flocker(_stream); if (use_decorations) { WRITE_LOG_WITH_RESULT_CHECK(write_decorations(decorations), written); WRITE_LOG_WITH_RESULT_CHECK(jio_fprintf(_stream, " "), written); } WRITE_LOG_WITH_RESULT_CHECK(jio_fprintf(_stream, "%s\n", msg), written); + return written; +} + +int LogFileStreamOutput::write_blocking(const LogDecorations& decorations, const char* msg) { + int written = write_internal(decorations, msg); + return flush() ? written : -1; +} + +int LogFileStreamOutput::write(const LogDecorations& decorations, const char* msg) { + AsyncLogWriter* aio_writer = AsyncLogWriter::instance(); + if (aio_writer != nullptr) { + aio_writer->enqueue(*this, decorations, msg); + return 0; + } + + FileLocker flocker(_stream); + int written = write_internal(decorations, msg); return flush() ? written : -1; } int LogFileStreamOutput::write(LogMessageBuffer::Iterator msg_iterator) { - const bool use_decorations = !_decorators.is_empty(); + AsyncLogWriter* aio_writer = AsyncLogWriter::instance(); + if (aio_writer != nullptr) { + aio_writer->enqueue(*this, msg_iterator); + return 0; + } int written = 0; FileLocker flocker(_stream); for (; !msg_iterator.is_at_end(); msg_iterator++) { - if (use_decorations) { - WRITE_LOG_WITH_RESULT_CHECK(write_decorations(msg_iterator.decorations()), written); - WRITE_LOG_WITH_RESULT_CHECK(jio_fprintf(_stream, " "), written); - } - WRITE_LOG_WITH_RESULT_CHECK(jio_fprintf(_stream, "%s\n", msg_iterator.message()), written); + written += write_internal(msg_iterator.decorations(), msg_iterator.message()); } return flush() ? written : -1; diff --git a/src/hotspot/share/logging/logFileStreamOutput.hpp b/src/hotspot/share/logging/logFileStreamOutput.hpp index c4a0db7355d..cc0f5f31c7d 100644 --- a/src/hotspot/share/logging/logFileStreamOutput.hpp +++ b/src/hotspot/share/logging/logFileStreamOutput.hpp @@ -42,6 +42,7 @@ static LogFileStreamInitializer log_stream_initializer; class LogFileStreamOutput : public LogOutput { private: bool _write_error_is_shown; + protected: FILE* _stream; size_t _decorator_padding[LogDecorators::Count]; @@ -53,11 +54,14 @@ class LogFileStreamOutput : public LogOutput { } int write_decorations(const LogDecorations& decorations); + int write_internal(const LogDecorations& decorations, const char* msg); bool flush(); public: virtual int write(const LogDecorations& decorations, const char* msg); virtual int write(LogMessageBuffer::Iterator msg_iterator); + // Write API used by AsyncLogWriter + virtual int write_blocking(const LogDecorations& decorations, const char* msg); }; class LogStdoutOutput : public LogFileStreamOutput { diff --git a/test/hotspot/gtest/logging/test_asynclog.cpp b/test/hotspot/gtest/logging/test_asynclog.cpp index ffabbb524c2..2525f40ec4e 100644 --- a/test/hotspot/gtest/logging/test_asynclog.cpp +++ b/test/hotspot/gtest/logging/test_asynclog.cpp @@ -66,6 +66,38 @@ LOG_LEVEL_LIST log_trace(logging)("log_trace-test"); log_debug(logging)("log_debug-test"); } + + void test_asynclog_drop_messages() { + if (AsyncLogWriter::instance() != nullptr) { + const size_t sz = 100; + + // shrink async buffer. + AutoModifyRestore saver(AsyncLogBufferSize, sz * 1024 /*in byte*/); + LogMessage(logging) lm; + + // write 100x more messages than its capacity in burst + for (size_t i = 0; i < sz * 100; ++i) { + lm.debug("a lot of log..."); + } + lm.flush(); + } + } + + // stdout/stderr support + bool write_to_file(const std::string& output) { + FILE* f = fopen(TestLogFileName, "w"); + + if (f != NULL) { + size_t sz = output.size(); + size_t written = fwrite(output.c_str(), sizeof(char), output.size(), f); + + if (written == sz * sizeof(char)) { + return fclose(f) == 0; + } + } + + return false; + } }; TEST_VM(AsyncLogBufferTest, fifo) { @@ -198,19 +230,48 @@ TEST_VM_F(AsyncLogTest, logMessage) { TEST_VM_F(AsyncLogTest, droppingMessage) { set_log_config(TestLogFileName, "logging=debug"); - const size_t sz = 100; + test_asynclog_drop_messages(); + AsyncLogWriter::flush(); if (AsyncLogWriter::instance() != nullptr) { - // shrink async buffer. - AutoModifyRestore saver(AsyncLogBufferSize, sz * 1024 /*in byte*/); - LogMessage(logging) lm; + EXPECT_TRUE(file_contains_substring(TestLogFileName, "messages dropped due to async logging")); + } +} - // write 100x more messages than its capacity in burst - for (size_t i = 0; i < sz * 100; ++i) { - lm.debug("a lot of log..."); - } - lm.flush(); - AsyncLogWriter::flush(); +TEST_VM_F(AsyncLogTest, stdoutOutput) { + testing::internal::CaptureStdout(); + set_log_config("stdout", "logging=debug"); + + test_asynclog_ls(); + test_asynclog_drop_messages(); + + AsyncLogWriter::flush(); + EXPECT_TRUE(write_to_file(testing::internal::GetCapturedStdout())); + + 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")); + + if (AsyncLogWriter::instance() != nullptr) { + EXPECT_TRUE(file_contains_substring(TestLogFileName, "messages dropped due to async logging")); + } +} + +TEST_VM_F(AsyncLogTest, stderrOutput) { + testing::internal::CaptureStderr(); + set_log_config("stderr", "logging=debug"); + + test_asynclog_ls(); + test_asynclog_drop_messages(); + + AsyncLogWriter::flush(); + EXPECT_TRUE(write_to_file(testing::internal::GetCapturedStderr())); + + 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")); + + if (AsyncLogWriter::instance() != nullptr) { EXPECT_TRUE(file_contains_substring(TestLogFileName, "messages dropped due to async logging")); } }