From 45729b005c793d8c1bf0517ba6053e6146ab7c8b Mon Sep 17 00:00:00 2001
From: marta-lokhova <marta@stellar.org>
Date: Wed, 22 Aug 2018 15:19:18 -0700
Subject: [PATCH 1/2] Log time it takes to resolve a bucket

---
 Builds/VisualStudio/stellar-core.vcxproj |  1 +
 src/bucket/FutureBucket.cpp              |  9 ++++++-
 src/util/LogSlowExecution.h              | 34 ++++++++++++++++++++++++
 3 files changed, 43 insertions(+), 1 deletion(-)
 create mode 100644 src/util/LogSlowExecution.h

diff --git a/Builds/VisualStudio/stellar-core.vcxproj b/Builds/VisualStudio/stellar-core.vcxproj
index 73e62b49c4..5f74acdd51 100644
--- 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/FutureBucket.cpp b/src/bucket/FutureBucket.cpp
index 3d9e7c3634..11fd86f451 100644
--- 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
new file mode 100644
index 0000000000..2fd4adab3d
--- /dev/null
+++ 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";
+    }
+};

From cf765d91c29151e74e8e385fa0130be1534f3d84 Mon Sep 17 00:00:00 2001
From: marta-lokhova <marta@stellar.org>
Date: Fri, 24 Aug 2018 11:14:16 -0700
Subject: [PATCH 2/2] Extra logging for bucket removal and merge

---
 src/bucket/Bucket.cpp            | 9 ++++++++-
 src/bucket/BucketManagerImpl.cpp | 6 +++++-
 2 files changed, 13 insertions(+), 2 deletions(-)

diff --git a/src/bucket/Bucket.cpp b/src/bucket/Bucket.cpp
index 1d55c4a989..f9a5722cec 100644
--- 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
index 5d4f6bc0db..073caf8acf 100644
--- 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
     {