Add StopWatch utility

CHANGELOG.md

@@ -95,6 +95,19 @@
   previous Windows-specific implementation has been removed. Note that `quill::ConsoleColours` has been replaced with
   `quill::ConsoleSink::Colours`, and `quill::ConsoleColours::ColourMode` has been renamed to
   `quill::ConsoleSink::ColourMode`.
+- Added a `StopWatch` utility for easy logging of elapsed time. It can log the time elapsed since construction in
+  various formats. You can use either `quill::StopWatchTsc` for high-resolution TSC-based timing or
+  `quill::StopWatchChrono` for standard std::chrono-based timing.
+  ```c++
+    #include "quill/StopWatch.h"
+
+    quill::StopWatchTsc swt;
+    std::this_thread::sleep_for(std::chrono::seconds(1));
+    LOG_INFO(logger, "After 1s, elapsed: {:.6}s", swt); // => After 1s, elapsed: 1.00849s
+    std::this_thread::sleep_for(std::chrono::milliseconds(500));
+    LOG_INFO(logger, "After 500ms, elapsed: {}s", swt); // => After 500ms, elapsed: 1.521880274s
+    LOG_INFO(logger, "elapsed: {}", swt.elapsed_as<std::chrono::nanoseconds>()); // => elapsed: 1521807324ns
+  ```
 
 ## TBD
 

CMakeLists.txt

@@ -246,6 +246,7 @@ set(HEADER_FILES
         include/quill/Frontend.h
         include/quill/Logger.h
         include/quill/LogMacros.h
+        include/quill/StopWatch.h
         include/quill/StringRef.h
         include/quill/TriviallyCopyableCodec.h
         include/quill/UserClockSource.h

examples/CMakeLists.txt

@@ -15,6 +15,7 @@ set(EXAMPLE_TARGETS
         quill_example_rotating_json_file_logging
         quill_example_rotating_json_file_logging_custom_json
         quill_example_signal_handler
+        quill_example_stopwatch
         quill_example_logger_removal_with_file_event_notifier
         quill_example_custom_frontend_options
         quill_example_file_logging

examples/stopwatch.cpp

@@ -0,0 +1,52 @@
+#include "quill/Backend.h"
+#include "quill/Frontend.h"
+#include "quill/LogMacros.h"
+#include "quill/Logger.h"
+#include "quill/sinks/ConsoleSink.h"
+#include "quill/StopWatch.h"
+
+#include <thread>
+
+/**
+ * Stopwatch logging example
+ */
+
+int main()
+{
+  quill::BackendOptions backend_options;
+  quill::Backend::start(backend_options);
+
+  // Frontend
+  auto console_sink = quill::Frontend::create_or_get_sink<quill::ConsoleSink>(
+    "sink_id_1", quill::ConsoleSink::ColourMode::Automatic);
+
+  quill::Logger* logger = quill::Frontend::create_or_get_logger("root", std::move(console_sink));
+
+  {
+    quill::StopWatchTsc swt;
+    LOG_INFO(logger, "Begin Tsc StopWatch");
+    std::this_thread::sleep_for(std::chrono::seconds(1));
+    LOG_INFO(logger, "After 1s, elapsed: {:.6}s", swt);
+    std::this_thread::sleep_for(std::chrono::milliseconds(500));
+    LOG_INFO(logger, "After 500ms, elapsed: {}s", swt);
+    LOG_INFO(logger, "elapsed: {}", swt.elapsed_as<std::chrono::nanoseconds>());
+    LOG_INFO(logger, "elapsed: {}", swt.elapsed_as<std::chrono::seconds>());
+    LOG_INFO(logger, "Reset");
+    std::this_thread::sleep_for(std::chrono::milliseconds(500));
+    LOG_INFO(logger, "After 500ms, elapsed: {}", swt);
+  }
+
+  {
+    quill::StopWatchChrono swt;
+    LOG_INFO(logger, "Begin Chrono StopWatch");
+    std::this_thread::sleep_for(std::chrono::seconds(1));
+    LOG_INFO(logger, "After 1s, elapsed: {:.6}s", swt);
+    std::this_thread::sleep_for(std::chrono::milliseconds(500));
+    LOG_INFO(logger, "After 500ms, elapsed: {}s", swt);
+    LOG_INFO(logger, "elapsed: {}", swt.elapsed_as<std::chrono::nanoseconds>());
+    LOG_INFO(logger, "elapsed: {}", swt.elapsed_as<std::chrono::seconds>());
+    LOG_INFO(logger, "Reset");
+    std::this_thread::sleep_for(std::chrono::milliseconds(500));
+    LOG_INFO(logger, "After 500ms, elapsed: {}", swt);
+  }
+}

include/quill/StopWatch.h

@@ -0,0 +1,130 @@
+/**
+ * @page copyright
+ * Copyright(c) 2020-present, Odysseas Georgoudis & quill contributors.
+ * Distributed under the MIT License (http://opensource.org/licenses/MIT)
+ */
+
+#pragma once
+
+#include <cstdint>
+
+#include "quill/TriviallyCopyableCodec.h"
+#include "quill/core/Attributes.h"
+#include "quill/core/Common.h"
+#include "quill/core/Rdtsc.h"
+#include "quill/backend/RdtscClock.h"
+
+#include "quill/bundled/fmt/format.h"
+#include "quill/std/Chrono.h"
+
+QUILL_BEGIN_NAMESPACE
+
+namespace detail
+{
+/**
+ * Displays elapsed seconds since construction as double.
+ *
+ * @code
+ *   quill::StopWatchTsc swt;
+ *   LOG_INFO(logger, "Begin");
+ *   std::this_thread::sleep_for(std::chrono::seconds(1));
+ *   LOG_INFO(logger, "After 1s, elapsed: {:.6}", swt);
+ *   std::this_thread::sleep_for(std::chrono::milliseconds(500));
+ *   LOG_INFO(logger, "After 500ms, elapsed: {}", swt);
+ * @endcode
+ */
+template <ClockSourceType ClockType>
+class StopWatch
+{
+public:
+  static_assert((ClockType == ClockSourceType::Tsc) || (ClockType == ClockSourceType::System),
+                "Invalid ClockType");
+
+  StopWatch()
+  {
+    if constexpr (ClockType == ClockSourceType::Tsc)
+    {
+      _ns_per_tick = RdtscClock::RdtscTicks::instance().ns_per_tick();
+      _start_tp = rdtsc();
+    }
+    else
+    {
+      _start_tp = std::chrono::duration_cast<std::chrono::nanoseconds>(
+                    std::chrono::steady_clock::now().time_since_epoch())
+                    .count();
+    }
+  }
+
+  [[nodiscard]] std::chrono::duration<double> elapsed() const
+  {
+    if constexpr (ClockType == ClockSourceType::Tsc)
+    {
+      return std::chrono::duration<double>(
+        std::chrono::nanoseconds{static_cast<uint64_t>((rdtsc() - _start_tp) * _ns_per_tick)});
+    }
+    else
+    {
+      return std::chrono::duration<double>(std::chrono::nanoseconds{
+        std::chrono::steady_clock::now().time_since_epoch().count() - _start_tp});
+    }
+  }
+
+  /**
+   * Get the desired duration type
+   */
+  template <typename T>
+  [[nodiscard]] T elapsed_as() const
+  {
+    if constexpr (ClockType == ClockSourceType::Tsc)
+    {
+      return std::chrono::duration_cast<T>(
+        std::chrono::nanoseconds{static_cast<uint64_t>((rdtsc() - _start_tp) * _ns_per_tick)});
+    }
+    else
+    {
+      return std::chrono::duration_cast<T>(std::chrono::nanoseconds{
+        std::chrono::steady_clock::now().time_since_epoch().count() - _start_tp});
+    }
+  }
+
+  void reset()
+  {
+    if constexpr (ClockType == ClockSourceType::Tsc)
+    {
+      _start_tp = rdtsc();
+    }
+    else
+    {
+      _start_tp = std::chrono::duration_cast<std::chrono::nanoseconds>(
+                    std::chrono::steady_clock::now().time_since_epoch())
+                    .count();
+    }
+  }
+
+private:
+  double _ns_per_tick{0};
+  uint64_t _start_tp{0};
+};
+} // namespace detail
+
+using StopWatchTsc = detail::StopWatch<ClockSourceType::Tsc>;
+using StopWatchChrono = detail::StopWatch<ClockSourceType::System>;
+
+QUILL_END_NAMESPACE
+
+template <quill::ClockSourceType ClockType>
+struct quill::Codec<quill::detail::StopWatch<ClockType>>
+  : quill::TriviallyCopyableTypeCodec<quill::detail::StopWatch<ClockType>>
+{
+};
+
+template <quill::ClockSourceType ClockType>
+struct fmtquill::formatter<quill::detail::StopWatch<ClockType>> : fmtquill::formatter<double>
+{
+  template <typename FormatContext>
+  auto format(quill::detail::StopWatch<ClockType> const& sw, FormatContext& ctx) const
+    -> decltype(ctx.out())
+  {
+    return fmtquill::formatter<double>::format(sw.elapsed().count(), ctx);
+  }
+};

include/quill/TriviallyCopyableCodec.h

@@ -7,6 +7,7 @@
 #pragma once
 
 #include "quill/core/Attributes.h"
+#include "quill/core/Codec.h"
 #include "quill/core/DynamicFormatArgStore.h"
 #include "quill/core/InlinedVector.h"
 

include/quill/backend/RdtscClock.h

@@ -26,6 +26,7 @@ namespace detail
  */
 class RdtscClock
 {
+public:
   /**
    * A static class that calculates the rdtsc ticks per second
    */
@@ -85,7 +86,6 @@ class RdtscClock
     double _ns_per_tick{0};
   };
 
-public:
   /***/
   explicit RdtscClock(std::chrono::nanoseconds resync_interval)
     : _resync_interval_ticks(static_cast<std::int64_t>(static_cast<double>(resync_interval.count()) *

test/unit_tests/CMakeLists.txt

@@ -71,4 +71,5 @@ endif ()
 
 if (NOT QUILL_USE_VALGRIND)
     quill_add_test(TEST_RdtscClock RdtscClockTest.cpp)
+    quill_add_test(TEST_StopWatch StopWatchTest.cpp)
 endif ()

test/unit_tests/StopWatchTest.cpp

@@ -0,0 +1,58 @@
+#include "doctest/doctest.h"
+
+#include "quill/StopWatch.h"
+#include <thread>
+
+TEST_SUITE_BEGIN("StopWatch");
+
+TEST_CASE("StopWatchTsc")
+{
+  quill::StopWatchTsc swt;
+  std::this_thread::sleep_for(std::chrono::seconds{1});
+
+  // greater than 1 second
+  REQUIRE_GE(swt.elapsed().count(), 1.0);
+  REQUIRE_GE(swt.elapsed_as<std::chrono::nanoseconds>().count(), 1'000'000'000);
+  REQUIRE_GE(swt.elapsed_as<std::chrono::microseconds>().count(), 1'000'000);
+  REQUIRE_GE(swt.elapsed_as<std::chrono::milliseconds>().count(), 1'000);
+  REQUIRE_GE(swt.elapsed_as<std::chrono::seconds>().count(), 1);
+
+  swt.reset();
+  REQUIRE_LT(swt.elapsed().count(), 1.0);
+
+  std::this_thread::sleep_for(std::chrono::seconds{2});
+
+  // greater than 2 seconds
+  REQUIRE_GE(swt.elapsed().count(), 2.0);
+  REQUIRE_GE(swt.elapsed_as<std::chrono::nanoseconds>().count(), 2'000'000'000);
+  REQUIRE_GE(swt.elapsed_as<std::chrono::microseconds>().count(), 2'000'000);
+  REQUIRE_GE(swt.elapsed_as<std::chrono::milliseconds>().count(), 2'000);
+  REQUIRE_GE(swt.elapsed_as<std::chrono::seconds>().count(), 2);
+}
+
+TEST_CASE("StopWatchChrono")
+{
+  quill::StopWatchChrono swt;
+  std::this_thread::sleep_for(std::chrono::seconds{1});
+
+  // greater than 1 second
+  REQUIRE_GE(swt.elapsed().count(), 1.0);
+  REQUIRE_GE(swt.elapsed_as<std::chrono::nanoseconds>().count(), 1'000'000'000);
+  REQUIRE_GE(swt.elapsed_as<std::chrono::microseconds>().count(), 1'000'000);
+  REQUIRE_GE(swt.elapsed_as<std::chrono::milliseconds>().count(), 1'000);
+  REQUIRE_GE(swt.elapsed_as<std::chrono::seconds>().count(), 1);
+
+  swt.reset();
+  REQUIRE_LT(swt.elapsed().count(), 1.0);
+
+  std::this_thread::sleep_for(std::chrono::seconds{2});
+
+  // greater than 2 seconds
+  REQUIRE_GE(swt.elapsed().count(), 2.0);
+  REQUIRE_GE(swt.elapsed_as<std::chrono::nanoseconds>().count(), 2'000'000'000);
+  REQUIRE_GE(swt.elapsed_as<std::chrono::microseconds>().count(), 2'000'000);
+  REQUIRE_GE(swt.elapsed_as<std::chrono::milliseconds>().count(), 2'000);
+  REQUIRE_GE(swt.elapsed_as<std::chrono::seconds>().count(), 2);
+}
+
+TEST_SUITE_END();