Fix remaining threading issues in Log.h
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.
Reviewers: zturner, clayborg
Subscribers: lldb-commits
Differential Revision: https://reviews.llvm.org/D30702
llvm-svn: 297368
diff --git a/lldb/source/Utility/Log.cpp b/lldb/source/Utility/Log.cpp
index c87e289..49de39f 100644
--- a/lldb/source/Utility/Log.cpp
+++ b/lldb/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);
+
+ uint32_t mask = m_mask.fetch_or(flags, std::memory_order_relaxed);
+ if (mask | flags) {
+ m_options.store(options, std::memory_order_relaxed);
+ m_stream_sp = stream_sp;
+ m_channel.log_ptr.store(this, std::memory_order_relaxed);
}
}
-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);
+void Log::Disable(uint32_t flags) {
+ llvm::sys::ScopedWriter lock(m_mutex);
+
+ 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);
}
}
-Log::Log() : m_stream_sp(), m_options(0), m_mask_bits(0) {}
+const Flags Log::GetOptions() const {
+ return m_options.load(std::memory_order_relaxed);
+}
-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::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;