Add logging for blocking using baton while on an executor

Summary:
Add sampled logging of blocking operations made on folly::Baton from within an executor task.

Relies on thread_local state recording whether we are in a context where blocking is disallowed, which means within a task running on an executor with support for the functionality. Functionality is currently limited to certain executors, and to blocking operations on Baton, but this covers common user-facing APIs like Future.

Reviewed By: andriigrynenko

Differential Revision: D20010963

fbshipit-source-id: c0598e1a3a9c4e3641581e561b678a2b241998ff

folly/Singleton-inl.h

@@ -176,8 +176,10 @@ void SingletonHolder<T>::destroyInstance() {
   instance_copy_.reset();
   if (destroy_baton_) {
     constexpr std::chrono::seconds kDestroyWaitTime{5};
+    auto const wait_options =
+        destroy_baton_->wait_options().logging_enabled(false);
     auto last_reference_released =
-        destroy_baton_->try_wait_for(kDestroyWaitTime);
+        destroy_baton_->try_wait_for(kDestroyWaitTime, wait_options);
     if (last_reference_released) {
       teardown_(instance_ptr_);
     } else {

folly/detail/AsyncTrace.cpp

@@ -28,5 +28,6 @@ FOLLY_ATTR_WEAK void logGetGlobalIOExecutor(IOExecutor*) noexcept {}
 FOLLY_ATTR_WEAK void logGetImmutableIOExecutor(IOExecutor*) noexcept {}
 FOLLY_ATTR_WEAK void logSemiFutureVia(Executor*, Executor*) noexcept {}
 FOLLY_ATTR_WEAK void logFutureVia(Executor*, Executor*) noexcept {}
+FOLLY_ATTR_WEAK void logBlockingOperation(std::chrono::milliseconds) noexcept {}
 } // namespace async_tracing
 } // namespace folly

folly/detail/AsyncTrace.h

@@ -15,6 +15,9 @@
  */
 
 #pragma once
+
+#include <chrono>
+
 #include <folly/Optional.h>
 
 namespace folly {
@@ -30,5 +33,6 @@ void logGetGlobalIOExecutor(IOExecutor*) noexcept;
 void logGetImmutableIOExecutor(IOExecutor*) noexcept;
 void logSemiFutureVia(Executor*, Executor*) noexcept;
 void logFutureVia(Executor*, Executor*) noexcept;
+void logBlockingOperation(std::chrono::milliseconds) noexcept;
 } // namespace async_tracing
 } // namespace folly

folly/detail/test/AsyncTraceTest.cpp

@@ -34,4 +34,6 @@ TEST(FollyCountersTest, Trivial) {
 
   folly::async_tracing::logSemiFutureVia(lastExec, exec);
   folly::async_tracing::logFutureVia(lastExec, exec);
+
+  folly::async_tracing::logBlockingOperation(std::chrono::milliseconds{100});
 }

folly/executors/ThreadPoolExecutor.cpp

@@ -200,7 +200,8 @@ void ThreadPoolExecutor::addThreads(size_t n) {
     threadList_.add(thread);
   }
   for (auto& thread : newThreads) {
-    thread->startupBaton.wait();
+    thread->startupBaton.wait(
+        folly::Baton<>::wait_options().logging_enabled(false));
   }
   for (auto& o : observers_) {
     for (auto& thread : newThreads) {

folly/io/async/EventBase.cpp

@@ -670,7 +670,7 @@ void EventBase::runInEventBaseThreadAndWait(Func fn) noexcept {
     // before posting the baton and waking the waiting thread.
     copy(std::move(fn))();
   });
-  ready.wait();
+  ready.wait(folly::Baton<>::wait_options().logging_enabled(false));
 }
 
 void EventBase::runImmediatelyOrRunInEventBaseThreadAndWait(Func fn) noexcept {

folly/io/async/ScopedEventBaseThread.cpp

@@ -42,7 +42,7 @@ static void run(
   // must destruct in io thread for on-destruction callbacks
   eb->runOnDestruction([=] { ebm->clearEventBase(); });
   // wait until terminateLoopSoon() is complete
-  stop->wait();
+  stop->wait(folly::Baton<>::wait_options().logging_enabled(false));
   eb->~EventBase();
 }
 

folly/synchronization/Baton.h

@@ -23,6 +23,7 @@
 #include <thread>
 
 #include <folly/Likely.h>
+#include <folly/detail/AsyncTrace.h>
 #include <folly/detail/Futex.h>
 #include <folly/detail/MemoryIdler.h>
 #include <folly/portability/Asm.h>
@@ -263,6 +264,12 @@ class Baton {
   FOLLY_NOINLINE bool tryWaitSlow(
       const std::chrono::time_point<Clock, Duration>& deadline,
       const WaitOptions& opt) noexcept {
+    if (opt.logging_enabled()) {
+      folly::async_tracing::logBlockingOperation(
+          std::chrono::duration_cast<std::chrono::milliseconds>(
+              deadline - Clock::now()));
+    }
+
     switch (detail::spin_pause_until(deadline, opt, [=] { return ready(); })) {
       case detail::spin_result::success:
         return true;

folly/synchronization/WaitOptions.h

@@ -53,6 +53,7 @@ class WaitOptions {
     /// nsec is the pause instruction.
     static constexpr std::chrono::nanoseconds spin_max =
         std::chrono::microseconds(2);
+    static constexpr bool logging_enabled = true;
   };
 
   constexpr std::chrono::nanoseconds spin_max() const {
@@ -62,9 +63,17 @@ class WaitOptions {
     spin_max_ = dur;
     return *this;
   }
+  constexpr bool logging_enabled() const {
+    return logging_enabled_;
+  }
+  constexpr WaitOptions& logging_enabled(bool enable) {
+    logging_enabled_ = enable;
+    return *this;
+  }
 
  private:
   std::chrono::nanoseconds spin_max_ = Defaults::spin_max;
+  bool logging_enabled_ = Defaults::logging_enabled;
 };
 
 } // namespace folly