replica
/
hanchenye-llvm-project
2
0
Fork 0
Code Issues Pull Requests Projects Releases Wiki Activity

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
This commit is contained in:
Pavel Labath 2017-03-09 10:16:07 +00:00
parent 8247fefead
commit f5aaa999b9
3 changed files with 144 additions and 121 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

95
lldb/include/lldb/Utility/Log.h
View File

@ -17,6 +17,7 @@
// Other libraries and framework includes // Other libraries and framework includes
#include "llvm/Support/FormatVariadic.h" #include "llvm/Support/FormatVariadic.h"
#include "llvm/Support/ManagedStatic.h"
#include "llvm/Support/RWMutex.h" #include "llvm/Support/RWMutex.h"
// C++ Includes // C++ Includes
#include <atomic> #include <atomic>
@ -55,6 +56,7 @@ public:
// necessary to enable a log channel in an atomic manner. // necessary to enable a log channel in an atomic manner.
class Channel { class Channel {
std::atomic<Log *> log_ptr; std::atomic<Log *> log_ptr;
friend class Log;
public: public:
const llvm::ArrayRef<Category> categories; const llvm::ArrayRef<Category> categories;
@ -66,29 +68,26 @@ public:
default_flags(default_flags) {} default_flags(default_flags) {}
// This function is safe to call at any time // 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 *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)) if (log && log->GetMask().AllSet(mask))
return log; return log;
return nullptr; return nullptr;
} }
// This function is safe to call at any time // 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 *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)) if (log && log->GetMask().AnySet(mask))
return log; return log;
return nullptr; 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 // 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(Channel &channel) : m_channel(channel) {}
~Log() = default;
Log(const std::shared_ptr<llvm::raw_ostream> &stream_sp);
~Log();
void PutCString(const char *cstr); void PutCString(const char *cstr);
void PutString(llvm::StringRef str); void PutString(llvm::StringRef str);
@ -136,9 +136,6 @@ public:
void VAPrintf(const char *format, va_list args); 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 Error(const char *fmt, ...) __attribute__((format(printf, 2, 3)));
void VAError(const char *format, va_list args); void VAError(const char *format, va_list args);
@ -147,38 +144,24 @@ public:
void Warning(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();
const Flags &GetMask() const;
bool GetVerbose() 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;
}
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: private:
DISALLOW_COPY_AND_ASSIGN(Log); Channel &m_channel;
// 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;
std::shared_ptr<llvm::raw_ostream> m_stream_sp;
std::atomic<uint32_t> m_options{0};
std::atomic<uint32_t> m_mask{0};
void WriteHeader(llvm::raw_ostream &OS, llvm::StringRef file, void WriteHeader(llvm::raw_ostream &OS, llvm::StringRef file,
llvm::StringRef function); llvm::StringRef function);
@ -186,6 +169,26 @@ private:
void Format(llvm::StringRef file, llvm::StringRef function, void Format(llvm::StringRef file, llvm::StringRef function,
const llvm::formatv_object_base &payload); 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 } // namespace lldb_private

120
lldb/source/Utility/Log.cpp
View File

@ -18,7 +18,6 @@
#include "llvm/ADT/STLExtras.h" #include "llvm/ADT/STLExtras.h"
#include "llvm/ADT/SmallString.h" #include "llvm/ADT/SmallString.h"
#include "llvm/Support/Chrono.h" #include "llvm/Support/Chrono.h"
#include "llvm/Support/ManagedStatic.h"
#include "llvm/Support/Path.h" #include "llvm/Support/Path.h"
#include "llvm/Support/Signals.h" #include "llvm/Support/Signals.h"
#include "llvm/Support/Threading.h" #include "llvm/Support/Threading.h"
@ -36,27 +35,17 @@
using namespace lldb; using namespace lldb;
using namespace lldb_private; using namespace lldb_private;
namespace { llvm::ManagedStatic<Log::ChannelMap> Log::g_channel_map;
struct ChannelAndLog {
Log log;
Log::Channel &channel;
ChannelAndLog(Log::Channel &channel) : channel(channel) {} void Log::ListCategories(Stream &stream, const ChannelMap::value_type &entry) {
};
typedef llvm::StringMap<ChannelAndLog> ChannelMap;
}
static llvm::ManagedStatic<ChannelMap> g_channel_map;
static void ListCategories(Stream &stream, const ChannelMap::value_type &entry) {
stream.Format("Logging categories for '{0}':\n", entry.first()); stream.Format("Logging categories for '{0}':\n", entry.first());
stream.Format(" all - all available logging categories\n"); stream.Format(" all - all available logging categories\n");
stream.Format(" default - default set of 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); 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) { llvm::ArrayRef<const char *> categories) {
bool list_categories = false; bool list_categories = false;
uint32_t flags = 0; uint32_t flags = 0;
@ -66,13 +55,13 @@ static uint32_t GetFlags(Stream &stream, const ChannelMap::value_type &entry,
continue; continue;
} }
if (llvm::StringRef("default").equals_lower(category)) { if (llvm::StringRef("default").equals_lower(category)) {
flags |= entry.second.channel.default_flags; flags |= entry.second.m_channel.default_flags;
continue; continue;
} }
auto cat = llvm::find_if( auto cat = llvm::find_if(
entry.second.channel.categories, entry.second.m_channel.categories,
[&](const Log::Category &c) { return c.name.equals_lower(category); }); [&](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; flags |= cat->flag;
continue; continue;
} }
@ -84,42 +73,35 @@ static uint32_t GetFlags(Stream &stream, const ChannelMap::value_type &entry,
return flags; return flags;
} }
void Log::Channel::Enable(Log &log, void Log::Enable(const std::shared_ptr<llvm::raw_ostream> &stream_sp,
const std::shared_ptr<llvm::raw_ostream> &stream_sp,
uint32_t options, uint32_t flags) { uint32_t options, uint32_t flags) {
log.GetMask().Set(flags); llvm::sys::ScopedWriter lock(m_mutex);
if (log.GetMask().Get()) {
log.GetOptions().Reset(options); uint32_t mask = m_mask.fetch_or(flags, std::memory_order_relaxed);
log.SetStream(stream_sp); if (mask | flags) {
log_ptr.store(&log, std::memory_order_release); 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) { void Log::Disable(uint32_t flags) {
Log *log = log_ptr.load(std::memory_order_acquire); llvm::sys::ScopedWriter lock(m_mutex);
if (!log)
return; uint32_t mask = m_mask.fetch_and(~flags, std::memory_order_relaxed);
log->GetMask().Clear(flags); if (!(mask & ~flags)) {
if (!log->GetMask().Get()) { m_stream_sp.reset();
log->SetStream(nullptr); m_channel.log_ptr.store(nullptr, std::memory_order_relaxed);
log_ptr.store(nullptr, std::memory_order_release);
} }
} }
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) const Flags Log::GetMask() const {
: m_stream_sp(stream_sp), m_options(0), m_mask_bits(0) {} return m_mask.load(std::memory_order_relaxed);
}
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; }
void Log::PutCString(const char *cstr) { Printf("%s", cstr); } void Log::PutCString(const char *cstr) { Printf("%s", cstr); }
void Log::PutString(llvm::StringRef str) { PutCString(str.str().c_str()); } void Log::PutString(llvm::StringRef str) { PutCString(str.str().c_str()); }
@ -152,19 +134,6 @@ void Log::VAPrintf(const char *format, va_list args) {
WriteMessage(FinalMessage.str()); 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. // Printing of errors that are not fatal.
//---------------------------------------------------------------------- //----------------------------------------------------------------------
@ -187,7 +156,7 @@ void Log::VAError(const char *format, va_list args) {
// enabled. // enabled.
//---------------------------------------------------------------------- //----------------------------------------------------------------------
void Log::Verbose(const char *format, ...) { void Log::Verbose(const char *format, ...) {
if (!m_options.Test(LLDB_LOG_OPTION_VERBOSE)) if (!GetVerbose())
return; return;
va_list args; va_list args;
@ -218,7 +187,7 @@ void Log::Register(llvm::StringRef name, Channel &channel) {
void Log::Unregister(llvm::StringRef name) { void Log::Unregister(llvm::StringRef name) {
auto iter = g_channel_map->find(name); auto iter = g_channel_map->find(name);
assert(iter != g_channel_map->end()); assert(iter != g_channel_map->end());
iter->second.channel.Disable(UINT32_MAX); iter->second.Disable(UINT32_MAX);
g_channel_map->erase(iter); g_channel_map->erase(iter);
} }
@ -232,10 +201,9 @@ bool Log::EnableLogChannel(
return false; return false;
} }
uint32_t flags = categories.empty() uint32_t flags = categories.empty()
? iter->second.channel.default_flags ? iter->second.m_channel.default_flags
: GetFlags(error_stream, *iter, categories); : GetFlags(error_stream, *iter, categories);
iter->second.channel.Enable(iter->second.log, log_stream_sp, log_options, iter->second.Enable(log_stream_sp, log_options, flags);
flags);
return true; return true;
} }
@ -250,7 +218,7 @@ bool Log::DisableLogChannel(llvm::StringRef channel,
uint32_t flags = categories.empty() uint32_t flags = categories.empty()
? UINT32_MAX ? UINT32_MAX
: GetFlags(error_stream, *iter, categories); : GetFlags(error_stream, *iter, categories);
iter->second.channel.Disable(flags); iter->second.Disable(flags);
return true; return true;
} }
@ -266,7 +234,7 @@ bool Log::ListChannelCategories(llvm::StringRef channel, Stream &stream) {
void Log::DisableAllLogChannels(Stream *feedback_strm) { void Log::DisableAllLogChannels(Stream *feedback_strm) {
for (auto &entry : *g_channel_map) for (auto &entry : *g_channel_map)
entry.second.channel.Disable(UINT32_MAX); entry.second.Disable(UINT32_MAX);
} }
void Log::ListAllLogChannels(Stream *strm) { void Log::ListAllLogChannels(Stream *strm) {
@ -278,39 +246,42 @@ void Log::ListAllLogChannels(Stream *strm) {
for (const auto &channel : *g_channel_map) for (const auto &channel : *g_channel_map)
ListCategories(*strm, channel); 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, void Log::WriteHeader(llvm::raw_ostream &OS, llvm::StringRef file,
llvm::StringRef function) { llvm::StringRef function) {
Flags options = GetOptions();
static uint32_t g_sequence_id = 0; static uint32_t g_sequence_id = 0;
// Add a sequence ID if requested // 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 << " "; OS << ++g_sequence_id << " ";
// Timestamp if requested // 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>( auto now = std::chrono::duration<double>(
std::chrono::system_clock::now().time_since_epoch()); std::chrono::system_clock::now().time_since_epoch());
OS << llvm::formatv("{0:f9} ", now.count()); OS << llvm::formatv("{0:f9} ", now.count());
} }
// Add the process and thread if requested // 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(), OS << llvm::formatv("[{0,0+4}/{1,0+4}] ", getpid(),
llvm::get_threadid()); llvm::get_threadid());
// Add the thread name if requested // 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::SmallString<32> thread_name;
llvm::get_thread_name(thread_name); llvm::get_thread_name(thread_name);
if (!thread_name.empty()) if (!thread_name.empty())
OS << thread_name; OS << thread_name;
} }
if (m_options.Test(LLDB_LOG_OPTION_BACKTRACE)) if (options.Test(LLDB_LOG_OPTION_BACKTRACE))
llvm::sys::PrintStackTrace(OS); 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.empty() || !function.empty())) {
file = llvm::sys::path::filename(file).take_front(40); file = llvm::sys::path::filename(file).take_front(40);
function = function.take_front(40); function = function.take_front(40);
@ -325,7 +296,8 @@ void Log::WriteMessage(const std::string &message) {
if (!stream_sp) if (!stream_sp)
return; 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; static std::recursive_mutex g_LogThreadedMutex;
std::lock_guard<std::recursive_mutex> guard(g_LogThreadedMutex); std::lock_guard<std::recursive_mutex> guard(g_LogThreadedMutex);
*stream_sp << message; *stream_sp << message;

48
lldb/unittests/Utility/LogTest.cpp
View File

@ -214,3 +214,51 @@ TEST_F(LogChannelTest, LogThread) {
EXPECT_TRUE(stream_sp->str() == "" || stream_sp->str() == "Hello World\n") EXPECT_TRUE(stream_sp->str() == "" || stream_sp->str() == "Hello World\n")
<< "str(): " << stream_sp->str(); << "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;
}