8267517: async logging for stdout and stderr

Reviewed-by: shade
Backport-of: 7aff03aee1a5cd70638d8bbafeb7765bc7beea45

Author: Xin Liu

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