labath created this revision.
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.
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
@@ -87,9 +87,10 @@
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);
}
@@ -99,27 +100,21 @@
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()); }
@@ -153,19 +148,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 +169,7 @@
// enabled.
//----------------------------------------------------------------------
void Log::Verbose(const char *format, ...) {
- if (!m_options.Test(LLDB_LOG_OPTION_VERBOSE))
+ if (!GetVerbose())
return;
va_list args;
@@ -278,39 +260,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_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);
@@ -325,7 +310,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
@@ -66,16 +66,20 @@
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))
@@ -115,12 +119,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() = default;
+ ~Log() = default;
void PutCString(const char *cstr);
void PutString(llvm::StringRef str);
@@ -136,26 +141,33 @@
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);
@@ -167,25 +179,7 @@
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
_______________________________________________
lldb-commits mailing list
lldb-commits@lists.llvm.org
http://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-commits
