Index: lldb/trunk/include/lldb/Utility/Log.h =================================================================== --- lldb/trunk/include/lldb/Utility/Log.h +++ lldb/trunk/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 @@ -55,6 +56,7 @@ // necessary to enable a log channel in an atomic manner. class Channel { std::atomic log_ptr; + friend class Log; public: const llvm::ArrayRef 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 &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 &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 @@ 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 @@ 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 &stream_sp) { - llvm::sys::ScopedWriter lock(m_stream_mutex); - m_stream_sp = stream_sp; - } +private: + Channel &m_channel; - std::shared_ptr 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 m_stream_sp; - - Flags m_options; - Flags m_mask_bits; - -private: - DISALLOW_COPY_AND_ASSIGN(Log); + std::atomic m_options{0}; + std::atomic m_mask{0}; void WriteHeader(llvm::raw_ostream &OS, llvm::StringRef file, llvm::StringRef function); @@ -186,6 +169,26 @@ void Format(llvm::StringRef file, llvm::StringRef function, const llvm::formatv_object_base &payload); + + std::shared_ptr GetStream() { + llvm::sys::ScopedReader lock(m_mutex); + return m_stream_sp; + } + + void Enable(const std::shared_ptr &stream_sp, + uint32_t options, uint32_t flags); + + void Disable(uint32_t flags); + + typedef llvm::StringMap ChannelMap; + static llvm::ManagedStatic 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 categories); + + DISALLOW_COPY_AND_ASSIGN(Log); }; } // namespace lldb_private Index: lldb/trunk/source/Utility/Log.cpp =================================================================== --- lldb/trunk/source/Utility/Log.cpp +++ lldb/trunk/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::g_channel_map; - ChannelAndLog(Log::Channel &channel) : channel(channel) {} - }; - typedef llvm::StringMap ChannelMap; -} - -static llvm::ManagedStatic 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 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 &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 &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_relaxed); + 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 &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( 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 guard(g_LogThreadedMutex); *stream_sp << message; Index: lldb/trunk/unittests/Utility/LogTest.cpp =================================================================== --- lldb/trunk/unittests/Utility/LogTest.cpp +++ lldb/trunk/unittests/Utility/LogTest.cpp @@ -214,3 +214,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 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 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; +}