feat: display preprocessing duration in logs in human-readable format…

… (not in microseconds) #296

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

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

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();

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));
    }