MINIFICPP-2500 Log runtime as human readable duration

libminifi/include/utils/TimeUtil.h

@@ -126,6 +126,8 @@ inline std::optional<std::chrono::sys_seconds> parseDateTimeStr(const std::strin
   return tp;
 }
 
+std::string humanReadableDuration(std::chrono::system_clock::duration input_duration);
+
 std::optional<std::chrono::system_clock::time_point> parseRfc3339(const std::string& str);
 
 inline std::string getDateTimeStr(std::chrono::sys_seconds tp) {

libminifi/src/utils/TimeUtil.cpp

@@ -16,6 +16,9 @@
  */
 
 #include "utils/TimeUtil.h"
+
+#include "fmt/format.h"
+#include "fmt/chrono.h"
 #include "range/v3/algorithm/contains.hpp"
 
 #ifdef WIN32
@@ -39,6 +42,60 @@ void setClock(std::shared_ptr<SteadyClock> clock) {
   global_clock = std::move(clock);
 }
 
+namespace {
+template<class... Durations>
+std::tuple<Durations...> breakDownDurations(std::chrono::system_clock::duration input_duration) {
+  std::tuple<Durations...> result;
+
+  ([&]<typename T>(T& duration) {
+      duration = std::chrono::duration_cast<std::decay_t<T>>(input_duration);
+      input_duration -= duration;
+    } (std::get<Durations>(result)), ...);
+
+  return result;
+}
+
+std::string formatAsDaysHoursMinutesSeconds(std::chrono::system_clock::duration input_duration) {
+  const auto durs = breakDownDurations<std::chrono::days, std::chrono::hours, std::chrono::minutes, std::chrono::seconds>(input_duration);
+  const auto& days = std::get<std::chrono::days>(durs);
+  std::string day_string;
+  if (days.count() > 0) {
+    day_string = fmt::format("{} {}", days.count(), days.count() == 1 ? "day, " : "days, ");
+  }
+  return fmt::format("{}{:02}:{:02}:{:02}",
+      day_string, std::get<std::chrono::hours>(durs).count(),
+      std::get<std::chrono::minutes>(durs).count(),
+      std::get<std::chrono::seconds>(durs).count());
+}
+
+template<class... Durations>
+std::string formatAsRoundedLargestUnit(std::chrono::system_clock::duration input_duration) {
+  std::optional<std::string> rounded_value_str;
+  using std::chrono::duration_cast;
+  using std::chrono::duration;
+
+  ((rounded_value_str = input_duration >= Durations(1)
+    ? std::optional<std::string>{fmt::format("{:.2}", duration_cast<duration<double, typename Durations::period>>(input_duration))}
+    : std::nullopt) || ...);
+
+
+  if (!rounded_value_str) {
+    return fmt::format("{}", input_duration);
+  }
+
+  return *rounded_value_str;
+}
+
+}  // namespace
+
+std::string humanReadableDuration(std::chrono::system_clock::duration input_duration) {
+  if (input_duration > 5s) {
+    return formatAsDaysHoursMinutesSeconds(input_duration);
+  }
+
+  return formatAsRoundedLargestUnit<std::chrono::seconds, std::chrono::milliseconds, std::chrono::microseconds>(input_duration);
+}
+
 std::optional<std::chrono::system_clock::time_point> parseRfc3339(const std::string& str) {
   std::istringstream stream(str);
   date::year_month_day date_part{};

libminifi/test/unit/TimeUtilTests.cpp

@@ -342,3 +342,17 @@ TEST_CASE("Parse RFC3339", "[parseRfc3339]") {
   CHECK_FALSE(parseRfc3339(" 2023-03-01T19:04:55Z"));
   CHECK_FALSE(parseRfc3339("2023-03-01"));
 }
+
+TEST_CASE("Test human readable parser") {
+  using utils::timeutils::humanReadableDuration;
+  CHECK(humanReadableDuration(1234567us) == "1.23s");
+  const auto nine_hundred_forty_five_microseconds = humanReadableDuration(945us);
+  CHECK((nine_hundred_forty_five_microseconds == "945.00µs" || nine_hundred_forty_five_microseconds == "945.00us"));
+  CHECK(humanReadableDuration(52ms) == "52.00ms");
+
+  CHECK(humanReadableDuration(1000s) == "00:16:40");
+  CHECK(humanReadableDuration(10000s) == "02:46:40");
+  CHECK(humanReadableDuration(2222222222ms) == "25 days, 17:17:02");
+  CHECK(humanReadableDuration(24h) == "1 day, 00:00:00");
+  CHECK(humanReadableDuration(23h + 12min + 1233ms) == "23:12:01");
+}

minifi_main/MiNiFiMain.cpp

@@ -223,7 +223,9 @@ int main(int argc, char **argv) {
   auto& logger_configuration = core::logging::LoggerConfiguration::getConfiguration();
   const auto logger = logger_configuration.getLogger("main");
   auto startup_timepoint = std::chrono::system_clock::now();
-  auto log_runtime = gsl::finally([&](){logger->log_info("Runtime was {}", std::chrono::system_clock::now()-startup_timepoint);});
+  auto log_runtime = gsl::finally([&]() {
+    logger->log_info("Runtime was {}", utils::timeutils::humanReadableDuration(std::chrono::system_clock::now()-startup_timepoint));
+  });
 #ifdef WIN32
   if (isStartedByService) {
     if (!CreateServiceTerminationThread(logger, terminationEventHandler)) {