[Lldb-commits] [lldb] r297368 - Fix remaining threading issues in Log.h
Pavel Labath via lldb-commits
lldb-commits at lists.llvm.org
Thu Mar 9 02:16:08 PST 2017
Author: labath
Date: Thu Mar 9 04:16:07 2017
New Revision: 297368
URL: http://llvm.org/viewvc/llvm-project?rev=297368&view=rev
Log:
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
Modified:
lldb/trunk/include/lldb/Utility/Log.h
lldb/trunk/source/Utility/Log.cpp
lldb/trunk/unittests/Utility/LogTest.cpp
Modified: lldb/trunk/include/lldb/Utility/Log.h
URL: http://llvm.org/viewvc/llvm-project/lldb/trunk/include/lldb/Utility/Log.h?rev=297368&r1=297367&r2=297368&view=diff
==============================================================================
--- lldb/trunk/include/lldb/Utility/Log.h (original)
+++ lldb/trunk/include/lldb/Utility/Log.h Thu Mar 9 04:16:07 2017
@@ -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 @@ public:
// 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 @@ public:
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 @@ public:
//------------------------------------------------------------------
// 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,9 +136,6 @@ public:
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);
@@ -147,38 +144,24 @@ public:
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);
@@ -186,6 +169,26 @@ private:
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
Modified: lldb/trunk/source/Utility/Log.cpp
URL: http://llvm.org/viewvc/llvm-project/lldb/trunk/source/Utility/Log.cpp?rev=297368&r1=297367&r2=297368&view=diff
==============================================================================
--- lldb/trunk/source/Utility/Log.cpp (original)
+++ lldb/trunk/source/Utility/Log.cpp Thu Mar 9 04:16:07 2017
@@ -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 @@ static uint32_t GetFlags(Stream &stream,
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 @@ static uint32_t GetFlags(Stream &stream,
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) {}
-
-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_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 @@ void Log::VAPrintf(const char *format, v
}
//----------------------------------------------------------------------
-// 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 @@ void Log::VAError(const char *format, va
// 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::Register(llvm::StringRef name,
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 @@ bool Log::EnableLogChannel(
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 @@ bool Log::DisableLogChannel(llvm::String
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 @@ bool Log::ListChannelCategories(llvm::St
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 @@ void Log::ListAllLogChannels(Stream *str
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 @@ void Log::WriteMessage(const std::string
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;
Modified: lldb/trunk/unittests/Utility/LogTest.cpp
URL: http://llvm.org/viewvc/llvm-project/lldb/trunk/unittests/Utility/LogTest.cpp?rev=297368&r1=297367&r2=297368&view=diff
==============================================================================
--- lldb/trunk/unittests/Utility/LogTest.cpp (original)
+++ lldb/trunk/unittests/Utility/LogTest.cpp Thu Mar 9 04:16:07 2017
@@ -214,3 +214,51 @@ TEST_F(LogChannelTest, LogThread) {
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;
+}
More information about the lldb-commits
mailing list