feat(storage): Log time taken for secondary storage operations

diff --git a/src/storage/Storage.cpp b/src/storage/Storage.cpp
index 548b226856bfb14217dc54eb91b3f1f332ca041e..7bd7d439c906fc29ec6b785c70e86adfcd7e20e2 100644 (file)
--- a/src/storage/Storage.cpp
+++ b/src/storage/Storage.cpp
@@ -31,6 +31,7 @@
 #  include <storage/secondary/RedisStorage.hpp>
 #endif
 #include <storage/secondary/SecondaryStorage.hpp>
+#include <util/Timer.hpp>
 #include <util/Tokenizer.hpp>
 #include <util/expected.hpp>
 #include <util/string.hpp>
@@ -334,7 +335,9 @@ Storage::get_from_secondary_storage(const Digest& key)
       continue;
     }
 
+    Timer timer;
     const auto result = entry->backend->get(key);
+    const auto ms = timer.measure_ms();
     if (!result) {
       mark_backend_as_failed(*entry, result.error());
       continue;
@@ -342,10 +345,14 @@ Storage::get_from_secondary_storage(const Digest& key)
 
     const auto& value = *result;
     if (value) {
-      LOG("Retrieved {} from {}", key.to_string(), entry->url_for_logging);
+      LOG("Retrieved {} from {} ({:.2f} ms)",
+          key.to_string(),
+          entry->url_for_logging,
+          ms);
       return *value;
     } else {
-      LOG("No {} in {}", key.to_string(), entry->url_for_logging);
+      LOG(
+        "No {} in {} ({:.2f} ms)", key.to_string(), entry->url_for_logging, ms);
     }
   }
 
@@ -360,7 +367,9 @@ Storage::put_in_secondary_storage(const Digest& key, const std::string& value)
       continue;
     }
 
+    Timer timer;
     const auto result = entry->backend->put(key, value);
+    const auto ms = timer.measure_ms();
     if (!result) {
       // The backend is expected to log details about the error.
       mark_backend_as_failed(*entry, result.error());
@@ -368,10 +377,11 @@ Storage::put_in_secondary_storage(const Digest& key, const std::string& value)
     }
 
     const bool stored = *result;
-    LOG("{} {} in {}",
+    LOG("{} {} in {} ({:.2f} ms)",
         stored ? "Stored" : "Failed to store",
         key.to_string(),
-        entry->url_for_logging);
+        entry->url_for_logging,
+        ms);
   }
 }
 
@@ -383,7 +393,9 @@ Storage::remove_from_secondary_storage(const Digest& key)
       continue;
     }
 
+    Timer timer;
     const auto result = entry->backend->remove(key);
+    const auto ms = timer.measure_ms();
     if (!result) {
       mark_backend_as_failed(*entry, result.error());
       continue;
@@ -391,9 +403,15 @@ Storage::remove_from_secondary_storage(const Digest& key)
 
     const bool removed = *result;
     if (removed) {
-      LOG("Removed {} from {}", key.to_string(), entry->url_for_logging);
+      LOG("Removed {} from {} ({:.2f} ms)",
+          key.to_string(),
+          entry->url_for_logging,
+          ms);
     } else {
-      LOG("No {} to remove from {}", key.to_string(), entry->url_for_logging);
+      LOG("No {} to remove from {} ({:.2f} ms)",
+          key.to_string(),
+          entry->url_for_logging,
+          ms);
     }
   }
 }

diff --git a/src/util/Timer.hpp b/src/util/Timer.hpp
new file mode 100644 (file)
index 0000000..afbf7ab
--- /dev/null
+++ b/src/util/Timer.hpp
@@ -0,0 +1,51 @@
+// Copyright (C) 2021 Joel Rosdahl and other contributors
+//
+// See doc/AUTHORS.adoc for a complete list of contributors.
+//
+// This program is free software; you can redistribute it and/or modify it
+// under the terms of the GNU General Public License as published by the Free
+// Software Foundation; either version 3 of the License, or (at your option)
+// any later version.
+//
+// This program is distributed in the hope that it will be useful, but WITHOUT
+// ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
+// FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for
+// more details.
+//
+// You should have received a copy of the GNU General Public License along with
+// this program; if not, write to the Free Software Foundation, Inc., 51
+// Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA
+
+#pragma once
+
+#include <chrono>
+#include <string>
+
+class Timer
+{
+public:
+  Timer();
+
+  double measure_s() const;
+  double measure_ms() const;
+
+private:
+  std::chrono::steady_clock::time_point m_start;
+};
+
+inline Timer::Timer() : m_start(std::chrono::steady_clock::now())
+{
+}
+
+inline double
+Timer::measure_s() const
+{
+  using namespace std::chrono;
+  return duration_cast<duration<double>>(steady_clock::now() - m_start).count();
+}
+
+inline double
+Timer::measure_ms() const
+{
+  return measure_s() * 1000;
+}