Timestamp Types

Use this page to choose between TSC, system, or custom clock sources and understand their trade-offs.

Timestamp Recording

The library records the timestamp of the log statement on the caller thread at the point the call was made. This approach makes the log statement timestamp more accurate but introduces the possibility of the backend seeing a timestamp in the past, causing an out-of-order timestamp to appear in the log.

Due to the usage of different types of queues, it is possible in rare cases for the timestamp to be recorded but not immediately processed. For example, the caller thread might block (if a blocking queue is used) or take some time to reallocate a new non-blocking queue.

To mitigate this, there is a configurable BackendOptions::log_timestamp_ordering_grace_period option. This option delays the reading of timestamps by the backend for a few microseconds (default 5μs), providing additional time for the frontend to push messages and reducing the chance of out-of-order timestamps within that grace window. The backend assumes timestamps produced within a single frontend queue are normally non-decreasing. If a wall clock or user-provided clock moves backwards, BackendOptions::ensure_monotonic_output_timestamps can be enabled to correct regular log and metric output. Backtrace records preserve their original capture timestamps and may still appear out of timestamp order when flushed later.

Timestamp Methods

There are several ways to get the timestamp on the frontend:

  • TSC (Time Stamp Counter): This is the fastest method for the frontend, as it simply calls __rdtsc and pushes the raw TSC counter value. The backend runs an RdtscClock which periodically syncs with the wall time (default every 500ms). It takes the rdtsc value from the frontend and converts it to wall time using a lock-free algorithm. Although the rdtsc clock might drift between resyncs, the difference is generally negligible. However, your processor must support invariant TSC to ensure that TSC counters between different cores remain synchronized. When this timestamp type is used, the backend requires a few seconds for the initial calibration of the RdtscClock on first usage.

    Note: TSC timestamps in rare cases may appear out of chronological order by a few microseconds. This occurs because: (1) frontend threads on different CPU cores capture raw TSC values with potential slight variations, (2) the backend converts these TSC values to wall time using a periodically updated calibration point, and (3) when resync occurs between message captures, different messages may be converted using different calibration points. Since the RdtscClock is not monotonic across resyncs, timestamps from different cores converted with different calibrations can appear out of order even when the actual logging occurred in sequence. This is an inherent characteristic of TSC-based timing across multi-core systems. If strict chronological timestamp ordering is required, use the System clock method instead.

  • System: This method calls std::chrono::system_clock::now() on the frontend and pushes the wall time value to the queue. It is slower than TSC but provides the most accurate and immediately usable timestamps. The backend thread does not require any additional initialization time since the RdtscClock is not used.

  • User: This method allows the user to provide a custom timestamp in nanoseconds since epoch via UserClockSource. This is useful, for example, in simulations where you want to display a custom timestamp rather than the current one in the log statements.

Providing a Custom Timestamp

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
#include "quill/Backend.h"
#include "quill/Frontend.h"
#include "quill/LogMacros.h"
#include "quill/Logger.h"
#include "quill/UserClockSource.h"
#include "quill/sinks/ConsoleSink.h"

#include <atomic>
#include <chrono>
#include <cstdint>
#include <utility>

/**
 * Example demonstrating custom clock usage for logging. This is particularly useful
 * when simulating events from a specific time period, allowing logs to align with
 * the simulated time.
 */

/**
 * This class needs to be thread-safe, unless only a single thread in the application calling
 * LOG_ macros from the same logger
 */
class SimulatedClock : public quill::UserClockSource
{
public:
  SimulatedClock() = default;

  /**
   * Required by TimestampClock
   * @return current time now, in nanoseconds since epoch
   */
  uint64_t now() const override { return _timestamp_ns.load(std::memory_order_relaxed); }

  /**
   * set custom timestamp
   * @param time_since_epoch timestamp
   */
  void set_timestamp(std::chrono::seconds time_since_epoch)
  {
    // always convert to nanos
    _timestamp_ns.store(static_cast<uint64_t>(std::chrono::nanoseconds{time_since_epoch}.count()),
                        std::memory_order_relaxed);
  }

private:
  std::atomic<uint64_t> _timestamp_ns{0}; // time since epoch - must always be in nanoseconds
};

int main()
{
  // Start the backend thread
  quill::BackendOptions backend_options;
  quill::Backend::start(backend_options);

  // Create a simulated timestamp class. Quill takes a pointer to this class,
  // and the user is responsible for its lifetime.
  // Ensure that the instance of this class remains alive for as long as the logger
  // object exists, until the logger is removed.
  SimulatedClock simulated_clock;

  // Get the console sink and also create a logger using the simulated clock
  auto console_sink = quill::Frontend::create_or_get_sink<quill::ConsoleSink>("sink_id_1");

  quill::Logger* logger = quill::Frontend::create_or_get_logger(
    "root", std::move(console_sink),
    quill::PatternFormatterOptions{
      "%(time) %(short_source_location:<28) LOG_%(log_level:<9) %(logger:<12) %(message)",
      "%D %H:%M:%S.%Qns", quill::Timezone::LocalTime, false},
    quill::ClockSourceType::User, &simulated_clock);

  // Change the LogLevel to print everything
  logger->set_log_level(quill::LogLevel::TraceL3);

  // Set our timestamp to Sunday 12 June 2022
  simulated_clock.set_timestamp(std::chrono::seconds{1655007309});
  LOG_TRACE_L3(logger, "This is a log trace l3 example {}", 1);
  LOG_TRACE_L2(logger, "This is a log trace l2 example {} {}", 2, 2.3);

  // update our timestamp
  simulated_clock.set_timestamp(std::chrono::seconds{1655039000});
  LOG_INFO(logger, "This is a log info {} example", "string");
  LOG_DEBUG(logger, "This is a log debug example {}", 4);
}

Getting a Synchronized Timestamp with the Backend Thread TSC Clock

In some cases, when using TSC for log statements, you might want to obtain a timestamp that is synchronized with the timestamp seen in the log statements. To achieve this, you can use the BackendTscClock. See the example below:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
#include "quill/Backend.h"
#include "quill/BackendTscClock.h"
#include "quill/Frontend.h"
#include "quill/LogMacros.h"
#include "quill/Logger.h"
#include "quill/sinks/ConsoleSink.h"

#include <iostream>
#include <utility>

int main()
{
  quill::Backend::start();

  auto console_sink = quill::Frontend::create_or_get_sink<quill::ConsoleSink>("sink_id_1");

  // Ensure at least one logger with quill::ClockSourceType::Tsc is created for BackendTscClock to function
  quill::Logger* logger = quill::Frontend::create_or_get_logger(
    "root", std::move(console_sink),
    quill::PatternFormatterOptions{
      "%(time) [%(thread_id)] %(short_source_location:<28) LOG_%(log_level:<9) %(logger:<12) "
      "%(message)",
      "%H:%M:%S.%Qns", quill::Timezone::LocalTime},
    quill::ClockSourceType::Tsc);

  // Log an informational message which will also init the backend RdtscClock
  LOG_INFO(logger, "This is a log info example with number {}", 123);

  // The function `quill::detail::BackendManager::instance().convert_rdtsc_to_epoch_time(quill::detail::rdtsc())`
  // will return a valid timestamp only after the backend worker has started and processed
  // at least one log with `ClockSourceType::Tsc`.
  // This is because the Rdtsc clock is lazily initialized by the backend worker on the first log message.
  // To ensure at least one log message is processed, we call flush_log here.
  logger->flush_log();

  // Get a timestamp synchronized with the backend's clock
  uint64_t const backend_timestamp = quill::BackendTscClock::now().time_since_epoch().count();
  std::cout << "Synchronized timestamp with the backend: " << backend_timestamp << std::endl;

  return 0;
}