Revert "Consolidate loggability checks and replace streams."

This reverts commit 4092cd6db459ab8152588143b7b76e0946d2c433.

Reason for revert: Some g3 things depend on log macro implementation details.

Original change's description:
> Consolidate loggability checks and replace streams.
> 
> Currently we check if a message should be printed at the call site using LogMessage::Loggable, in the LogMessage itself using LogMessage::IsNoop and in LogMessage::OutputToDebug using log_to_stderr_.
> 
> This change unifies the first two of these into a early return in Log().
> 
> Bug: webrtc:8982
> Change-Id: Ia4e3e12b34716d76c05807e44db1ed4a62dffb87
> Reviewed-on: https://webrtc-review.googlesource.com/97440
> Commit-Queue: Jonas Olsson <jonasolsson@webrtc.org>
> Reviewed-by: Karl Wiberg <kwiberg@webrtc.org>
> Cr-Commit-Position: refs/heads/master@{#24547}

TBR=kwiberg@webrtc.org,jonasolsson@webrtc.org

Change-Id: I06f0a5b50c96c08a5e7be4d8d2bcb22d50c0179f
No-Presubmit: true
No-Tree-Checks: true
No-Try: true
Bug: webrtc:8982
Reviewed-on: https://webrtc-review.googlesource.com/97720
Reviewed-by: Jonas Olsson <jonasolsson@webrtc.org>
Commit-Queue: Jonas Olsson <jonasolsson@webrtc.org>
Cr-Commit-Position: refs/heads/master@{#24553}
This commit is contained in:
Jonas Olsson
2018-09-04 13:42:08 +00:00
committed by Commit Bot
parent 4c6747c9db
commit 46d65e2c2c
5 changed files with 101 additions and 46 deletions

View File

@ -64,6 +64,16 @@ const char* FilenameFromPath(const char* file) {
return (end1 > end2) ? end1 + 1 : end2 + 1; 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_. // Global lock for log subsystem, only needed to serialize access to streams_.
CriticalSection g_log_crit; CriticalSection g_log_crit;
} // namespace } // namespace
@ -98,7 +108,11 @@ LogMessage::LogMessage(const char* file,
LoggingSeverity sev, LoggingSeverity sev,
LogErrorContext err_ctx, LogErrorContext err_ctx,
int err) 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_) { if (timestamp_) {
// Use SystemTimeMillis so that even if tests use fake clocks, the timestamp // Use SystemTimeMillis so that even if tests use fake clocks, the timestamp
// in log messages represents the real system time. // 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 // Also ensure WallClockStartTime is initialized, so that it matches
// LogStartTime. // LogStartTime.
WallClockStartTime(); WallClockStartTime();
print_stream_ << "[" << rtc::LeftPad('0', 3, rtc::ToString(time / 1000)) print_stream_ << "[" << std::setfill('0') << std::setw(3) << (time / 1000)
<< ":" << rtc::LeftPad('0', 3, rtc::ToString(time % 1000)) << ":" << std::setw(3) << (time % 1000) << std::setfill(' ')
<< "] "; << "] ";
} }
if (thread_) { if (thread_) {
PlatformThreadId id = CurrentThreadId(); PlatformThreadId id = CurrentThreadId();
print_stream_ << "[" << id << "] "; print_stream_ << "[" << std::dec << id << "] ";
} }
if (file != nullptr) { if (file != nullptr) {
@ -170,8 +184,10 @@ LogMessage::LogMessage(const char* file,
LoggingSeverity sev, LoggingSeverity sev,
const char* tag) const char* tag)
: LogMessage(file, line, sev, ERRCTX_NONE, 0 /* err */) { : LogMessage(file, line, sev, ERRCTX_NONE, 0 /* err */) {
if (!is_noop_) {
tag_ = tag; tag_ = tag;
print_stream_ << tag << ": "; print_stream_ << tag << ": ";
}
} }
#endif #endif
@ -183,13 +199,21 @@ LogMessage::LogMessage(const char* file,
LoggingSeverity sev, LoggingSeverity sev,
const std::string& tag) const std::string& tag)
: LogMessage(file, line, sev) { : LogMessage(file, line, sev) {
if (!is_noop_)
print_stream_ << tag << ": "; print_stream_ << tag << ": ";
} }
LogMessage::~LogMessage() { LogMessage::~LogMessage() {
if (is_noop_)
return;
FinishPrintStream(); 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 (severity_ >= g_dbg_sev) {
#if defined(WEBRTC_ANDROID) #if defined(WEBRTC_ANDROID)
@ -213,12 +237,18 @@ LogMessage::~LogMessage() {
void LogMessage::AddTag(const char* tag) { void LogMessage::AddTag(const char* tag) {
#ifdef WEBRTC_ANDROID #ifdef WEBRTC_ANDROID
if (!is_noop_) {
tag_ = tag; tag_ = tag;
}
#endif #endif
} }
rtc::StringBuilder& LogMessage::stream() { std::ostream& LogMessage::stream() {
return print_stream_; return is_noop_ ? GetNoopStream() : print_stream_;
}
bool LogMessage::Loggable(LoggingSeverity sev) {
return sev >= g_min_sev;
} }
int LogMessage::GetMinLogSeverity() { int LogMessage::GetMinLogSeverity() {
@ -446,23 +476,22 @@ void LogMessage::OutputToDebug(const std::string& str,
// static // static
bool LogMessage::IsNoop(LoggingSeverity severity) { bool LogMessage::IsNoop(LoggingSeverity severity) {
if (severity >= g_dbg_sev || severity >= g_min_sev) if (severity >= g_dbg_sev)
return false; return false;
// TODO(tommi): We're grabbing this lock for every LogMessage instance that // TODO(tommi): We're grabbing this lock for every LogMessage instance that
// is going to be logged. This introduces unnecessary synchronization for // is going to be logged. This introduces unnecessary synchronization for
// a feature that's mostly used for testing. // a feature that's mostly used for testing.
CritScope cs(&g_log_crit); CritScope cs(&g_log_crit);
if (streams_.size() > 0) return streams_.size() == 0;
return false;
return true;
} }
void LogMessage::FinishPrintStream() { void LogMessage::FinishPrintStream() {
if (is_noop_)
return;
if (!extra_.empty()) if (!extra_.empty())
print_stream_ << " : " << extra_; print_stream_ << " : " << extra_;
print_stream_ << "\n"; print_stream_ << std::endl;
} }
namespace webrtc_logging_impl { namespace webrtc_logging_impl {
@ -496,12 +525,6 @@ void Log(const LogArgType* fmt, ...) {
return; return;
} }
} }
if (LogMessage::IsNoop(meta.meta.Severity())) {
va_end(args);
return;
}
LogMessage log_message(meta.meta.File(), meta.meta.Line(), LogMessage log_message(meta.meta.File(), meta.meta.Line(),
meta.meta.Severity(), meta.err_ctx, meta.err); meta.meta.Severity(), meta.err_ctx, meta.err);
if (tag) { if (tag) {
@ -541,8 +564,7 @@ void Log(const LogArgType* fmt, ...) {
log_message.stream() << *va_arg(args, const std::string*); log_message.stream() << *va_arg(args, const std::string*);
break; break;
case LogArgType::kVoidP: case LogArgType::kVoidP:
log_message.stream() << rtc::ToHex( log_message.stream() << va_arg(args, const void*);
reinterpret_cast<uintptr_t>(va_arg(args, const void*)));
break; break;
default: default:
RTC_NOTREACHED(); RTC_NOTREACHED();

View File

@ -57,7 +57,6 @@
#include "rtc_base/constructormagic.h" #include "rtc_base/constructormagic.h"
#include "rtc_base/deprecation.h" #include "rtc_base/deprecation.h"
#include "rtc_base/strings/string_builder.h"
#include "rtc_base/system/inline.h" #include "rtc_base/system/inline.h"
#include "rtc_base/thread_annotations.h" #include "rtc_base/thread_annotations.h"
@ -408,7 +407,18 @@ class LogMessage {
void AddTag(const char* tag); 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 <LoggingSeverity S>
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. // Returns the time at which this function was called for the first time.
// The time will be used as the logging start 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. // Useful for configuring logging from the command line.
static void ConfigureLogging(const char* params); 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: private:
friend class LogMessageForTesting; friend class LogMessageForTesting;
typedef std::pair<LogSink*, LoggingSeverity> StreamAndSeverity; typedef std::pair<LogSink*, LoggingSeverity> StreamAndSeverity;
@ -477,12 +481,18 @@ class LogMessage {
static void OutputToDebug(const std::string& msg, LoggingSeverity severity); static void OutputToDebug(const std::string& msg, LoggingSeverity severity);
#endif #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 // Called from the dtor (or from a test) to append optional extra error
// information to the log stream and a newline character. // information to the log stream and a newline character.
void FinishPrintStream(); void FinishPrintStream();
// The stringbuilder that buffers the formatted message before output // The ostream that buffers the formatted message before output
rtc::StringBuilder print_stream_; std::ostringstream print_stream_;
// The severity level of this message // The severity level of this message
LoggingSeverity severity_; LoggingSeverity severity_;
@ -496,6 +506,8 @@ class LogMessage {
// the message before output. // the message before output.
std::string extra_; std::string extra_;
const bool is_noop_;
// The output streams and their associated severities // The output streams and their associated severities
static StreamList streams_; static StreamList streams_;
@ -515,11 +527,13 @@ class LogMessage {
// DEPRECATED. // DEPRECATED.
// TODO(bugs.webrtc.org/9278): Remove once there are no more users. // TODO(bugs.webrtc.org/9278): Remove once there are no more users.
#define RTC_LOG_SEVERITY_PRECONDITION(sev) \ #define RTC_LOG_SEVERITY_PRECONDITION(sev) \
(rtc::LogMessage::IsNoop(sev)) \ !(rtc::LogMessage::Loggable(sev)) \
? static_cast<void>(0) \ ? static_cast<void>(0) \
: rtc::webrtc_logging_impl::LogMessageVoidify()& : rtc::webrtc_logging_impl::LogMessageVoidify()&
#define RTC_LOG(sev) \ #define RTC_LOG(sev) \
for (bool do_log = rtc::LogMessage::Loggable<rtc::sev>(); do_log; \
do_log = false) \
rtc::webrtc_logging_impl::LogCall() & \ rtc::webrtc_logging_impl::LogCall() & \
rtc::webrtc_logging_impl::LogStreamer<>() \ rtc::webrtc_logging_impl::LogStreamer<>() \
<< rtc::webrtc_logging_impl::LogMetadata(__FILE__, __LINE__, \ << rtc::webrtc_logging_impl::LogMetadata(__FILE__, __LINE__, \
@ -527,6 +541,7 @@ class LogMessage {
// The _V version is for when a variable is passed in. // The _V version is for when a variable is passed in.
#define RTC_LOG_V(sev) \ #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::LogCall() & \
rtc::webrtc_logging_impl::LogStreamer<>() \ rtc::webrtc_logging_impl::LogStreamer<>() \
<< rtc::webrtc_logging_impl::LogMetadata(__FILE__, __LINE__, sev) << rtc::webrtc_logging_impl::LogMetadata(__FILE__, __LINE__, sev)
@ -549,6 +564,8 @@ inline bool LogCheckLevel(LoggingSeverity sev) {
} }
#define RTC_LOG_E(sev, ctx, err) \ #define RTC_LOG_E(sev, ctx, err) \
for (bool do_log = rtc::LogMessage::Loggable<rtc::sev>(); do_log; \
do_log = false) \
rtc::webrtc_logging_impl::LogCall() & \ rtc::webrtc_logging_impl::LogCall() & \
rtc::webrtc_logging_impl::LogStreamer<>() \ rtc::webrtc_logging_impl::LogStreamer<>() \
<< rtc::webrtc_logging_impl::LogMetadataErr { \ << rtc::webrtc_logging_impl::LogMetadataErr { \
@ -586,6 +603,7 @@ inline const char* AdaptString(const std::string& str) {
} // namespace webrtc_logging_impl } // namespace webrtc_logging_impl
#define RTC_LOG_TAG(sev, tag) \ #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::LogCall() & \
rtc::webrtc_logging_impl::LogStreamer<>() \ rtc::webrtc_logging_impl::LogStreamer<>() \
<< rtc::webrtc_logging_impl::LogMetadataTag { \ << rtc::webrtc_logging_impl::LogMetadataTag { \

View File

@ -150,6 +150,7 @@ class LogMessageForTesting : public LogMessage {
: LogMessage(file, line, sev, err_ctx, err) {} : LogMessage(file, line, sev, err_ctx, err) {}
const std::string& get_extra() const { return extra_; } const std::string& get_extra() const { return extra_; }
bool is_noop() const { return is_noop_; }
#if defined(WEBRTC_ANDROID) #if defined(WEBRTC_ANDROID)
const char* get_tag() const { return tag_; } const char* get_tag() const { return tag_; }
#endif #endif
@ -162,7 +163,10 @@ class LogMessageForTesting : public LogMessage {
RTC_DCHECK(!is_finished_); RTC_DCHECK(!is_finished_);
is_finished_ = true; is_finished_ = true;
FinishPrintStream(); 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: private:
@ -299,6 +303,7 @@ TEST(LogTest, WallClockStartTime) {
TEST(LogTest, CheckExtraErrorField) { TEST(LogTest, CheckExtraErrorField) {
LogMessageForTesting log_msg("some/path/myfile.cc", 100, LS_WARNING, LogMessageForTesting log_msg("some/path/myfile.cc", 100, LS_WARNING,
ERRCTX_ERRNO, 0xD); ERRCTX_ERRNO, 0xD);
ASSERT_FALSE(log_msg.is_noop());
log_msg.stream() << "This gets added at dtor time"; log_msg.stream() << "This gets added at dtor time";
const std::string& extra = log_msg.get_extra(); const std::string& extra = log_msg.get_extra();
@ -309,6 +314,7 @@ TEST(LogTest, CheckExtraErrorField) {
TEST(LogTest, CheckFilePathParsed) { TEST(LogTest, CheckFilePathParsed) {
LogMessageForTesting log_msg("some/path/myfile.cc", 100, LS_INFO); LogMessageForTesting log_msg("some/path/myfile.cc", 100, LS_INFO);
ASSERT_FALSE(log_msg.is_noop());
log_msg.stream() << "<- Does this look right?"; log_msg.stream() << "<- Does this look right?";
const std::string stream = log_msg.GetPrintStream(); const std::string stream = log_msg.GetPrintStream();
@ -334,6 +340,21 @@ TEST(LogTest, CheckTagAddedToStringInDefaultOnLogMessageAndroid) {
} }
#endif #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 the time required to write 1000 80-character logs to a string.
TEST(LogTest, Perf) { TEST(LogTest, Perf) {
std::string str; std::string str;
@ -342,7 +363,10 @@ TEST(LogTest, Perf) {
const std::string message(80, 'X'); 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); 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. // We now know how many bytes the logging framework will tag onto every msg.

View File

@ -146,10 +146,4 @@ std::string ToHex(const int i) {
return std::string(buffer); 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 } // namespace rtc

View File

@ -329,9 +329,6 @@ std::string string_trim(const std::string& s);
// TODO(jonasolsson): replace with absl::Hex when that becomes available. // TODO(jonasolsson): replace with absl::Hex when that becomes available.
std::string ToHex(const int i); std::string ToHex(const int i);
std::string LeftPad(char padding, unsigned length, std::string s);
} // namespace rtc } // namespace rtc
#endif // RTC_BASE_STRINGUTILS_H_ #endif // RTC_BASE_STRINGUTILS_H_