From a2499af5cf3c5f46c695f019fda632c28939c62c Mon Sep 17 00:00:00 2001
From: Fabian Engelniederhammer <fabian.engelniederhammer@tngtech.com>
Date: Thu, 22 Feb 2024 11:08:52 +0100
Subject: [PATCH] feat: display preprocessing duration  in logs in
 human-readable format (not in microseconds) #296

---
 include/silo/common/block_timer.h       |  7 ++++++
 src/silo/common/block_timer.cpp         | 29 +++++++++++++++++++++++++
 src/silo/preprocessing/preprocessor.cpp |  4 ++--
 src/silo/query_engine/query_engine.cpp  |  4 ++--
 4 files changed, 40 insertions(+), 4 deletions(-)
 create mode 100644 src/silo/common/block_timer.cpp

diff --git a/include/silo/common/block_timer.h b/include/silo/common/block_timer.h
index 83fe88651..ea654f12b 100644
--- a/include/silo/common/block_timer.h
+++ b/include/silo/common/block_timer.h
@@ -1,6 +1,9 @@
 #pragma once
 
 #include <chrono>
+#include <string>
+
+namespace silo::common {
 
 template <typename Unit = std::chrono::microseconds, typename Clock = std::chrono::steady_clock>
 struct [[nodiscard]] BlockTimer {
@@ -21,3 +24,7 @@ struct [[nodiscard]] BlockTimer {
 
    output_t untilNow() { return std::chrono::duration_cast<Unit>(Clock::now() - start).count(); }
 };
+
+std::string formatDuration(int64_t int_microseconds);
+
+}  // namespace silo::common
diff --git a/src/silo/common/block_timer.cpp b/src/silo/common/block_timer.cpp
new file mode 100644
index 000000000..634c805ff
--- /dev/null
+++ b/src/silo/common/block_timer.cpp
@@ -0,0 +1,29 @@
+#include "silo/common/block_timer.h"
+
+#include <chrono>
+#include <iomanip>
+#include <string>
+
+namespace silo::common {
+
+std::string formatDuration(int64_t int_microseconds) {
+   auto microseconds = std::chrono::microseconds(int_microseconds);
+   auto hours = std::chrono::duration_cast<std::chrono::hours>(microseconds);
+   microseconds -= hours;
+   auto minutes = std::chrono::duration_cast<std::chrono::minutes>(microseconds);
+   microseconds -= minutes;
+   auto seconds = std::chrono::duration_cast<std::chrono::seconds>(microseconds);
+   microseconds -= seconds;
+   auto milliseconds = std::chrono::duration_cast<std::chrono::milliseconds>(microseconds);
+
+   std::stringstream string_stream;
+
+   string_stream << std::setw(2) << std::setfill('0') << hours.count() << ":";
+   string_stream << std::setw(2) << std::setfill('0') << minutes.count() << ":";
+   string_stream << std::setw(2) << std::setfill('0') << seconds.count() << ".";
+   string_stream << std::setw(3) << std::setfill('0') << milliseconds.count();
+
+   return string_stream.str();
+}
+
+}  // namespace silo::common
diff --git a/src/silo/preprocessing/preprocessor.cpp b/src/silo/preprocessing/preprocessor.cpp
index c39932cf8..2f0d75107 100644
--- a/src/silo/preprocessing/preprocessor.cpp
+++ b/src/silo/preprocessing/preprocessor.cpp
@@ -460,7 +460,7 @@ Database Preprocessor::buildDatabase(
 
    int64_t micros = 0;
    {
-      const BlockTimer timer(micros);
+      const silo::common::BlockTimer timer(micros);
       for (const auto& partition : partition_descriptor.getPartitions()) {
          database.partitions.emplace_back(partition.getPartitionChunks());
       }
@@ -494,7 +494,7 @@ Database Preprocessor::buildDatabase(
       database.finalizeInsertionIndexes();
    }
 
-   SPDLOG_INFO("Build took {} ms", micros);
+   SPDLOG_INFO("Build took {}", silo::common::formatDuration(micros));
    SPDLOG_INFO("database info: {}", database.getDatabaseInfo());
 
    database.validate();
diff --git a/src/silo/query_engine/query_engine.cpp b/src/silo/query_engine/query_engine.cpp
index 57eec0301..2c28700e5 100644
--- a/src/silo/query_engine/query_engine.cpp
+++ b/src/silo/query_engine/query_engine.cpp
@@ -31,7 +31,7 @@ QueryResult QueryEngine::executeQuery(const std::string& query_string) const {
    std::vector<silo::query_engine::OperatorResult> partition_filters(database.partitions.size());
    int64_t filter_time;
    {
-      const BlockTimer timer(filter_time);
+      const silo::common::BlockTimer timer(filter_time);
       for (size_t partition_index = 0; partition_index != database.partitions.size();
            partition_index++) {
          std::unique_ptr<operators::Operator> part_filter = query.filter->compile(
@@ -51,7 +51,7 @@ QueryResult QueryEngine::executeQuery(const std::string& query_string) const {
    QueryResult query_result;
    int64_t action_time;
    {
-      const BlockTimer timer(action_time);
+      const silo::common::BlockTimer timer(action_time);
       query_result = query.action->executeAndOrder(database, std::move(partition_filters));
    }