labath updated this revision to Diff 90994.
labath added a comment.

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.


https://reviews.llvm.org/D30702

Files:
  include/lldb/Utility/Log.h
  source/Utility/Log.cpp
  unittests/Utility/LogTest.cpp

Index: unittests/Utility/LogTest.cpp
===================================================================
--- unittests/Utility/LogTest.cpp
+++ unittests/Utility/LogTest.cpp
@@ -13,6 +13,7 @@
 #include "lldb/Utility/StreamString.h"
 #include "llvm/Support/ManagedStatic.h"
 #include "llvm/Support/Threading.h"
+#include <future>
 #include <thread>
 
 using namespace lldb;
@@ -214,3 +215,51 @@
   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;
+}
Index: source/Utility/Log.cpp
===================================================================
--- source/Utility/Log.cpp
+++ source/Utility/Log.cpp
@@ -18,7 +18,6 @@
 #include "llvm/ADT/STLExtras.h"
 #include "llvm/ADT/SmallString.h"
 #include "llvm/Support/Chrono.h"
-#include "llvm/Support/ManagedStatic.h"
 #include "llvm/Support/Path.h"
 #include "llvm/Support/Signals.h"
 #include "llvm/Support/Threading.h"
@@ -36,27 +35,17 @@
 using namespace lldb;
 using namespace lldb_private;
 
-namespace {
-  struct ChannelAndLog {
-    Log log;
-    Log::Channel &channel;
+llvm::ManagedStatic<Log::ChannelMap> Log::g_channel_map;
 
-    ChannelAndLog(Log::Channel &channel) : channel(channel) {}
-  };
-  typedef llvm::StringMap<ChannelAndLog> ChannelMap;
-}
-
-static llvm::ManagedStatic<ChannelMap> g_channel_map;
-
-static void ListCategories(Stream &stream, const ChannelMap::value_type &entry) {
+void Log::ListCategories(Stream &stream, const ChannelMap::value_type &entry) {
   stream.Format("Logging categories for '{0}':\n", entry.first());
   stream.Format("  all - all available logging categories\n");
   stream.Format("  default - default set of logging categories\n");
-  for (const auto &category : entry.second.channel.categories)
+  for (const auto &category : entry.second.m_channel.categories)
     stream.Format("  {0} - {1}\n", category.name, category.description);
 }
 
-static uint32_t GetFlags(Stream &stream, const ChannelMap::value_type &entry,
+uint32_t Log::GetFlags(Stream &stream, const ChannelMap::value_type &entry,
                          llvm::ArrayRef<const char *> categories) {
   bool list_categories = false;
   uint32_t flags = 0;
@@ -66,13 +55,13 @@
       continue;
     }
     if (llvm::StringRef("default").equals_lower(category)) {
-      flags |= entry.second.channel.default_flags;
+      flags |= entry.second.m_channel.default_flags;
       continue;
     }
     auto cat = llvm::find_if(
-        entry.second.channel.categories,
+        entry.second.m_channel.categories,
         [&](const Log::Category &c) { return c.name.equals_lower(category); });
-    if (cat != entry.second.channel.categories.end()) {
+    if (cat != entry.second.m_channel.categories.end()) {
       flags |= cat->flag;
       continue;
     }
@@ -84,42 +73,35 @@
   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);
-    log.SetStream(stream_sp);
-    log_ptr.store(&log, std::memory_order_release);
-  }
-}
+void Log::Enable(const std::shared_ptr<llvm::raw_ostream> &stream_sp,
+                 uint32_t options, uint32_t flags) {
+  llvm::sys::ScopedWriter lock(m_mutex);
 
-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()) {
-    log->SetStream(nullptr);
-    log_ptr.store(nullptr, std::memory_order_release);
+  uint32_t mask = m_mask.fetch_or(flags, std::memory_order_relaxed);
+  if (mask | flags) {
+    m_options.store(options, std::memory_order_release);
+    m_stream_sp = stream_sp;
+    m_channel.log_ptr.store(this, std::memory_order_relaxed);
   }
 }
 
-Log::Log() : m_stream_sp(), m_options(0), m_mask_bits(0) {}
+void Log::Disable(uint32_t flags) {
+  llvm::sys::ScopedWriter lock(m_mutex);
 
-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; }
+  uint32_t mask = m_mask.fetch_and(~flags, std::memory_order_relaxed);
+  if (!(mask & ~flags)) {
+    m_stream_sp.reset();
+    m_channel.log_ptr.store(nullptr, std::memory_order_relaxed);
+  }
+}
 
-Flags &Log::GetMask() { return m_mask_bits; }
+const Flags Log::GetOptions() const {
+  return m_options.load(std::memory_order_relaxed);
+}
 
-const Flags &Log::GetMask() const { return m_mask_bits; }
+const Flags Log::GetMask() const {
+  return m_mask.load(std::memory_order_relaxed);
+}
 
 void Log::PutCString(const char *cstr) { Printf("%s", cstr); }
 void Log::PutString(llvm::StringRef str) { PutCString(str.str().c_str()); }
@@ -153,19 +135,6 @@
 }
 
 //----------------------------------------------------------------------
-// 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, ...) {
@@ -187,7 +156,7 @@
 // enabled.
 //----------------------------------------------------------------------
 void Log::Verbose(const char *format, ...) {
-  if (!m_options.Test(LLDB_LOG_OPTION_VERBOSE))
+  if (!GetVerbose())
     return;
 
   va_list args;
@@ -218,7 +187,7 @@
 void Log::Unregister(llvm::StringRef name) {
   auto iter = g_channel_map->find(name);
   assert(iter != g_channel_map->end());
-  iter->second.channel.Disable(UINT32_MAX);
+  iter->second.Disable(UINT32_MAX);
   g_channel_map->erase(iter);
 }
 
@@ -232,10 +201,9 @@
     return false;
   }
   uint32_t flags = categories.empty()
-                       ? iter->second.channel.default_flags
+                       ? iter->second.m_channel.default_flags
                        : GetFlags(error_stream, *iter, categories);
-  iter->second.channel.Enable(iter->second.log, log_stream_sp, log_options,
-                              flags);
+  iter->second.Enable(log_stream_sp, log_options, flags);
   return true;
 }
 
@@ -250,7 +218,7 @@
   uint32_t flags = categories.empty()
                        ? UINT32_MAX
                        : GetFlags(error_stream, *iter, categories);
-  iter->second.channel.Disable(flags);
+  iter->second.Disable(flags);
   return true;
 }
 
@@ -266,7 +234,7 @@
 
 void Log::DisableAllLogChannels(Stream *feedback_strm) {
   for (auto &entry : *g_channel_map)
-    entry.second.channel.Disable(UINT32_MAX);
+    entry.second.Disable(UINT32_MAX);
 }
 
 void Log::ListAllLogChannels(Stream *strm) {
@@ -278,39 +246,42 @@
   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_relaxed) & 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);
@@ -325,7 +296,8 @@
   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;
Index: include/lldb/Utility/Log.h
===================================================================
--- include/lldb/Utility/Log.h
+++ include/lldb/Utility/Log.h
@@ -17,6 +17,7 @@
 
 // Other libraries and framework includes
 #include "llvm/Support/FormatVariadic.h"
+#include "llvm/Support/ManagedStatic.h"
 #include "llvm/Support/RWMutex.h"
 // C++ Includes
 #include <atomic>
@@ -55,6 +56,7 @@
   // necessary to enable a log channel in an atomic manner.
   class Channel {
     std::atomic<Log *> log_ptr;
+    friend class Log;
 
   public:
     const llvm::ArrayRef<Category> categories;
@@ -66,29 +68,26 @@
           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);
+      Log *log = log_ptr.load(std::memory_order_relaxed);
       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);
+      Log *log = log_ptr.load(std::memory_order_relaxed);
       if (log && log->GetMask().AnySet(mask))
         return log;
       return nullptr;
     }
-
-    // Calls to Enable and disable need to be serialized externally.
-    void Enable(Log &log, const std::shared_ptr<llvm::raw_ostream> &stream_sp,
-                uint32_t options, uint32_t flags);
-
-    // Calls to Enable and disable need to be serialized externally.
-    void Disable(uint32_t flags);
   };
 
   //------------------------------------------------------------------
@@ -115,12 +114,13 @@
 
   //------------------------------------------------------------------
   // 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(Channel &channel) : m_channel(channel) {}
+  ~Log() = default;
 
   void PutCString(const char *cstr);
   void PutString(llvm::StringRef str);
@@ -136,56 +136,59 @@
 
   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;
-
-  Flags &GetMask();
+  const Flags GetOptions() const;
 
-  const Flags &GetMask() const;
+  const Flags GetMask() const;
 
   bool GetVerbose() const;
 
-  void SetStream(const std::shared_ptr<llvm::raw_ostream> &stream_sp) {
-    llvm::sys::ScopedWriter lock(m_stream_mutex);
-    m_stream_sp = stream_sp;
-  }
+private:
+  Channel &m_channel;
 
-  std::shared_ptr<llvm::raw_ostream> GetStream() {
-    llvm::sys::ScopedReader lock(m_stream_mutex);
-    return m_stream_sp;
-  }
+  // The mutex makes sure enable/disable operations are thread-safe. The options
+  // and mask variables are atomic to enable their reading in
+  // Channel::GetLogIfAny without taking the mutex to speed up the fast path.
+  // Their modification however, is still protected by this mutex.
+  llvm::sys::RWMutex m_mutex;
 
-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);
+  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);
+
+  std::shared_ptr<llvm::raw_ostream> GetStream() {
+    llvm::sys::ScopedReader lock(m_mutex);
+    return m_stream_sp;
+  }
+
+  void Enable(const std::shared_ptr<llvm::raw_ostream> &stream_sp,
+              uint32_t options, uint32_t flags);
+
+  void Disable(uint32_t flags);
+
+  typedef llvm::StringMap<Log> ChannelMap;
+  static llvm::ManagedStatic<ChannelMap> g_channel_map;
+
+  static void ListCategories(Stream &stream,
+                             const ChannelMap::value_type &entry);
+  static uint32_t GetFlags(Stream &stream, const ChannelMap::value_type &entry,
+                           llvm::ArrayRef<const char *> categories);
+
+  DISALLOW_COPY_AND_ASSIGN(Log);
 };
 
 } // namespace lldb_private
_______________________________________________
lldb-commits mailing list
lldb-commits@lists.llvm.org
http://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-commits

Reply via email to