Log slow calls to Stoppable::onStop

beast/threads/Stoppable.h

@@ -266,8 +266,8 @@ private:
 
     void prepareRecursive ();
     void startRecursive ();
-    void stopAsyncRecursive ();
-    void stopRecursive (Journal journal);
+    void stopAsyncRecursive (Journal j);
+    void stopRecursive (Journal j);
 
     std::string m_name;
     RootStoppable& m_root;
@@ -314,15 +314,16 @@ public:
         Thread safety:
             Safe to call from any thread not associated with a Stoppable.
     */
-    void stop (Journal journal = Journal());
+    void stop (Journal j);
+
 private:
-    /** Notify a root stoppable and children to stop, without waiting.
+    /*  Notify a root stoppable and children to stop, without waiting.
         Has no effect if the stoppable was already notified.
 
         Thread safety:
             Safe to call from any thread at any time.
     */
-    void stopAsync ();
+    void stopAsync(Journal j);
 
     std::atomic<bool> m_prepared;
     std::atomic<bool> m_calledStop;

beast/threads/impl/Stoppable.cpp

@@ -106,21 +106,28 @@ void Stoppable::startRecursive ()
         iter->stoppable->startRecursive ();
 }
 
-void Stoppable::stopAsyncRecursive ()
+void Stoppable::stopAsyncRecursive (Journal j)
 {
+    using namespace std::chrono;
+    auto const start = high_resolution_clock::now();
     onStop ();
+    auto const ms = duration_cast<milliseconds>(
+        high_resolution_clock::now() - start).count();
+    if (ms >= 10)
+        j.fatal << m_name << "::onStop took " << ms << "ms";
+
     for (Children::const_iterator iter (m_children.cbegin ());
         iter != m_children.cend(); ++iter)
-        iter->stoppable->stopAsyncRecursive ();
+        iter->stoppable->stopAsyncRecursive(j);
 }
 
-void Stoppable::stopRecursive (Journal journal)
+void Stoppable::stopRecursive (Journal j)
 {
     // Block on each child from the bottom of the tree up.
     //
     for (Children::const_iterator iter (m_children.cbegin ());
         iter != m_children.cend(); ++iter)
-        iter->stoppable->stopRecursive (journal);
+        iter->stoppable->stopRecursive (j);
 
     // if we get here then all children have stopped
     //
@@ -132,7 +139,7 @@ void Stoppable::stopRecursive (Journal journal)
     bool const timedOut (! m_stoppedEvent.wait (1 * 1000)); // milliseconds
     if (timedOut)
     {
-        journal.warning << "Waiting for '" << m_name << "' to stop";
+        j.warning << "Waiting for '" << m_name << "' to stop";
         m_stoppedEvent.wait ();
     }
 
@@ -171,25 +178,25 @@ void RootStoppable::start ()
         startRecursive ();
 }
 
-void RootStoppable::stop (Journal journal)
+void RootStoppable::stop (Journal j)
 {
     // Must have a prior call to start()
     bassert (m_started);
 
     if (m_calledStop.exchange (true) == true)
     {
-        journal.warning << "Stoppable::stop called again";
+        j.warning << "Stoppable::stop called again";
         return;
     }
 
-    stopAsync ();
-    stopRecursive (journal);
+    stopAsync (j);
+    stopRecursive (j);
 }
 
-void RootStoppable::stopAsync ()
+void RootStoppable::stopAsync(Journal j)
 {
     if (m_calledStopAsync.exchange (true) == false)
-        stopAsyncRecursive ();
+        stopAsyncRecursive(j);
 }
 
 }

beast/threads/impl/Stoppable.test.cpp

@@ -403,7 +403,7 @@ class Stoppable_test
         {
             prepare();
             start();
-            stop();
+            stop(Journal{});
         }
 
         void onPrepare() override