Add params to configure logging semantics of LogSlowExecution, add LogSlowExecution for bucket merges longer than 2 minutes

Author: Thomas Brady

src/bucket/FutureBucket.cpp

@@ -353,7 +353,10 @@ FutureBucket::startMerge(Application& app, uint32_t maxProtocolVersion,
     std::shared_ptr<task_t> task = std::make_shared<task_t>(
         [curr, snap, &bm, shadows, maxProtocolVersion, countMergeEvents, level,
          &timer, &ctx, doFsync, availableTime]() mutable {
-            auto timeScope = timer.TimeScope();
+            auto timeScope = LogSlowExecution(
+                "Bucket merge", LogSlowExecution::Mode::AUTOMATIC_RAII, "took",
+                std::chrono::seconds(120), /*warnOnThreshold=*/true,
+                /*logEveryExecution=*/true);
             CLOG_TRACE(Bucket, "Worker merging curr={} with snap={}",
                        hexAbbrev(curr->getHash()), hexAbbrev(snap->getHash()));
 
@@ -372,14 +375,6 @@ FutureBucket::startMerge(Application& app, uint32_t maxProtocolVersion,
                     CLOG_TRACE(
                         Bucket, "Worker finished merging curr={} with snap={}",
                         hexAbbrev(curr->getHash()), hexAbbrev(snap->getHash()));
-
-                    std::chrono::duration<double> time(timeScope.Stop());
-                    double timePct = time.count() / availableTime.count() * 100;
-                    CLOG_DEBUG(
-                        Perf,
-                        "Bucket merge on level {} finished in {} seconds "
-                        "({}% of available time)",
-                        level, time.count(), timePct);
                 }
 
                 return res;

src/util/LogSlowExecution.cpp

@@ -22,12 +22,15 @@ namespace stellar
 {
 LogSlowExecution::LogSlowExecution(std::string eventName, Mode mode,
                                    std::string message,
-                                   std::chrono::milliseconds threshold)
+                                   std::chrono::milliseconds threshold,
+                                   bool warnOnThreshold, bool logEveryExecution)
     : mStart(std::chrono::system_clock::now())
     , mName(std::move(eventName))
     , mMode(mode)
     , mMessage(std::move(message))
-    , mThreshold(threshold){};
+    , mThreshold(threshold)
+    , mWarnOnThreshold(warnOnThreshold)
+    , mLogEveryExecution(logEveryExecution){};
 
 LogSlowExecution::~LogSlowExecution()
 {
@@ -44,13 +47,15 @@ LogSlowExecution::checkElapsedTime() const
     auto elapsed =
         std::chrono::duration_cast<std::chrono::milliseconds>(finish - mStart);
 
-    if (!mThreshold.count() || elapsed > mThreshold)
+    if (!mThreshold.count() || elapsed > mThreshold || mLogEveryExecution)
     {
         std::lock_guard<std::mutex> guard(gLogSlowExecMutex);
 
         // Check whether we're 10 times over the threshold to decide the log
-        // level.
-        LogLevel ll = (elapsed > mThreshold * 10 || !mThreshold.count())
+        // level. If warnOnThreshold is set, log as warning if we're over the
+        // threshold.
+        LogLevel ll = (elapsed > mThreshold * 10 || !mThreshold.count() ||
+                       (elapsed > mThreshold && mWarnOnThreshold))
                           ? LogLevel::LVL_WARNING
                           : LogLevel::LVL_DEBUG;
 

src/util/LogSlowExecution.h

@@ -22,7 +22,8 @@ class LogSlowExecution
     LogSlowExecution(
         std::string eventName, Mode mode = Mode::AUTOMATIC_RAII,
         std::string message = "took",
-        std::chrono::milliseconds threshold = std::chrono::seconds(1));
+        std::chrono::milliseconds threshold = std::chrono::seconds(1),
+        bool warnOnThreshold = false, bool logEveryExecution = false);
     ~LogSlowExecution();
     std::chrono::milliseconds checkElapsedTime() const;
 
@@ -32,6 +33,8 @@ class LogSlowExecution
     Mode mMode;
     std::string mMessage;
     std::chrono::milliseconds mThreshold;
+    bool mWarnOnThreshold;
+    bool mLogEveryExecution;
 };
 
 // Helper class to emit rate-limited log messages without any threshold