8267952: async logging supports to dynamically change tags and decorators

Reviewed-by: dholmes, phh

src/hotspot/share/logging/logAsyncWriter.cpp

@@ -41,7 +41,7 @@ class AsyncLogWriter::AsyncLogLocker : public StackObj {
 };
 
 void AsyncLogWriter::enqueue_locked(const AsyncLogMessage& msg) {
-  if (_buffer.size() >= _buffer_max_size)  {
+  if (_buffer.size() >= _buffer_max_size) {
     bool p_created;
     uint32_t* counter = _stats.add_if_absent(msg.output(), 0, &p_created);
     *counter = *counter + 1;
@@ -50,13 +50,12 @@ void AsyncLogWriter::enqueue_locked(const AsyncLogMessage& msg) {
     return;
   }
 
-  assert(_buffer.size() < _buffer_max_size, "_buffer is over-sized.");
   _buffer.push_back(msg);
   _sem.signal();
 }
 
 void AsyncLogWriter::enqueue(LogFileOutput& output, const LogDecorations& decorations, const char* msg) {
-  AsyncLogMessage m(output, decorations, os::strdup(msg));
+  AsyncLogMessage m(&output, decorations, os::strdup(msg));
 
   { // critical area
     AsyncLogLocker locker;
@@ -70,13 +69,13 @@ void AsyncLogWriter::enqueue(LogFileOutput& output, LogMessageBuffer::Iterator m
   AsyncLogLocker locker;
 
   for (; !msg_iterator.is_at_end(); msg_iterator++) {
-    AsyncLogMessage m(output, msg_iterator.decorations(), os::strdup(msg_iterator.message()));
+    AsyncLogMessage m(&output, msg_iterator.decorations(), os::strdup(msg_iterator.message()));
     enqueue_locked(m);
   }
 }
 
 AsyncLogWriter::AsyncLogWriter()
-  : _lock(1), _sem(0), _io_sem(1),
+  : _lock(1), _sem(0), _flush_sem(0),
     _initialized(false),
     _stats(17 /*table_size*/) {
   if (os::create_thread(this, os::asynclog_thread)) {
@@ -98,10 +97,10 @@ class AsyncLogMapIterator {
     using none = LogTagSetMapping<LogTag::__NO_TAG>;
 
     if (*counter > 0) {
-      LogDecorations decorations(LogLevel::Warning, none::tagset(), output->decorators());
+      LogDecorations decorations(LogLevel::Warning, none::tagset(), LogDecorators::All);
       stringStream ss;
       ss.print(UINT32_FORMAT_W(6) " messages dropped due to async logging", *counter);
-      AsyncLogMessage msg(*output, decorations, ss.as_string(true /*c_heap*/));
+      AsyncLogMessage msg(output, decorations, ss.as_string(true /*c_heap*/));
       _logs.push_back(msg);
       *counter = 0;
     }
@@ -118,7 +117,6 @@ void AsyncLogWriter::write() {
   // The operation 'pop_all()' is done in O(1). All I/O jobs are then performed without
   // lock protection. This guarantees I/O jobs don't block logsites.
   AsyncLogBuffer logs;
-  bool own_io = false;
 
   { // critical region
     AsyncLogLocker locker;
@@ -127,14 +125,11 @@ void AsyncLogWriter::write() {
     // append meta-messages of dropped counters
     AsyncLogMapIterator dropped_counters_iter(logs);
     _stats.iterate(&dropped_counters_iter);
-    own_io = _io_sem.trywait();
   }
 
   LinkedListIterator<AsyncLogMessage> it(logs.head());
-  if (!own_io) {
-    _io_sem.wait();
-  }
 
+  int req = 0;
   while (!it.is_empty()) {
     AsyncLogMessage* e = it.next();
     char* msg = e->message();
@@ -142,9 +137,17 @@ void AsyncLogWriter::write() {
     if (msg != nullptr) {
       e->output()->write_blocking(e->decorations(), msg);
       os::free(msg);
+    } else if (e->output() == nullptr) {
+      // This is a flush token. Record that we found it and then
+      // signal the flushing thread after the loop.
+      req++;
     }
   }
-  _io_sem.signal();
+
+  if (req > 0) {
+    assert(req == 1, "AsyncLogWriter::flush() is NOT MT-safe!");
+    _flush_sem.signal(req);
+  }
 }
 
 void AsyncLogWriter::run() {
@@ -181,10 +184,23 @@ AsyncLogWriter* AsyncLogWriter::instance() {
   return _instance;
 }
 
-// write() acquires and releases _io_sem even _buffer is empty.
-// This guarantees all logging I/O of dequeued messages are done when it returns.
+// Inserts a flush token into the async output buffer and waits until the AsyncLog thread
+// signals that it has seen it and completed all dequeued message processing.
+// This method is not MT-safe in itself, but is guarded by another lock in the usual
+// usecase - see the comments in the header file for more details.
 void AsyncLogWriter::flush() {
   if (_instance != nullptr) {
-    _instance->write();
+    {
+      using none = LogTagSetMapping<LogTag::__NO_TAG>;
+      AsyncLogLocker locker;
+      LogDecorations d(LogLevel::Off, none::tagset(), LogDecorators::None);
+      AsyncLogMessage token(nullptr, d, nullptr);
+
+      // Push directly in-case we are at logical max capacity, as this must not get dropped.
+      _instance->_buffer.push_back(token);
+      _instance->_sem.signal();
+    }
+
+    _instance->_flush_sem.wait();
   }
 }

src/hotspot/share/logging/logAsyncWriter.hpp

@@ -91,18 +91,18 @@ class LinkedListDeque : private LinkedListImpl<E, ResourceObj::C_HEAP, F> {
 };
 
 class AsyncLogMessage {
-  LogFileOutput& _output;
+  LogFileOutput* _output;
   const LogDecorations _decorations;
   char* _message;
 
 public:
-  AsyncLogMessage(LogFileOutput& output, const LogDecorations& decorations, char* msg)
+  AsyncLogMessage(LogFileOutput* 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; }
+  LogFileOutput* output() const { return _output; }
   const LogDecorations& decorations() const { return _decorations; }
   char* message() const { return _message; }
 };
@@ -121,17 +121,16 @@ typedef KVHashtable<LogFileOutput*, uint32_t, mtLogging> AsyncLogMap;
 // initialize() is called once when JVM is initialized. It creates and initializes the singleton instance of AsyncLogWriter.
 // Once async logging is established, there's no way to turn it off.
 //
-// instance() is MT-safe and returns the pointer of the singleton instance if and only if async logging is enabled and has well
-// initialized. Clients can use its return value to determine async logging is established or not.
+// instance() is MT-safe and returns the pointer of the singleton instance if and only if async logging is enabled and has
+// successfully initialized. Clients can use its return value to determine async logging is established or not.
 //
-// The basic operation of AsyncLogWriter is enqueue(). 2 overloading versions of it are provided to match LogOutput::write().
+// enqueue() is the basic operation of AsyncLogWriter. Two overloading versions of it are provided to match LogOutput::write().
 // They are both MT-safe and non-blocking. Derived classes of LogOutput can invoke the corresponding enqueue() in write() and
 // return 0. AsyncLogWriter is responsible of copying neccessary data.
 //
-// The static member function flush() is designated to flush out all pending messages when JVM is terminating.
-// In normal JVM termination, flush() is invoked in LogConfiguration::finalize(). flush() is MT-safe and can be invoked arbitrary
-// times. It is no-op if async logging is not established.
-//
+// flush() ensures that all pending messages have been written out before it returns. It is not MT-safe in itself. When users
+// change the logging configuration via jcmd, LogConfiguration::configure_output() calls flush() under the protection of the
+// ConfigurationLock. In addition flush() is called during JVM termination, via LogConfiguration::finalize.
 class AsyncLogWriter : public NonJavaThread {
   class AsyncLogLocker;
 
@@ -141,8 +140,7 @@ class AsyncLogWriter : public NonJavaThread {
   // _sem is a semaphore whose value denotes how many messages have been enqueued.
   // It decreases in AsyncLogWriter::run()
   Semaphore _sem;
-  // A lock of IO
-  Semaphore _io_sem;
+  Semaphore _flush_sem;
 
   volatile bool _initialized;
   AsyncLogMap _stats; // statistics for dropped messages

src/hotspot/share/logging/logConfiguration.cpp

@@ -211,6 +211,21 @@ void LogConfiguration::delete_output(size_t idx) {
   delete output;
 }
 
+// MT-SAFETY
+//
+// The ConfigurationLock guarantees that only one thread is performing reconfiguration. This function still needs
+// to be MT-safe because logsites in other threads may be executing in parallel. Reconfiguration means unified
+// logging allows users to dynamically change tags and decorators of a log output via DCMD(logDiagnosticCommand.hpp).
+//
+// A RCU-style synchronization 'wait_until_no_readers()' is used inside of 'ts->set_output_level(output, level)'
+// if a setting has changed. It guarantees that all logs, either synchronous writes or enqueuing to the async buffer
+// see the new tags and decorators. It's worth noting that the synchronization occurs even if the level does not change.
+//
+// LogDecorator is a set of decorators represented in a uint. ts->update_decorators(decorators) is a union of the
+// current decorators and new_decorators. It's safe to do output->set_decorators(decorators) because new_decorators
+// is a subset of relevant tagsets decorators. After updating output's decorators, it is still safe to shrink all
+// decorators of tagsets.
+//
 void LogConfiguration::configure_output(size_t idx, const LogSelectionList& selections, const LogDecorators& decorators) {
   assert(ConfigurationLock::current_thread_has_lock(), "Must hold configuration lock to call this function.");
   assert(idx < _n_outputs, "Invalid index, idx = " SIZE_FORMAT " and _n_outputs = " SIZE_FORMAT, idx, _n_outputs);
@@ -253,6 +268,10 @@ void LogConfiguration::configure_output(size_t idx, const LogSelectionList& sele
     on_level[level]++;
   }
 
+  // For async logging we have to ensure that all enqueued messages, which may refer to previous decorators,
+  // or a soon-to-be-deleted output, are written out first. The flush() call ensures this.
+  AsyncLogWriter::flush();
+
   // It is now safe to set the new decorators for the actual output
   output->set_decorators(decorators);
 
@@ -262,10 +281,6 @@ void LogConfiguration::configure_output(size_t idx, const LogSelectionList& sele
   }
 
   if (!enabled && idx > 1) {
-    // User may disable a logOuput like this:
-    // LogConfiguration::parse_log_arguments(filename, "all=off", "", "", &stream);
-    // Just be conservative. Flush them all before deleting idx.
-    AsyncLogWriter::flush();
     // Output is unused and should be removed, unless it is stdout/stderr (idx < 2)
     delete_output(idx);
     return;
@@ -283,10 +298,10 @@ void LogConfiguration::disable_outputs() {
     ts->disable_outputs();
   }
 
-  // Handle jcmd VM.log disable
-  // ts->disable_outputs() above has deleted output_list with RCU synchronization.
-  // Therefore, no new logging entry can enter AsyncLog buffer for the time being.
-  // flush pending entries before LogOutput instances die.
+  // Handle 'jcmd VM.log disable' and JVM termination.
+  // ts->disable_outputs() above has disabled all output_lists with RCU synchronization.
+  // Therefore, no new logging message can enter the async buffer for the time being.
+  // flush out all pending messages before LogOutput instances die.
   AsyncLogWriter::flush();
 
   while (idx > 0) {

src/hotspot/share/logging/logDecorators.cpp

@@ -25,7 +25,19 @@
 #include "logging/logDecorators.hpp"
 #include "runtime/os.hpp"
 
+template <LogDecorators::Decorator d>
+struct AllBitmask {
+  // Use recursive template deduction to calculate the bitmask of all decorations.
+  static const uint _value = (1 << d) | AllBitmask<static_cast<LogDecorators::Decorator>(d + 1)>::_value;
+};
+
+template<>
+struct AllBitmask<LogDecorators::Count> {
+  static const uint _value = 0;
+};
+
 const LogDecorators LogDecorators::None = LogDecorators(0);
+const LogDecorators LogDecorators::All  = LogDecorators(AllBitmask<time_decorator>::_value);
 
 const char* LogDecorators::_name[][2] = {
 #define DECORATOR(n, a) {#n, #a},

src/hotspot/share/logging/logDecorators.hpp

@@ -82,6 +82,7 @@ class LogDecorators {
 
  public:
   static const LogDecorators None;
+  static const LogDecorators All;
 
   LogDecorators() : _decorators(DefaultDecoratorsMask) {
   }

src/hotspot/share/logging/logTagSet.cpp

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2015, 2020, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2015, 2021, Oracle and/or its affiliates. All rights reserved.
  * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
  *
  * This code is free software; you can redistribute it and/or modify it
@@ -73,15 +73,24 @@ bool LogTagSet::has_output(const LogOutput* output) {
 }
 
 void LogTagSet::log(LogLevelType level, const char* msg) {
+  // Increasing the atomic reader counter in iterator(level) must
+  // happen before the creation of LogDecorations instance so
+  // wait_until_no_readers() in LogConfiguration::configure_output()
+  // synchronizes _decorations as well. The order is guaranteed by
+  // the implied memory order of Atomic::add().
+  LogOutputList::Iterator it = _output_list.iterator(level);
   LogDecorations decorations(level, *this, _decorators);
-  for (LogOutputList::Iterator it = _output_list.iterator(level); it != _output_list.end(); it++) {
+
+  for (; it != _output_list.end(); it++) {
     (*it)->write(decorations, msg);
   }
 }
 
 void LogTagSet::log(const LogMessageBuffer& msg) {
+  LogOutputList::Iterator it = _output_list.iterator(msg.least_detailed_level());
   LogDecorations decorations(LogLevel::Invalid, *this, _decorators);
-  for (LogOutputList::Iterator it = _output_list.iterator(msg.least_detailed_level()); it != _output_list.end(); it++) {
+
+  for (; it != _output_list.end(); it++) {
     (*it)->write(msg.iterator(it.level(), decorations));
   }
 }

test/hotspot/gtest/logging/logTestFixture.cpp

@@ -46,7 +46,6 @@ LogTestFixture::LogTestFixture() : _n_snapshots(0), _configuration_snapshot(NULL
 }
 
 LogTestFixture::~LogTestFixture() {
-  AsyncLogWriter::flush();
   restore_config();
   clear_snapshot();
   delete_file(TestLogFileName);

test/hotspot/gtest/logging/test_logConfiguration.cpp

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2016, 2019, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2016, 2021, Oracle and/or its affiliates. All rights reserved.
  * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
  *
  * This code is free software; you can redistribute it and/or modify it
@@ -23,6 +23,7 @@
 
 #include "precompiled.hpp"
 #include "jvm.h"
+#include "concurrentTestRunner.inline.hpp"
 #include "logTestFixture.hpp"
 #include "logTestUtils.inline.hpp"
 #include "logging/logConfiguration.hpp"
@@ -228,6 +229,91 @@ TEST_VM_F(LogConfigurationTest, reconfigure_decorators) {
   EXPECT_TRUE(is_described("#1: stderr all=off none (reconfigured)\n")) << "Expecting no decorators";
 }
 
+class ConcurrentLogsite : public TestRunnable {
+  int _id;
+
+ public:
+  ConcurrentLogsite(int id) : _id(id) {}
+  void runUnitTest() const override {
+    log_debug(logging)("ConcurrentLogsite %d emits a log", _id);
+  }
+};
+
+// Dynamically change decorators while loggings are emitting.
+TEST_VM_F(LogConfigurationTest, reconfigure_decorators_MT) {
+  const int nrOfThreads = 2;
+  ConcurrentLogsite logsites[nrOfThreads] = {0, 1};
+  Semaphore done(0);
+  const long testDurationMillis = 1000;
+  UnitTestThread* t[nrOfThreads];
+
+  set_log_config(TestLogFileName, "logging=debug", "none", "filecount=0");
+  set_log_config("stdout", "all=off", "none");
+  set_log_config("stderr", "all=off", "none");
+  for (int i = 0; i < nrOfThreads; ++i) {
+    t[i] = new UnitTestThread(&logsites[i], &done, testDurationMillis);
+  }
+
+  for (int i = 0; i < nrOfThreads; i++) {
+    t[i]->doit();
+  }
+
+  jlong time_start = os::elapsed_counter();
+  while (true) {
+    jlong elapsed = (jlong)TimeHelper::counter_to_millis(os::elapsed_counter() - time_start);
+    if (elapsed > testDurationMillis) {
+      break;
+    }
+
+    // Take turn logging with different decorators, either None or All.
+    set_log_config(TestLogFileName, "logging=debug", "none");
+    set_log_config(TestLogFileName, "logging=debug", _all_decorators);
+  }
+
+  for (int i = 0; i < nrOfThreads; ++i) {
+    done.wait();
+  }
+}
+
+// Dynamically change tags while loggings are emitting.
+TEST_VM_F(LogConfigurationTest, reconfigure_tags_MT) {
+  const int nrOfThreads = 2;
+  ConcurrentLogsite logsites[nrOfThreads] = {0, 1};
+  Semaphore done(0);
+  const long testDurationMillis = 1000;
+  UnitTestThread* t[nrOfThreads];
+
+  set_log_config(TestLogFileName, "logging=debug", "", "filecount=0");
+  set_log_config("stdout", "all=off", "none");
+  set_log_config("stderr", "all=off", "none");
+
+  for (int i = 0; i < nrOfThreads; ++i) {
+    t[i] = new UnitTestThread(&logsites[i], &done, testDurationMillis);
+  }
+
+  for (int i = 0; i < nrOfThreads; i++) {
+    t[i]->doit();
+  }
+
+  jlong time_start = os::elapsed_counter();
+  while (true) {
+    jlong elapsed = (jlong)TimeHelper::counter_to_millis(os::elapsed_counter() - time_start);
+    if (elapsed > testDurationMillis) {
+      break;
+    }
+
+    // turn on/off the tagset 'logging'.
+    set_log_config(TestLogFileName, "logging=off");
+    set_log_config(TestLogFileName, "logging=debug", "", "filecount=0");
+    // sleep a prime number milliseconds to allow concurrent logsites to write logs
+    os::naked_short_nanosleep(37);
+  }
+
+  for (int i = 0; i < nrOfThreads; ++i) {
+    done.wait();
+  }
+}
+
 // Test that invalid options cause configuration errors
 TEST_VM_F(LogConfigurationTest, invalid_configure_options) {
   LogConfiguration::disable_logging();

test/hotspot/gtest/logging/test_logDecorators.cpp

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2016, 2017, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2016, 2021, Oracle and/or its affiliates. All rights reserved.
  * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
  *
  * This code is free software; you can redistribute it and/or modify it
@@ -210,6 +210,13 @@ TEST(LogDecorators, none) {
   }
 }
 
+TEST(LogDecorators, all) {
+  LogDecorators dec = LogDecorators::All;
+  for (size_t i = 0; i < LogDecorators::Count; i++) {
+    EXPECT_TRUE(dec.is_decorator(decorator_array[i]));
+  }
+}
+
 TEST(LogDecorators, is_empty) {
   LogDecorators def, none = LogDecorators::None;
   EXPECT_FALSE(def.is_empty());