8267517: async logging for stdout and stderr

Reviewed-by: dholmes, ysuenaga

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

src/hotspot/share/logging/logFileOutput.cpp

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

src/hotspot/share/logging/logFileOutput.hpp

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

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"
@@ -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_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) {
-  const bool use_decorations = !_decorators.is_empty();
+  AsyncLogWriter* aio_writer = AsyncLogWriter::instance();
+  if (aio_writer != nullptr) {
+    aio_writer->enqueue(*this, decorations, msg);
+    return 0;
+  }
 
-  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);
-  }
-  written += write_internal(msg);
+  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;

src/hotspot/share/logging/logFileStreamOutput.hpp

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

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