8267517: async logging for stdout and stderr

Reviewed-by: shade
Backport-of: 7aff03a

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

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<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 KVHashtable<LogFileOutput*, uint32_t, mtLogging> AsyncLogMap;
+typedef KVHashtable<LogFileStreamOutput*, uint32_t, mtLogging> 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();

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;
 

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);
 

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;

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 {

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<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) {
- // shrink async buffer.
-  AutoModifyRestore<size_t> 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"));
  }
 }