Skip to content

Event timestamps (record.time) only have millisecond resolution despite 100ns tick field #1514

Description

@jamesdooleymsft

Describe your environment.

  • SDK: 1DS C++ client telemetry (microsoft/cpp_client_telemetry).
  • Source verified against the current main branch — the behavior described below is still present in main.
  • Platforms: affects all platforms by construction. On Windows the record time comes from GetSystemTimeAsFileTime() (coarse system-timer resolution); on non-Windows platforms it is computed from std::chrono::system_clock truncated to milliseconds.
  • Upload path: direct upload / 1DS. Originally observed in ingested data (Kusto), where the time field renders with 7 fractional-second digits but the sub-millisecond digits are always zero.

Steps to reproduce.

  1. Log any event with the SDK (no explicit timestamp needed):
    ILogger* logger = LogManager::Initialize("<ikey>");
    for (int i = 0; i < 100; ++i)
    {
        EventProperties evt("MyEvent");
        logger->LogEvent(evt);
    }
    LogManager::FlushAndTeardown();
  2. Inspect the time (record.time) field of the emitted records — either at ingestion in Kusto, or directly from BaseDecorator::decorate / PAL::getUtcSystemTimeinTicks().
  3. Observe that the value, when expressed in .NET ticks (100 ns units), always ends in four zero digits (i.e. it is an exact multiple of 10000 ticks = 1 ms). Many events emitted in quick succession share the identical time.
  4. Sorting the resulting events by time is unstable, e.g.:
    func_Tables_ClientEvents1DS
    | where DeviceId in (devices)
    | where Time >= datetime(2025-03-24 10:22:11.6962030) and Time <= datetime(2025-03-24 12:07:20.9386138)
    | sort by Time asc
    | extend diffInMs = (Time - prev(Time)) / 1ms
    | project-reorder diffInMs, Time
    Rows with diffInMs == 0 (same-millisecond events) appear in an arbitrary, non-deterministic order.

What is the expected behavior?

The time field is stored as .NET ticks (100 ns units) and is rendered with 7 fractional-second digits, so it should carry sub-millisecond precision. Events emitted within the same millisecond should receive distinct, monotonically increasing timestamps, so that sort by Time yields a stable, correct ordering.

What is the actual behavior?

Timestamps are only millisecond-granular; the sub-millisecond portion of the tick value is always zero. The record time is populated in two code paths, both limited to milliseconds:

  1. Default path — lib/decorators/BaseDecorator.cpp:

    record.time = PAL::getUtcSystemTimeinTicks();

    PAL::getUtcSystemTimeinTicks() in lib/pal/PAL.cpp:

    int64_t PlatformAbstractionLayer::getUtcSystemTimeinTicks() const
    {
    #ifdef _WIN32
        FILETIME tocks;
        ::GetSystemTimeAsFileTime(&tocks);
        ULONGLONG ticks = (ULONGLONG(tocks.dwHighDateTime) << 32) | tocks.dwLowDateTime;
        return ticks + 0x701ce1722770000ULL;
    #else
        std::chrono::time_point<std::chrono::system_clock> now = std::chrono::system_clock::now();
        auto duration = now.time_since_epoch();
        auto millis = std::chrono::duration_cast<std::chrono::milliseconds>(duration).count();
        uint64_t ticks = millis;
        ticks *= 10000; // convert millis to ticks (1 tick = 100ns)
        ticks += 0x89F7FF5F7B58000ULL; // UTC time 0 in .NET ticks
        return ticks;
    #endif
    }
    • Non-Windows: value is derived from milliseconds (millis * 10000), so the low 4 decimal digits are always zero.
    • Windows: GetSystemTimeAsFileTime() returns 100 ns units but its actual resolution is the coarse OS system-timer tick (~0.5–15.6 ms), not 100 ns. GetSystemTimePreciseAsFileTime() is not used.
  2. User-supplied path — lib/decorators/EventPropertiesDecorator.hpp:

    auto timestamp = eventProperties.GetTimestamp();
    if (timestamp != 0)
        // convert timestamp in millis to ticks and add ticks for UTC time 0.
        record.time = timestamp * 10000 + 0x89F7FF5F7B58000ULL;

    EventProperties::SetTimestamp accepts epoch milliseconds, so a caller-supplied timestamp is millisecond-granular by construction.

As a result, same-millisecond events share an identical time, and sort-by-time ordering is unstable/non-deterministic. The precision suggested by the 100 ns tick field and Kusto's 7-digit rendering is misleading.

Additional context.

Suggested fix direction:

  • Non-Windows getUtcSystemTimeinTicks(): preserve full 100 ns tick resolution instead of millis * 10000, e.g.:
    auto nanos = std::chrono::duration_cast<std::chrono::nanoseconds>(duration).count();
    uint64_t ticks = static_cast<uint64_t>(nanos / 100);
    ticks += 0x89F7FF5F7B58000ULL;
  • Windows getUtcSystemTimeinTicks(): use GetSystemTimePreciseAsFileTime() (Windows 8 / Server 2012+) instead of GetSystemTimeAsFileTime() for sub-millisecond resolution.
  • Public API: the user-supplied path (EventProperties::SetTimestamp, epoch milliseconds) remains millisecond-limited even after the above fixes. Consider adding a higher-resolution overload, or documenting the millisecond limitation explicitly.

Note: even with high-resolution wall-clock timestamps, distinct events could still collide within the same 100 ns tick

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugSomething isn't working

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions