Fix remaining threading issues in Log.h

[labath]

Summary

This fixes two threading issues in the logging code. The access to the
mask and options flags had data races when we were trying to
enable/disable logging while another thread was writing to the log.
Since we can log from almost any context, and we want it to be fast, so
I avoided locking primitives and used atomic variables instead. I have
also removed the (unused) setters for the mask and flags to make sure
that the only way to set them is through the enable/disable channel
functions.

I also add tests, which when run under tsan, verify that the use cases
like "doing an LLDB_LOGV while another thread disables logging" are
data-race-free.

[clayborg]

With my limited std::atomic experience, this seems fine.

[eugene]

include/lldb/Utility/Log.h

152

Seems like const on return value is not really needed.

163

Do we actually need atomics here?

It seems like the stream itself is protected by the mutex, and It doesn't seem to affect performance.
Can we use the same (or a different) mutex to protect flags and options?

[zturner]

source/Utility/Log.cpp

90–91

How about

uint32_t old_mask = log.m_mask.fetch_or(flags);
if (old_mask  & flags) {
  ...
}

Also, there is still a race if two people call this function at the same time.

103–104

uint32_t old_mask = log->m_mask.fetch_and(~flags);
if (!(old_mask & ~flags)) {
  ...
}

116

Any reason you always use the explicit load(memory_order_acquire) syntax instead of using the default sequentially consistent ordering?

[labath]

include/lldb/Utility/Log.h

152

Well... otherwise people could write something like: log.GetOptions().Reset(foo) and expect that it will change underlying log object. This worked before this patch, so this seems like a good idea -- make sure accidental usage like that results in a compiler error rather than silently fail.

163

The difference is that these variables are accessed even when logging is disabled -- GetLogIfAll fetches the mask to decide whether it should log things. The stream mutex is only taken if logging is enabled and you are actually logging something (also only the read side is taken, so it is contention-free unless someone actually is modifying the stream at the same time).

I don't think doing this with a mutex would drastically hurt our performance, but I'm trying to avoid the case where enabling logging introduces enough thread synchronization than the race condition you were debugging disappears.

source/Utility/Log.cpp

90–91

That is not the race I was trying to solve here, but it seems making sure that is safe wouldn't be too hard, and it should make this easier to reason about. I'll reuse the stream mutex for this case.

116

The sequentially consistent ordering is more heavy, particularly on weakly ordered systems, and it's not necessary here - all I need is to make sure the value is read correctly. In fact, I was considering dropping this all the way to memory_order_relaxed.

[labath]

I've repurposed the stream mutex to protect the entirety of enable/disable
operations. To make this flow better, I've also gotten rid of the LogAndChannel
struct and make Channel a member of Log directly (which required moving some
declarations from the cpp file to the header).

I've also updated all atomic operations to use relaxed memory order. For the
operations in the critical section in does not matter. for the fast path in the
logging code it is enough to makee sure that the reads are atomic and once we
get around to actually writing to the log, the read lock on the mutex will make
sure the modifications to m_stream_sp are visible to the logging thread.

[zturner]

source/Utility/Log.cpp

109

Might as well use memory_order_relaxed here.

unittests/Utility/LogTest.cpp

16

Is this included needed?

[labath]

source/Utility/Log.cpp

109

Done. I missed that one.

unittests/Utility/LogTest.cpp

16

Not anymore. I had tried implementing the test with futures, but I couldn't get tsan to work with them properly.

include/lldb/Utility/Log.h

public:
     const uint32_t default_flags;
 
     constexpr Channel(llvm::ArrayRef<Log::Category> categories,
                       uint32_t default_flags)
         : log_ptr(nullptr), categories(categories),
           default_flags(default_flags) {}
 
     // This function is safe to call at any time
-    // FIXME: Not true yet, mask access is not atomic
+    // If the channel is disabled after (or concurrently with) this function
+    // returning a non-null Log pointer, it is still safe to attempt to write to
+    // the Log object -- the output will be discarded.
     Log *GetLogIfAll(uint32_t mask) {
       Log *log = log_ptr.load(std::memory_order_acquire);
       if (log && log->GetMask().AllSet(mask))
         return log;
       return nullptr;
     }
 
     // This function is safe to call at any time
-    // FIXME: Not true yet, mask access is not atomic
+    // If the channel is disabled after (or concurrently with) this function
+    // returning a non-null Log pointer, it is still safe to attempt to write to
+    // the Log object -- the output will be discarded.
     Log *GetLogIfAny(uint32_t mask) {
       Log *log = log_ptr.load(std::memory_order_acquire);
       if (log && log->GetMask().AnySet(mask))
         return log;
       return nullptr;
     }
 
     // Calls to Enable and disable need to be serialized externally.
public:
   static bool ListChannelCategories(llvm::StringRef channel, Stream &stream);
 
   static void DisableAllLogChannels(Stream *feedback_strm);
 
   static void ListAllLogChannels(Stream *strm);
 
   //------------------------------------------------------------------
   // Member functions
+  //
+  // These functions are safe to call at any time you have a Log* obtained from
+  // the Channel class. If logging is disabled between you obtaining the Log
+  // object and writing to it, the output will be silently discarded.
   //------------------------------------------------------------------
-  Log();
-
-  Log(const std::shared_ptr<llvm::raw_ostream> &stream_sp);
-
-  ~Log();
+  Log() = default;
+  ~Log() = default;
 
   void PutCString(const char *cstr);
   void PutString(llvm::StringRef str);
 
   template <typename... Args>
   void Format(llvm::StringRef file, llvm::StringRef function,
               const char *format, Args &&... args) {
     Format(file, function, llvm::formatv(format, std::forward<Args>(args)...));
   }
 
   // CLEANUP: Add llvm::raw_ostream &Stream() function.
   void Printf(const char *format, ...) __attribute__((format(printf, 2, 3)));
 
   void VAPrintf(const char *format, va_list args);
 
-  void LogIf(uint32_t mask, const char *fmt, ...)
-      __attribute__((format(printf, 3, 4)));
-
   void Error(const char *fmt, ...) __attribute__((format(printf, 2, 3)));
 
   void VAError(const char *format, va_list args);
 
   void Verbose(const char *fmt, ...) __attribute__((format(printf, 2, 3)));
 
   void Warning(const char *fmt, ...) __attribute__((format(printf, 2, 3)));
 
-  Flags &GetOptions();
+  const Flags GetOptions() const;
 
-  const Flags &GetOptions() const;
+  const Flags GetMask() const;
 
-  Flags &GetMask();
+  bool GetVerbose() const;
 
-  const Flags &GetMask() const;
+private:
+  llvm::sys::RWMutex m_stream_mutex; // Protects m_stream_sp
+  std::shared_ptr<llvm::raw_ostream> m_stream_sp;
 
-  bool GetVerbose() const;
+  std::atomic<uint32_t> m_options{0};
+  std::atomic<uint32_t> m_mask{0};
+
+  void WriteHeader(llvm::raw_ostream &OS, llvm::StringRef file,
+                   llvm::StringRef function);
+  void WriteMessage(const std::string &message);
+
+  void Format(llvm::StringRef file, llvm::StringRef function,
+              const llvm::formatv_object_base &payload);
 
   void SetStream(const std::shared_ptr<llvm::raw_ostream> &stream_sp) {
     llvm::sys::ScopedWriter lock(m_stream_mutex);
     m_stream_sp = stream_sp;
   }
 
   std::shared_ptr<llvm::raw_ostream> GetStream() {
     llvm::sys::ScopedReader lock(m_stream_mutex);
     return m_stream_sp;
   }
 
-protected:
-  //------------------------------------------------------------------
-  // Member variables
-  //------------------------------------------------------------------
-  llvm::sys::RWMutex m_stream_mutex; // Protects m_stream_sp
-  std::shared_ptr<llvm::raw_ostream> m_stream_sp;
-
-  Flags m_options;
-  Flags m_mask_bits;
-
-private:
   DISALLOW_COPY_AND_ASSIGN(Log);
-
-  void WriteHeader(llvm::raw_ostream &OS, llvm::StringRef file,
-                   llvm::StringRef function);
-  void WriteMessage(const std::string &message);
-
-  void Format(llvm::StringRef file, llvm::StringRef function,
-              const llvm::formatv_object_base &payload);
 };
 
 } // namespace lldb_private
 
 #define LLDB_LOG(log, ...)                                                     \
   do {                                                                         \
     ::lldb_private::Log *log_private = (log);                                  \
     if (log_private)                                                           \

source/Utility/Log.cpp

static uint32_t GetFlags(Stream &stream, const ChannelMap::value_type &entry,
   if (list_categories)
     ListCategories(stream, entry);
   return flags;
 }
 
 void Log::Channel::Enable(Log &log,
                           const std::shared_ptr<llvm::raw_ostream> &stream_sp,
                           uint32_t options, uint32_t flags) {
-  log.GetMask().Set(flags);
-  if (log.GetMask().Get()) {
-    log.GetOptions().Reset(options);
+  uint32_t mask = log.m_mask.load(std::memory_order_acquire) | flags;
+  log.m_mask.store(mask, std::memory_order_release);
+  if (mask) {
+    log.m_options.store(options, std::memory_order_release);
     log.SetStream(stream_sp);
     log_ptr.store(&log, std::memory_order_release);
   }
 }
 
 void Log::Channel::Disable(uint32_t flags) {
   Log *log = log_ptr.load(std::memory_order_acquire);
   if (!log)
     return;
-  log->GetMask().Clear(flags);
-  if (!log->GetMask().Get()) {
+  uint32_t mask = log->m_mask.load(std::memory_order_acquire) & ~flags;
+  log->m_mask.store(mask, std::memory_order_release);
+  if (!mask) {
     log->SetStream(nullptr);
     log_ptr.store(nullptr, std::memory_order_release);
   }
 }
 
-Log::Log() : m_stream_sp(), m_options(0), m_mask_bits(0) {}
-
-Log::Log(const std::shared_ptr<llvm::raw_ostream> &stream_sp)
-    : m_stream_sp(stream_sp), m_options(0), m_mask_bits(0) {}
-
-Log::~Log() = default;
-
-Flags &Log::GetOptions() { return m_options; }
-
-const Flags &Log::GetOptions() const { return m_options; }
-
-Flags &Log::GetMask() { return m_mask_bits; }
+const Flags Log::GetOptions() const {
+  return m_options.load(std::memory_order_acquire);
+}
 
-const Flags &Log::GetMask() const { return m_mask_bits; }
+const Flags Log::GetMask() const {
+  return m_mask.load(std::memory_order_acquire);
+}
 
 void Log::PutCString(const char *cstr) { Printf("%s", cstr); }
 void Log::PutString(llvm::StringRef str) { PutCString(str.str().c_str()); }
 
 //----------------------------------------------------------------------
 // Simple variable argument logging with flags.
 //----------------------------------------------------------------------
 void Log::Printf(const char *format, ...) {
void Log::VAPrintf(const char *format, va_list args) {
   lldb_private::VASprintf(Content, format, args);
 
   Stream << Content << "\n";
 
   WriteMessage(FinalMessage.str());
 }
 
 //----------------------------------------------------------------------
-// Log only if all of the bits are set
-//----------------------------------------------------------------------
-void Log::LogIf(uint32_t bits, const char *format, ...) {
-  if (!m_options.AllSet(bits))
-    return;
-
-  va_list args;
-  va_start(args, format);
-  VAPrintf(format, args);
-  va_end(args);
-}
-
-//----------------------------------------------------------------------
 // Printing of errors that are not fatal.
 //----------------------------------------------------------------------
 void Log::Error(const char *format, ...) {
   va_list args;
   va_start(args, format);
   VAError(format, args);
   va_end(args);
 }
 
 void Log::VAError(const char *format, va_list args) {
   llvm::SmallString<64> Content;
   VASprintf(Content, format, args);
 
   Printf("error: %s", Content.c_str());
 }
 
 //----------------------------------------------------------------------
 // Printing of warnings that are not fatal only if verbose mode is
 // enabled.
 //----------------------------------------------------------------------
 void Log::Verbose(const char *format, ...) {
-  if (!m_options.Test(LLDB_LOG_OPTION_VERBOSE))
+  if (!GetVerbose())
     return;
 
   va_list args;
   va_start(args, format);
   VAPrintf(format, args);
   va_end(args);
 }
 
void Log::ListAllLogChannels(Stream *strm) {
   if (g_channel_map->empty()) {
     strm->PutCString("No logging channels are currently registered.\n");
     return;
   }
 
   for (const auto &channel : *g_channel_map)
     ListCategories(*strm, channel);
 }
-bool Log::GetVerbose() const { return m_options.Test(LLDB_LOG_OPTION_VERBOSE); }
+bool Log::GetVerbose() const {
+  return m_options.load(std::memory_order_acquire) & LLDB_LOG_OPTION_VERBOSE;
+}
 
 void Log::WriteHeader(llvm::raw_ostream &OS, llvm::StringRef file,
                       llvm::StringRef function) {
+  Flags options = GetOptions();
   static uint32_t g_sequence_id = 0;
   // Add a sequence ID if requested
-  if (m_options.Test(LLDB_LOG_OPTION_PREPEND_SEQUENCE))
+  if (options.Test(LLDB_LOG_OPTION_PREPEND_SEQUENCE))
     OS << ++g_sequence_id << " ";
 
   // Timestamp if requested
-  if (m_options.Test(LLDB_LOG_OPTION_PREPEND_TIMESTAMP)) {
+  if (options.Test(LLDB_LOG_OPTION_PREPEND_TIMESTAMP)) {
     auto now = std::chrono::duration<double>(
         std::chrono::system_clock::now().time_since_epoch());
     OS << llvm::formatv("{0:f9} ", now.count());
   }
 
   // Add the process and thread if requested
-  if (m_options.Test(LLDB_LOG_OPTION_PREPEND_PROC_AND_THREAD))
+  if (options.Test(LLDB_LOG_OPTION_PREPEND_PROC_AND_THREAD))
     OS << llvm::formatv("[{0,0+4}/{1,0+4}] ", getpid(),
                         llvm::get_threadid());
 
   // Add the thread name if requested
-  if (m_options.Test(LLDB_LOG_OPTION_PREPEND_THREAD_NAME)) {
+  if (options.Test(LLDB_LOG_OPTION_PREPEND_THREAD_NAME)) {
     llvm::SmallString<32> thread_name;
     llvm::get_thread_name(thread_name);
     if (!thread_name.empty())
       OS << thread_name;
   }
 
-  if (m_options.Test(LLDB_LOG_OPTION_BACKTRACE))
+  if (options.Test(LLDB_LOG_OPTION_BACKTRACE))
     llvm::sys::PrintStackTrace(OS);
 
-  if (m_options.Test(LLDB_LOG_OPTION_PREPEND_FILE_FUNCTION) &&
+  if (options.Test(LLDB_LOG_OPTION_PREPEND_FILE_FUNCTION) &&
       (!file.empty() || !function.empty())) {
     file = llvm::sys::path::filename(file).take_front(40);
     function = function.take_front(40);
     OS << llvm::formatv("{0,-60:60} ", (file + ":" + function).str());
   }
 }
 
 void Log::WriteMessage(const std::string &message) {
   // Make a copy of our stream shared pointer in case someone disables our
   // log while we are logging and releases the stream
   auto stream_sp = GetStream();
   if (!stream_sp)
     return;
 
-  if (m_options.Test(LLDB_LOG_OPTION_THREADSAFE)) {
+  Flags options = GetOptions();
+  if (options.Test(LLDB_LOG_OPTION_THREADSAFE)) {
     static std::recursive_mutex g_LogThreadedMutex;
     std::lock_guard<std::recursive_mutex> guard(g_LogThreadedMutex);
     *stream_sp << message;
     stream_sp->flush();
   } else {
     *stream_sp << message;
     stream_sp->flush();
   }

unittests/Utility/LogTest.cpp

 //===-- LogTest.cpp ---------------------------------------------*- C++ -*-===//
 //
 //                     The LLVM Compiler Infrastructure
 //
 // This file is distributed under the University of Illinois Open Source
 // License. See LICENSE.TXT for details.
 //
 //===----------------------------------------------------------------------===//
 
 #include "gtest/gtest.h"
 
 #include "lldb/Utility/Log.h"
 #include "lldb/Utility/StreamString.h"
 #include "llvm/Support/ManagedStatic.h"
 #include "llvm/Support/Threading.h"
+#include <future>
 #include <thread>
 
 using namespace lldb;
 using namespace lldb_private;
 
 enum { FOO = 1, BAR = 2 };
 static constexpr Log::Category test_categories[] = {
     {{"foo"}, {"log foo"}, FOO}, {{"bar"}, {"log bar"}, BAR},
TEST_F(LogChannelTest, LogThread) {
   log_thread.join();
 
   // The log thread either managed to write to the log in time, or it didn't. In
   // either case, we should not trip any undefined behavior (run the test under
   // TSAN to verify this).
   EXPECT_TRUE(stream_sp->str() == "" || stream_sp->str() == "Hello World\n")
       << "str(): " << stream_sp->str();
 }
+
+TEST_F(LogChannelTest, LogVerboseThread) {
+  // Test that we are able to concurrently check the verbose flag of a log
+  // channel and enable it.
+  std::string message;
+  std::shared_ptr<llvm::raw_string_ostream> stream_sp(
+      new llvm::raw_string_ostream(message));
+  StreamString err;
+  EXPECT_TRUE(Log::EnableLogChannel(stream_sp, 0, "chan", {}, err));
+
+  Log *log = test_channel.GetLogIfAll(FOO);
+
+  // Start logging on one thread. Concurrently, try enabling the log channel
+  // (with different log options).
+  std::thread log_thread([log] { LLDB_LOGV(log, "Hello World"); });
+  EXPECT_TRUE(Log::EnableLogChannel(stream_sp, LLDB_LOG_OPTION_VERBOSE, "chan",
+                                    {}, err));
+  log_thread.join();
+  EXPECT_TRUE(Log::DisableLogChannel("chan", {}, err));
+
+  // The log thread either managed to write to the log, or it didn't. In either
+  // case, we should not trip any undefined behavior (run the test under TSAN to
+  // verify this).
+  EXPECT_TRUE(stream_sp->str() == "" || stream_sp->str() == "Hello World\n")
+      << "str(): " << stream_sp->str();
+}
+
+TEST_F(LogChannelTest, LogGetLogThread) {
+  // Test that we are able to concurrently get mask of a Log object and disable
+  // it.
+  std::string message;
+  std::shared_ptr<llvm::raw_string_ostream> stream_sp(
+      new llvm::raw_string_ostream(message));
+  StreamString err;
+  EXPECT_TRUE(Log::EnableLogChannel(stream_sp, 0, "chan", {}, err));
+  Log *log = test_channel.GetLogIfAll(FOO);
+
+  // Try fetching the log on one thread. Concurrently, try disabling the log
+  // channel.
+  uint32_t mask;
+  std::thread log_thread([log, &mask] { mask = log->GetMask().Get(); });
+  EXPECT_TRUE(Log::DisableLogChannel("chan", {}, err));
+  log_thread.join();
+
+  // The mask should be either zero of "FOO". In either case, we should not trip
+  // any undefined behavior (run the test under TSAN to verify this).
+  EXPECT_TRUE(mask == 0 || mask == FOO) << "mask: " << mask;
+}