Merge pull request #1766 from marta-lokhova/extra_logging

Log time it takes to resolve a bucket Reviewed-by: MonsieurNicolas
stellar · Aug 28, 2018 · 81446c6 · 81446c6
2 parents 675382d + cf765d9
commit 81446c6
Show file tree

Hide file tree

Showing 5 changed files with 56 additions and 3 deletions.
diff --git a/Builds/VisualStudio/stellar-core.vcxproj b/Builds/VisualStudio/stellar-core.vcxproj
@@ -714,6 +714,7 @@ exit /b 0
     <ClInclude Include="..\..\src\util\GlobalChecks.h" />
     <ClInclude Include="..\..\src\util\HashOfHash.h" />
     <ClInclude Include="..\..\src\util\Logging.h" />
+    <ClInclude Include="..\..\src\util\LogSlowExecution.h" />
     <ClInclude Include="..\..\src\util\make_unique.h" />
     <ClInclude Include="..\..\src\util\Math.h" />
     <ClInclude Include="..\..\src\util\must_use.h" />

diff --git a/src/bucket/Bucket.cpp b/src/bucket/Bucket.cpp
@@ -26,6 +26,7 @@
 #include "main/Application.h"
 #include "medida/medida.h"
 #include "util/Fs.h"
+#include "util/LogSlowExecution.h"
 #include "util/Logging.h"
 #include "util/TmpDir.h"
 #include "util/XDRStream.h"
@@ -151,7 +152,13 @@ Bucket::fresh(BucketManager& bucketManager,
 
     auto liveBucket = liveOut.getBucket(bucketManager);
     auto deadBucket = deadOut.getBucket(bucketManager);
-    return Bucket::merge(bucketManager, liveBucket, deadBucket);
+
+    std::shared_ptr<Bucket> bucket;
+    {
+        auto timer = LogSlowExecution("Bucket merge");
+        bucket = Bucket::merge(bucketManager, liveBucket, deadBucket);
+    }
+    return bucket;
 }
 
 inline void

diff --git a/src/bucket/BucketManagerImpl.cpp b/src/bucket/BucketManagerImpl.cpp
@@ -10,6 +10,7 @@
 #include "main/Config.h"
 #include "overlay/StellarXDR.h"
 #include "util/Fs.h"
+#include "util/LogSlowExecution.h"
 #include "util/Logging.h"
 #include "util/TmpDir.h"
 #include "util/types.h"
@@ -171,7 +172,10 @@ BucketManagerImpl::adoptFileAsBucket(std::string const& filename,
     {
         CLOG(DEBUG, "Bucket") << "Deleting bucket file " << filename
                               << " that is redundant with existing bucket";
-        std::remove(filename.c_str());
+        {
+            auto timer = LogSlowExecution("Delete redundant bucket");
+            std::remove(filename.c_str());
+        }
     }
     else
     {

diff --git a/src/bucket/FutureBucket.cpp b/src/bucket/FutureBucket.cpp
@@ -12,6 +12,7 @@
 #include "bucket/FutureBucket.h"
 #include "crypto/Hex.h"
 #include "main/Application.h"
+#include "util/LogSlowExecution.h"
 #include "util/Logging.h"
 
 #include <chrono>
@@ -210,7 +211,13 @@ FutureBucket::resolve()
     checkState();
     assert(isLive());
     clearInputs();
-    std::shared_ptr<Bucket> bucket = mOutputBucket.get();
+    std::shared_ptr<Bucket> bucket;
+
+    {
+        auto timer = LogSlowExecution("Resolving bucket");
+        bucket = mOutputBucket.get();
+    }
+
     if (mOutputBucketHash.empty())
     {
         mOutputBucketHash = binToHex(bucket->getHash());

diff --git a/src/util/LogSlowExecution.h b/src/util/LogSlowExecution.h
@@ -0,0 +1,34 @@
+// Copyright 2018 Stellar Development Foundation and contributors. Licensed
+// under the Apache License, Version 2.0. See the COPYING file at the root
+// of this distribution or at http://www.apache.org/licenses/LICENSE-2.0
+
+#pragma once
+
+#include "util/Logging.h"
+#include <chrono>
+
+class LogSlowExecution
+{
+
+    std::chrono::system_clock::time_point mStart;
+    std::string mName;
+    int mThresholdInMs;
+
+  public:
+    LogSlowExecution(std::string eventName, int ms = 1000)
+        : mStart(std::chrono::system_clock::now())
+        , mName(std::move(eventName))
+        , mThresholdInMs(ms){};
+
+    ~LogSlowExecution()
+    {
+        auto finish = std::chrono::system_clock::now();
+        auto elapsed = std::chrono::duration_cast<std::chrono::milliseconds>(
+            finish - mStart);
+        auto tooSlow = elapsed.count() > mThresholdInMs;
+
+        LOG_IF(tooSlow, INFO)
+            << mName << " hung for "
+            << static_cast<float>(elapsed.count()) / 1000 << " s";
+    }
+};