rtc::Event::Wait(kForever): Print stack trace when we deadlock

After being stuck "forever" (3 seconds) waiting for an event to
trigger, log the stack trace of the current thread to aid debugging of
the deadlock.

Bug: webrtc:10308
Change-Id: I04852f191027294d7e7a7f5e63de4c6c7fdd6326
Reviewed-on: https://webrtc-review.googlesource.com/c/src/+/128342
Commit-Queue: Karl Wiberg <kwiberg@webrtc.org>
Reviewed-by: Magnus Jedvert <magjed@webrtc.org>
Cr-Commit-Position: refs/heads/master@{#27263}

rtc_base/BUILD.gn

@@ -247,23 +247,25 @@ rtc_source_set("platform_thread") {
 }
 
 rtc_source_set("rtc_event") {
-  deps = [
-    ":checks",
-  ]
-
   if (build_with_chromium) {
-    # Dependency on chromium's waitable_event (in //base).
-    deps += [ "//base" ]
     sources = [
       "../../webrtc_overrides/rtc_base/event.cc",
       "../../webrtc_overrides/rtc_base/event.h",
     ]
+    deps = [
+      ":checks",
+      "//base",  # Dependency on chromium's waitable_event.
+    ]
   } else {
-    deps += [ "synchronization:yield_policy" ]
     sources = [
       "event.cc",
       "event.h",
     ]
+    deps = [
+      ":checks",
+      "synchronization:yield_policy",
+      "system:warn_current_thread_is_deadlocked",
+    ]
   }
 }
 

rtc_base/event.cc

@@ -13,6 +13,7 @@
 #if defined(WEBRTC_WIN)
 #include <windows.h>
 #elif defined(WEBRTC_POSIX)
+#include <errno.h>
 #include <pthread.h>
 #include <sys/time.h>
 #include <time.h>
@@ -22,6 +23,7 @@
 
 #include "rtc_base/checks.h"
 #include "rtc_base/synchronization/yield_policy.h"
+#include "rtc_base/system/warn_current_thread_is_deadlocked.h"
 
 namespace rtc {
 
@@ -103,45 +105,65 @@ void Event::Reset() {
   pthread_mutex_unlock(&event_mutex_);
 }
 
-bool Event::Wait(int milliseconds) {
-  ScopedYieldPolicy::YieldExecution();
+namespace {
 
-  int error = 0;
+timespec GetTimespec(const int milliseconds_from_now) {
+  timespec ts;
 
-  struct timespec ts;
-  if (milliseconds != kForever) {
+  // Get the current time.
 #if USE_CLOCK_GETTIME
-    clock_gettime(CLOCK_MONOTONIC, &ts);
+  clock_gettime(CLOCK_MONOTONIC, &ts);
 #else
-    struct timeval tv;
-    gettimeofday(&tv, nullptr);
-    ts.tv_sec = tv.tv_sec;
-    ts.tv_nsec = tv.tv_usec * 1000;
+  timeval tv;
+  gettimeofday(&tv, nullptr);
+  ts.tv_sec = tv.tv_sec;
+  ts.tv_nsec = tv.tv_usec * 1000;
 #endif
 
-    ts.tv_sec += (milliseconds / 1000);
-    ts.tv_nsec += (milliseconds % 1000) * 1000000;
+  // Add the specified number of milliseconds to it.
+  ts.tv_sec += (milliseconds_from_now / 1000);
+  ts.tv_nsec += (milliseconds_from_now % 1000) * 1000000;
 
-    // Handle overflow.
-    if (ts.tv_nsec >= 1000000000) {
-      ts.tv_sec++;
-      ts.tv_nsec -= 1000000000;
-    }
+  // Normalize.
+  if (ts.tv_nsec >= 1000000000) {
+    ts.tv_sec++;
+    ts.tv_nsec -= 1000000000;
   }
 
+  return ts;
+}
+
+}  // namespace
+
+bool Event::Wait(const int milliseconds) {
+  // Set a timeout for the given number of milliseconds, or 3000 ms if the
+  // caller asked for kForever.
+  const timespec ts =
+      GetTimespec(milliseconds == kForever ? 3000 : milliseconds);
+
+  ScopedYieldPolicy::YieldExecution();
   pthread_mutex_lock(&event_mutex_);
-  if (milliseconds != kForever) {
-    while (!event_status_ && error == 0) {
+
+  // Wait for the event to trigger or the timeout to expire, whichever comes
+  // first.
+  int error = 0;
+  while (!event_status_ && error == 0) {
 #if USE_PTHREAD_COND_TIMEDWAIT_MONOTONIC_NP
-      error =
-          pthread_cond_timedwait_monotonic_np(&event_cond_, &event_mutex_, &ts);
+    error =
+        pthread_cond_timedwait_monotonic_np(&event_cond_, &event_mutex_, &ts);
 #else
-      error = pthread_cond_timedwait(&event_cond_, &event_mutex_, &ts);
+    error = pthread_cond_timedwait(&event_cond_, &event_mutex_, &ts);
 #endif
-    }
-  } else {
-    while (!event_status_ && error == 0)
+  }
+
+  if (milliseconds == kForever && error == ETIMEDOUT) {
+    // Our 3000 ms timeout expired, but the caller asked us to wait forever, so
+    // do that.
+    webrtc::WarnThatTheCurrentThreadIsProbablyDeadlocked();
+    error = 0;
+    while (!event_status_ && error == 0) {
       error = pthread_cond_wait(&event_cond_, &event_mutex_);
+    }
   }
 
   // NOTE(liulk): Exactly one thread will auto-reset this event. All

rtc_base/system/BUILD.gn

@@ -94,3 +94,17 @@ rtc_source_set("thread_registry") {
     ]
   }
 }
+
+rtc_source_set("warn_current_thread_is_deadlocked") {
+  sources = [
+    "warn_current_thread_is_deadlocked.h",
+  ]
+  deps = []
+  if (is_android && !build_with_chromium) {
+    sources += [ "warn_current_thread_is_deadlocked.cc" ]
+    deps += [
+      "..:logging",
+      "../../sdk/android:native_api_stacktrace",
+    ]
+  }
+}

rtc_base/system/DEPS

@@ -2,4 +2,7 @@ specific_include_rules = {
   "thread_registry\.cc": [
     "+sdk/android/native_api/stacktrace/stacktrace.h",
   ],
+  "warn_current_thread_is_deadlocked\.cc": [
+    "+sdk/android/native_api/stacktrace/stacktrace.h",
+  ],
 }

rtc_base/system/warn_current_thread_is_deadlocked.cc

@@ -0,0 +1,23 @@
+/*
+ *  Copyright 2019 The WebRTC Project Authors. All rights reserved.
+ *
+ *  Use of this source code is governed by a BSD-style license
+ *  that can be found in the LICENSE file in the root of the source
+ *  tree. An additional intellectual property rights grant can be found
+ *  in the file PATENTS.  All contributing project authors may
+ *  be found in the AUTHORS file in the root of the source tree.
+ */
+
+#include "rtc_base/system/warn_current_thread_is_deadlocked.h"
+
+#include "rtc_base/logging.h"
+#include "sdk/android/native_api/stacktrace/stacktrace.h"
+
+namespace webrtc {
+
+void WarnThatTheCurrentThreadIsProbablyDeadlocked() {
+  RTC_LOG(LS_WARNING) << "Probable deadlock:";
+  RTC_LOG(LS_WARNING) << StackTraceToString(GetStackTrace());
+}
+
+}  // namespace webrtc

rtc_base/system/warn_current_thread_is_deadlocked.h

@@ -0,0 +1,24 @@
+/*
+ *  Copyright 2019 The WebRTC Project Authors. All rights reserved.
+ *
+ *  Use of this source code is governed by a BSD-style license
+ *  that can be found in the LICENSE file in the root of the source
+ *  tree. An additional intellectual property rights grant can be found
+ *  in the file PATENTS.  All contributing project authors may
+ *  be found in the AUTHORS file in the root of the source tree.
+ */
+
+#ifndef RTC_BASE_SYSTEM_WARN_CURRENT_THREAD_IS_DEADLOCKED_H_
+#define RTC_BASE_SYSTEM_WARN_CURRENT_THREAD_IS_DEADLOCKED_H_
+
+namespace webrtc {
+
+#if defined(WEBRTC_ANDROID) && !defined(WEBRTC_CHROMIUM_BUILD)
+void WarnThatTheCurrentThreadIsProbablyDeadlocked();
+#else
+inline void WarnThatTheCurrentThreadIsProbablyDeadlocked() {}
+#endif
+
+}  // namespace webrtc
+
+#endif  // RTC_BASE_SYSTEM_WARN_CURRENT_THREAD_IS_DEADLOCKED_H_

sdk/android/native_unittests/stacktrace/stacktrace_unittest.cc

@@ -200,6 +200,22 @@ void TestStacktrace(std::unique_ptr<DeadlockInterface> deadlock_impl) {
   thread.Stop();
 }
 
+class LookoutLogSink final : public rtc::LogSink {
+ public:
+  explicit LookoutLogSink(std::string look_for)
+      : look_for_(std::move(look_for)) {}
+  void OnLogMessage(const std::string& message) override {
+    if (message.find(look_for_) != std::string::npos) {
+      when_found_.Set();
+    }
+  }
+  rtc::Event& WhenFound() { return when_found_; }
+
+ private:
+  const std::string look_for_;
+  rtc::Event when_found_;
+};
+
 }  // namespace
 
 TEST(Stacktrace, TestCurrentThread) {
@@ -223,6 +239,7 @@ TEST(Stacktrace, TestSleep) {
 // Stack traces originating from kernel space does not include user space stack
 // traces for ARM 32.
 #ifdef WEBRTC_ARCH_ARM64
+
 TEST(Stacktrace, TestRtcEvent) {
   TestStacktrace(absl::make_unique<RtcEventDeadlock>());
 }
@@ -230,7 +247,33 @@ TEST(Stacktrace, TestRtcEvent) {
 TEST(Stacktrace, TestRtcCriticalSection) {
   TestStacktrace(absl::make_unique<RtcCriticalSectionDeadlock>());
 }
+
 #endif
 
+TEST(Stacktrace, TestRtcEventDeadlockDetection) {
+  // Start looking for the expected log output.
+  LookoutLogSink sink(/*look_for=*/"Probable deadlock");
+  rtc::LogMessage::AddLogToStream(&sink, rtc::LS_WARNING);
+
+  // Start a thread that waits for an event.
+  rtc::Event ev;
+  rtc::PlatformThread thread(
+      [](void* arg) {
+        auto* ev = static_cast<rtc::Event*>(arg);
+        ev->Wait(rtc::Event::kForever);
+      },
+      &ev, "TestRtcEventDeadlockDetection");
+  thread.Start();
+
+  // The message should appear after 3 sec. We'll wait up to 10 sec in an
+  // attempt to not be flaky.
+  EXPECT_TRUE(sink.WhenFound().Wait(10000));
+
+  // Unblock the thread and shut it down.
+  ev.Set();
+  thread.Stop();
+  rtc::LogMessage::RemoveLogToStream(&sink);
+}
+
 }  // namespace test
 }  // namespace webrtc