stan/jdk-24
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

8267517: async logging for stdout and stderr

Browse Source 
Reviewed-by: dholmes, ysuenaga
This commit is contained in:
Xin Liu 2021-12-23 20:25:08 +00:00
parent ff2ca4f21b
commit 7aff03aee1
7 changed files with 120 additions and 39 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

7
src/hotspot/share/logging/logAsyncWriter.cpp
View File

@ -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<LogTag::__NO_TAG>;
if (counter > 0) {

17
src/hotspot/share/logging/logAsyncWriter.hpp
View File

@ -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/resourceHash.hpp"
#include "utilities/linkedlist.hpp"
@ -90,25 +90,28 @@ class LinkedListDeque : private LinkedListImpl<E, ResourceObj::C_HEAP, F> {
}
};
// 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<AsyncLogMessage, mtLogging> AsyncLogBuffer;
typedef ResourceHashtable<LogFileOutput*,
typedef ResourceHashtable<LogFileStreamOutput*,
uint32_t,
17, /*table_size*/
ResourceObj::C_HEAP,
@ -168,8 +171,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();

4
src/hotspot/share/logging/logFileOutput.cpp
View File

@ -272,7 +272,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;

2
src/hotspot/share/logging/logFileOutput.hpp
View File

@ -85,7 +85,7 @@ class LogFileOutput : public LogFileStreamOutput {
virtual bool set_option(const char* key, const char* value, 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);

42
src/hotspot/share/logging/logFileStreamOutput.cpp
View File

@ -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"
@ -135,8 +136,15 @@ bool LogFileStreamOutput::flush() {
total += result; \
}
int LogFileStreamOutput::write_internal(const char* msg) {
int LogFileStreamOutput::write_internal(const LogDecorations& decorations, const char* msg) {
int written = 0;
const bool use_decorations = !_decorators.is_empty();
if (use_decorations) {
WRITE_LOG_WITH_RESULT_CHECK(write_decorations(decorations), written);
WRITE_LOG_WITH_RESULT_CHECK(jio_fprintf(_stream, " "), written);
}
if (!_fold_multilines) {
WRITE_LOG_WITH_RESULT_CHECK(jio_fprintf(_stream, "%s\n", msg), written);
} else {
@ -159,31 +167,35 @@ int LogFileStreamOutput::write_internal(const char* msg) {
return written;
}
int LogFileStreamOutput::write(const LogDecorations& decorations, const char* msg) {
const bool use_decorations = !_decorators.is_empty();
int LogFileStreamOutput::write_blocking(const LogDecorations& decorations, const char* msg) {
int written = write_internal(decorations, msg);
return flush() ? written : -1;
}
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);
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;
}
written += write_internal(msg);
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);
}
written += write_internal(msg_iterator.message());
written += write_internal(msg_iterator.decorations(), msg_iterator.message());
}
return flush() ? written : -1;

4
src/hotspot/share/logging/logFileStreamOutput.hpp
View File

@ -46,7 +46,6 @@ class LogFileStreamOutput : public LogOutput {
bool _fold_multilines;
bool _write_error_is_shown;
int write_internal(const char* msg);
protected:
FILE* _stream;
size_t _decorator_padding[LogDecorators::Count];
@ -58,12 +57,15 @@ class LogFileStreamOutput : public LogOutput {
}
int write_decorations(const LogDecorations& decorations);
int write_internal(const LogDecorations& decorations, const char* msg);
bool flush();
public:
virtual bool set_option(const char* key, const char* value, outputStream* errstream);
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);
virtual void describe(outputStream* out);
};

83
test/hotspot/gtest/logging/test_asynclog.cpp
View File

@ -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<size_t> 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) {
EXPECT_TRUE(file_contains_substring(TestLogFileName, "messages dropped due to async logging"));
}
}
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) {
// shrink async buffer.
AutoModifyRestore<size_t> 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();
AsyncLogWriter::flush();
EXPECT_TRUE(file_contains_substring(TestLogFileName, "messages dropped due to async logging"));
}
}