From cf3d28f9dfa4e79b5f55c18a5364def61e5e8332 Mon Sep 17 00:00:00 2001 From: Bright Chen Date: Tue, 5 Nov 2024 22:35:37 +0800 Subject: [PATCH] Support backtrace log --- src/bthread/mutex.cpp | 12 +++--------- src/butil/logging.cc | 2 +- src/butil/logging.h | 35 ++++++++++++++++++++++++++++++++++- src/bvar/detail/percentile.h | 2 +- test/logging_unittest.cc | 6 ++++++ 5 files changed, 45 insertions(+), 12 deletions(-) diff --git a/src/bthread/mutex.cpp b/src/bthread/mutex.cpp index fa5f55b5a0..451a5c90e1 100644 --- a/src/bthread/mutex.cpp +++ b/src/bthread/mutex.cpp @@ -544,15 +544,9 @@ void CheckBthreadScheSafety() { return; } - static butil::atomic b_sched_in_p_lock_logged{false}; - if (BAIDU_UNLIKELY(!b_sched_in_p_lock_logged.exchange( - true, butil::memory_order_relaxed))) { - butil::debug::StackTrace trace(true); - // It can only be checked once because the counter is messed up. - LOG(ERROR) << "bthread is suspended while holding " - << tls_pthread_lock_count << " pthread locks." - << std::endl << trace.ToString(); - } + // It can only be checked once because the counter is messed up. + LOG_BACKTRACE_ONCE(ERROR) << "bthread is suspended while holding " + << tls_pthread_lock_count << " pthread locks."; } #else #define ADD_TLS_PTHREAD_LOCK_COUNT ((void)0) diff --git a/src/butil/logging.cc b/src/butil/logging.cc index 14c977bddf..9f2246092c 100644 --- a/src/butil/logging.cc +++ b/src/butil/logging.cc @@ -1334,7 +1334,7 @@ void LogStream::FlushWithoutReset() { } #if !defined(OS_NACL) && !defined(__UCLIBC__) - if (FLAGS_print_stack_on_check && _is_check && _severity == BLOG_FATAL) { + if ((FLAGS_print_stack_on_check && _is_check && _severity == BLOG_FATAL) || _backtrace) { // Include a stack trace on a fatal. butil::debug::StackTrace trace; size_t count = 0; diff --git a/src/butil/logging.h b/src/butil/logging.h index c4f8ef0032..1d03242710 100644 --- a/src/butil/logging.h +++ b/src/butil/logging.h @@ -55,8 +55,25 @@ # define DVPLOG(...) DVLOG(__VA_ARGS__) # endif +#ifndef LOG_BACKTRACE_IF +#define LOG_BACKTRACE_IF(severity, condition) LOG_IF(severity, condition) +#endif + +#ifndef LOG_BACKTRACE_IF_ONCE +#define LOG_BACKTRACE_IF_ONCE(severity, condition) LOG_IF_ONCE(severity, condition) +#endif + +#ifndef LOG_BACKTRACE_FIRST_N +#define LOG_BACKTRACE_FIRST_N(severity, N) LOG_FIRST_N(severity, N) +#endif + +#ifndef LOG_BACKTRACE_IF_FIRST_N +#define LOG_BACKTRACE_IF_FIRST_N(severity, condition, N) LOG_IF_FIRST_N(severity, condition, N) +#endif + + #define LOG_AT(severity, file, line) \ - google::LogMessage(file, line, google::severity).stream() + ::google::LogMessage(file, line, ::google::severity).stream() #else @@ -468,6 +485,8 @@ void print_vlog_sites(VLogSitePrinter*); BAIDU_LAZY_STREAM(LOG_STREAM(severity), LOG_IS_ON(severity)) #define LOG_IF(severity, condition) \ BAIDU_LAZY_STREAM(LOG_STREAM(severity), LOG_IS_ON(severity) && (condition)) +#define LOG_BACKTRACE_IF(severity, condition) \ + BAIDU_LAZY_STREAM(LOG_STREAM(severity).SetBacktrace(), LOG_IS_ON(severity) && (condition)) // FIXME(gejun): Should always crash. #define LOG_ASSERT(condition) \ @@ -942,6 +961,11 @@ friend void DestroyLogStream(LogStream*); return *this; } + LogStream& SetBacktrace() { + _backtrace = true; + return *this; + } + bool empty() const { return pbase() == pptr(); } butil::StringPiece content() const @@ -972,6 +996,7 @@ friend void DestroyLogStream(LogStream*); clear(); SetLastSystemErrorCode(err); _is_check = false; + _backtrace = false; } } @@ -981,6 +1006,7 @@ friend void DestroyLogStream(LogStream*); LogSeverity _severity; bool _noflush; bool _is_check; + bool _backtrace; }; // This class more or less represents a particular log message. You @@ -1231,7 +1257,10 @@ inline std::ostream& operator<<(std::ostream& out, const std::wstring& wstr) { // Almost zero overhead when the log was printed. #ifndef LOG_ONCE # define LOG_ONCE(severity) LOG_FIRST_N(severity, 1) +# define LOG_BACKTRACE_ONCE(severity) LOG_BACKTRACE_FIRST_N(severity, 1) # define LOG_IF_ONCE(severity, condition) LOG_IF_FIRST_N(severity, condition, 1) +# define LOG_BACKTRACE_IF_ONCE(severity, condition) \ + LOG_BACKTRACE_IF_FIRST_N(severity, condition, 1) #endif // Print a log after every N calls. First call always prints. @@ -1250,8 +1279,12 @@ inline std::ostream& operator<<(std::ostream& out, const std::wstring& wstr) { #ifndef LOG_FIRST_N # define LOG_FIRST_N(severity, N) \ BAIDU_LOG_IF_FIRST_N_IMPL(LOG_IF, severity, true, N) +# define LOG_BACKTRACE_FIRST_N(severity, N) \ + BAIDU_LOG_IF_FIRST_N_IMPL(LOG_BACKTRACE_IF, severity, true, N) # define LOG_IF_FIRST_N(severity, condition, N) \ BAIDU_LOG_IF_FIRST_N_IMPL(LOG_IF, severity, condition, N) +# define LOG_BACKTRACE_IF_FIRST_N(severity, condition, N) \ + BAIDU_LOG_IF_FIRST_N_IMPL(LOG_BACKTRACE_IF, severity, condition, N) #endif // Print a log every second. (not present in glog). First call always prints. diff --git a/src/bvar/detail/percentile.h b/src/bvar/detail/percentile.h index f04268d268..5fcc180ab6 100644 --- a/src/bvar/detail/percentile.h +++ b/src/bvar/detail/percentile.h @@ -99,7 +99,7 @@ class PercentileInterval { // No sample should be dropped CHECK_EQ(_num_samples, _num_added) << "_num_added=" << _num_added - << " rhs._num_added" << rhs._num_added + << " rhs._num_added=" << rhs._num_added << " _num_samples=" << _num_samples << " rhs._num_samples=" << rhs._num_samples << " SAMPLE_SIZE=" << SAMPLE_SIZE diff --git a/test/logging_unittest.cc b/test/logging_unittest.cc index 6072044be5..018b2aa535 100644 --- a/test/logging_unittest.cc +++ b/test/logging_unittest.cc @@ -350,6 +350,12 @@ TEST_F(LoggingTest, check) { CHECK_GE(3, 3); } +TEST_F(LoggingTest, log_backtrace) { + LOG_BACKTRACE_IF(INFO, true) << "log_backtrace_if"; + LOG_BACKTRACE_IF_ONCE(INFO, true) << "log_backtrace_if_once"; + LOG_BACKTRACE_ONCE(INFO) << "log_backtrace_once"; +} + int foo(int* p) { return ++*p; }