diff --git a/rtc_base/logging.cc b/rtc_base/logging.cc index 42f4fa941f..c386600abb 100644 --- a/rtc_base/logging.cc +++ b/rtc_base/logging.cc @@ -64,6 +64,16 @@ const char* FilenameFromPath(const char* file) { return (end1 > end2) ? end1 + 1 : end2 + 1; } +std::ostream& GetNoopStream() { + class NoopStreamBuf : public std::streambuf { + public: + int overflow(int c) override { return c; } + }; + static NoopStreamBuf noop_buffer; + static std::ostream noop_stream(&noop_buffer); + return noop_stream; +} + // Global lock for log subsystem, only needed to serialize access to streams_. CriticalSection g_log_crit; } // namespace @@ -98,7 +108,11 @@ LogMessage::LogMessage(const char* file, LoggingSeverity sev, LogErrorContext err_ctx, int err) - : severity_(sev) { + : severity_(sev), is_noop_(IsNoop(sev)) { + // If there's no need to do any work, let's not :) + if (is_noop_) + return; + if (timestamp_) { // Use SystemTimeMillis so that even if tests use fake clocks, the timestamp // in log messages represents the real system time. @@ -106,14 +120,14 @@ LogMessage::LogMessage(const char* file, // Also ensure WallClockStartTime is initialized, so that it matches // LogStartTime. WallClockStartTime(); - print_stream_ << "[" << rtc::LeftPad('0', 3, rtc::ToString(time / 1000)) - << ":" << rtc::LeftPad('0', 3, rtc::ToString(time % 1000)) + print_stream_ << "[" << std::setfill('0') << std::setw(3) << (time / 1000) + << ":" << std::setw(3) << (time % 1000) << std::setfill(' ') << "] "; } if (thread_) { PlatformThreadId id = CurrentThreadId(); - print_stream_ << "[" << id << "] "; + print_stream_ << "[" << std::dec << id << "] "; } if (file != nullptr) { @@ -170,8 +184,10 @@ LogMessage::LogMessage(const char* file, LoggingSeverity sev, const char* tag) : LogMessage(file, line, sev, ERRCTX_NONE, 0 /* err */) { - tag_ = tag; - print_stream_ << tag << ": "; + if (!is_noop_) { + tag_ = tag; + print_stream_ << tag << ": "; + } } #endif @@ -183,13 +199,21 @@ LogMessage::LogMessage(const char* file, LoggingSeverity sev, const std::string& tag) : LogMessage(file, line, sev) { - print_stream_ << tag << ": "; + if (!is_noop_) + print_stream_ << tag << ": "; } LogMessage::~LogMessage() { + if (is_noop_) + return; + FinishPrintStream(); - const std::string str = print_stream_.Release(); + // TODO(tommi): Unfortunately |ostringstream::str()| always returns a copy + // of the constructed string. This means that we always end up creating + // two copies here (one owned by the stream, one by the return value of + // |str()|). It would be nice to switch to something else. + const std::string str = print_stream_.str(); if (severity_ >= g_dbg_sev) { #if defined(WEBRTC_ANDROID) @@ -213,12 +237,18 @@ LogMessage::~LogMessage() { void LogMessage::AddTag(const char* tag) { #ifdef WEBRTC_ANDROID - tag_ = tag; + if (!is_noop_) { + tag_ = tag; + } #endif } -rtc::StringBuilder& LogMessage::stream() { - return print_stream_; +std::ostream& LogMessage::stream() { + return is_noop_ ? GetNoopStream() : print_stream_; +} + +bool LogMessage::Loggable(LoggingSeverity sev) { + return sev >= g_min_sev; } int LogMessage::GetMinLogSeverity() { @@ -446,23 +476,22 @@ void LogMessage::OutputToDebug(const std::string& str, // static bool LogMessage::IsNoop(LoggingSeverity severity) { - if (severity >= g_dbg_sev || severity >= g_min_sev) + if (severity >= g_dbg_sev) return false; // TODO(tommi): We're grabbing this lock for every LogMessage instance that // is going to be logged. This introduces unnecessary synchronization for // a feature that's mostly used for testing. CritScope cs(&g_log_crit); - if (streams_.size() > 0) - return false; - - return true; + return streams_.size() == 0; } void LogMessage::FinishPrintStream() { + if (is_noop_) + return; if (!extra_.empty()) print_stream_ << " : " << extra_; - print_stream_ << "\n"; + print_stream_ << std::endl; } namespace webrtc_logging_impl { @@ -496,12 +525,6 @@ void Log(const LogArgType* fmt, ...) { return; } } - - if (LogMessage::IsNoop(meta.meta.Severity())) { - va_end(args); - return; - } - LogMessage log_message(meta.meta.File(), meta.meta.Line(), meta.meta.Severity(), meta.err_ctx, meta.err); if (tag) { @@ -541,8 +564,7 @@ void Log(const LogArgType* fmt, ...) { log_message.stream() << *va_arg(args, const std::string*); break; case LogArgType::kVoidP: - log_message.stream() << rtc::ToHex( - reinterpret_cast(va_arg(args, const void*))); + log_message.stream() << va_arg(args, const void*); break; default: RTC_NOTREACHED(); diff --git a/rtc_base/logging.h b/rtc_base/logging.h index 5f2aadb6f5..b5af95928b 100644 --- a/rtc_base/logging.h +++ b/rtc_base/logging.h @@ -57,7 +57,6 @@ #include "rtc_base/constructormagic.h" #include "rtc_base/deprecation.h" -#include "rtc_base/strings/string_builder.h" #include "rtc_base/system/inline.h" #include "rtc_base/thread_annotations.h" @@ -408,7 +407,18 @@ class LogMessage { void AddTag(const char* tag); - rtc::StringBuilder& stream(); + static bool Loggable(LoggingSeverity sev); + + // Same as the above, but using a template argument instead of a function + // argument. (When the logging severity is statically known, passing it as a + // template argument instead of as a function argument saves space at the + // call site.) + template + RTC_NO_INLINE static bool Loggable() { + return Loggable(S); + } + + std::ostream& stream(); // Returns the time at which this function was called for the first time. // The time will be used as the logging start time. @@ -454,12 +464,6 @@ class LogMessage { // Useful for configuring logging from the command line. static void ConfigureLogging(const char* params); - // Checks the current global debug severity and if the |streams_| collection - // is empty. If |severity| is smaller than the global severity and if the - // |streams_| collection is empty, the LogMessage will be considered a noop - // LogMessage. - static bool IsNoop(LoggingSeverity severity); - private: friend class LogMessageForTesting; typedef std::pair StreamAndSeverity; @@ -477,12 +481,18 @@ class LogMessage { static void OutputToDebug(const std::string& msg, LoggingSeverity severity); #endif + // Checks the current global debug severity and if the |streams_| collection + // is empty. If |severity| is smaller than the global severity and if the + // |streams_| collection is empty, the LogMessage will be considered a noop + // LogMessage. + static bool IsNoop(LoggingSeverity severity); + // Called from the dtor (or from a test) to append optional extra error // information to the log stream and a newline character. void FinishPrintStream(); - // The stringbuilder that buffers the formatted message before output - rtc::StringBuilder print_stream_; + // The ostream that buffers the formatted message before output + std::ostringstream print_stream_; // The severity level of this message LoggingSeverity severity_; @@ -496,6 +506,8 @@ class LogMessage { // the message before output. std::string extra_; + const bool is_noop_; + // The output streams and their associated severities static StreamList streams_; @@ -515,11 +527,13 @@ class LogMessage { // DEPRECATED. // TODO(bugs.webrtc.org/9278): Remove once there are no more users. #define RTC_LOG_SEVERITY_PRECONDITION(sev) \ - (rtc::LogMessage::IsNoop(sev)) \ + !(rtc::LogMessage::Loggable(sev)) \ ? static_cast(0) \ : rtc::webrtc_logging_impl::LogMessageVoidify()& #define RTC_LOG(sev) \ + for (bool do_log = rtc::LogMessage::Loggable(); do_log; \ + do_log = false) \ rtc::webrtc_logging_impl::LogCall() & \ rtc::webrtc_logging_impl::LogStreamer<>() \ << rtc::webrtc_logging_impl::LogMetadata(__FILE__, __LINE__, \ @@ -527,6 +541,7 @@ class LogMessage { // The _V version is for when a variable is passed in. #define RTC_LOG_V(sev) \ + for (bool do_log = rtc::LogMessage::Loggable(sev); do_log; do_log = false) \ rtc::webrtc_logging_impl::LogCall() & \ rtc::webrtc_logging_impl::LogStreamer<>() \ << rtc::webrtc_logging_impl::LogMetadata(__FILE__, __LINE__, sev) @@ -549,6 +564,8 @@ inline bool LogCheckLevel(LoggingSeverity sev) { } #define RTC_LOG_E(sev, ctx, err) \ + for (bool do_log = rtc::LogMessage::Loggable(); do_log; \ + do_log = false) \ rtc::webrtc_logging_impl::LogCall() & \ rtc::webrtc_logging_impl::LogStreamer<>() \ << rtc::webrtc_logging_impl::LogMetadataErr { \ @@ -586,6 +603,7 @@ inline const char* AdaptString(const std::string& str) { } // namespace webrtc_logging_impl #define RTC_LOG_TAG(sev, tag) \ + for (bool do_log = rtc::LogMessage::Loggable(sev); do_log; do_log = false) \ rtc::webrtc_logging_impl::LogCall() & \ rtc::webrtc_logging_impl::LogStreamer<>() \ << rtc::webrtc_logging_impl::LogMetadataTag { \ diff --git a/rtc_base/logging_unittest.cc b/rtc_base/logging_unittest.cc index 263e9926d2..af512129fb 100644 --- a/rtc_base/logging_unittest.cc +++ b/rtc_base/logging_unittest.cc @@ -150,6 +150,7 @@ class LogMessageForTesting : public LogMessage { : LogMessage(file, line, sev, err_ctx, err) {} const std::string& get_extra() const { return extra_; } + bool is_noop() const { return is_noop_; } #if defined(WEBRTC_ANDROID) const char* get_tag() const { return tag_; } #endif @@ -162,7 +163,10 @@ class LogMessageForTesting : public LogMessage { RTC_DCHECK(!is_finished_); is_finished_ = true; FinishPrintStream(); - return print_stream_.Release(); + std::string ret = print_stream_.str(); + // Just to make an error even more clear if the stream gets used after this. + print_stream_.clear(); + return ret; } private: @@ -299,6 +303,7 @@ TEST(LogTest, WallClockStartTime) { TEST(LogTest, CheckExtraErrorField) { LogMessageForTesting log_msg("some/path/myfile.cc", 100, LS_WARNING, ERRCTX_ERRNO, 0xD); + ASSERT_FALSE(log_msg.is_noop()); log_msg.stream() << "This gets added at dtor time"; const std::string& extra = log_msg.get_extra(); @@ -309,6 +314,7 @@ TEST(LogTest, CheckExtraErrorField) { TEST(LogTest, CheckFilePathParsed) { LogMessageForTesting log_msg("some/path/myfile.cc", 100, LS_INFO); + ASSERT_FALSE(log_msg.is_noop()); log_msg.stream() << "<- Does this look right?"; const std::string stream = log_msg.GetPrintStream(); @@ -334,6 +340,21 @@ TEST(LogTest, CheckTagAddedToStringInDefaultOnLogMessageAndroid) { } #endif +TEST(LogTest, CheckNoopLogEntry) { + if (LogMessage::GetLogToDebug() <= LS_SENSITIVE) { + printf("CheckNoopLogEntry: skipping. Global severity is being overridden."); + return; + } + + // Logging at LS_SENSITIVE severity, is by default turned off, so this should + // be treated as a noop message. + LogMessageForTesting log_msg("some/path/myfile.cc", 100, LS_SENSITIVE); + log_msg.stream() << "Should be logged to nowhere."; + EXPECT_TRUE(log_msg.is_noop()); + const std::string stream = log_msg.GetPrintStream(); + EXPECT_TRUE(stream.empty()); +} + // Test the time required to write 1000 80-character logs to a string. TEST(LogTest, Perf) { std::string str; @@ -342,7 +363,10 @@ TEST(LogTest, Perf) { const std::string message(80, 'X'); { + // Just to be sure that we're not measuring the performance of logging + // noop log messages. LogMessageForTesting sanity_check_msg(__FILE__, __LINE__, LS_SENSITIVE); + ASSERT_FALSE(sanity_check_msg.is_noop()); } // We now know how many bytes the logging framework will tag onto every msg. diff --git a/rtc_base/stringutils.cc b/rtc_base/stringutils.cc index 6baddd11bd..bef128c229 100644 --- a/rtc_base/stringutils.cc +++ b/rtc_base/stringutils.cc @@ -146,10 +146,4 @@ std::string ToHex(const int i) { return std::string(buffer); } -std::string LeftPad(char padding, unsigned length, std::string s) { - if (s.length() >= length) - return s; - return std::string(length - s.length(), padding) + s; -} - } // namespace rtc diff --git a/rtc_base/stringutils.h b/rtc_base/stringutils.h index 367a673ab4..d92ba0260f 100644 --- a/rtc_base/stringutils.h +++ b/rtc_base/stringutils.h @@ -329,9 +329,6 @@ std::string string_trim(const std::string& s); // TODO(jonasolsson): replace with absl::Hex when that becomes available. std::string ToHex(const int i); - -std::string LeftPad(char padding, unsigned length, std::string s); - } // namespace rtc #endif // RTC_BASE_STRINGUTILS_H_