Merge pull request apache#2811 from chenBright/log_stack

Support backtrace log

src/bthread/mutex.cpp

@@ -544,15 +544,9 @@ void CheckBthreadScheSafety() {
         return;
     }
 
-    static butil::atomic<bool> 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)

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;

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.

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

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;
 }