diff --git a/exporters/etw/include/opentelemetry/exporters/etw/etw_logger.h b/exporters/etw/include/opentelemetry/exporters/etw/etw_logger.h index bd2478224f..5897d53808 100644 --- a/exporters/etw/include/opentelemetry/exporters/etw/etw_logger.h +++ b/exporters/etw/include/opentelemetry/exporters/etw/etw_logger.h @@ -164,8 +164,8 @@ class Logger : public opentelemetry::logs::Logger # ifdef HAVE_FIELD_TIME { auto timeNow = std::chrono::system_clock::now().time_since_epoch(); - auto millis = std::chrono::duration_cast(timeNow).count(); - evt[ETW_FIELD_TIME] = utils::formatUtcTimestampMsAsISO8601(millis); + auto nanos = std::chrono::duration_cast(timeNow).count(); + evt[ETW_FIELD_TIME] = utils::formatUtcTimestampNsAsISO8601(nanos); } # endif const auto &cfg = GetConfiguration(loggerProvider_); @@ -189,9 +189,9 @@ class Logger : public opentelemetry::logs::Logger } evt[ETW_FIELD_PAYLOAD_NAME] = std::string(name.data(), name.size()); std::chrono::system_clock::time_point ts = timestamp; - int64_t tsMs = - std::chrono::duration_cast(ts.time_since_epoch()).count(); - evt[ETW_FIELD_TIMESTAMP] = utils::formatUtcTimestampMsAsISO8601(tsMs); + int64_t tsNs = + std::chrono::duration_cast(ts.time_since_epoch()).count(); + evt[ETW_FIELD_TIMESTAMP] = utils::formatUtcTimestampNsAsISO8601(tsNs); int severity_index = static_cast(severity); if (severity_index < 0 || severity_index >= std::extent::value) diff --git a/exporters/etw/include/opentelemetry/exporters/etw/etw_tracer.h b/exporters/etw/include/opentelemetry/exporters/etw/etw_tracer.h index 41ab741c1c..0c26b0a998 100644 --- a/exporters/etw/include/opentelemetry/exporters/etw/etw_tracer.h +++ b/exporters/etw/include/opentelemetry/exporters/etw/etw_tracer.h @@ -302,25 +302,25 @@ class Tracer : public opentelemetry::trace::Tracer, // local time, but rather UTC time (Z=0). std::chrono::system_clock::time_point startTime = GetStartTime(currentSpan); std::chrono::system_clock::time_point endTime = GetEndTime(currentSpan); - int64_t startTimeMs = - std::chrono::duration_cast(startTime.time_since_epoch()) + int64_t startTimeNs = + std::chrono::duration_cast(startTime.time_since_epoch()) .count(); - int64_t endTimeMs = - std::chrono::duration_cast(endTime.time_since_epoch()).count(); + int64_t endTimeNs = + std::chrono::duration_cast(endTime.time_since_epoch()).count(); - // It may be more optimal to enable passing timestamps as UTC milliseconds + // It may be more optimal to enable passing timestamps as UTC nanoseconds // since Unix epoch instead of string, but that implies additional tooling // is needed to convert it, rendering it NOT human-readable. - evt[ETW_FIELD_STARTTIME] = utils::formatUtcTimestampMsAsISO8601(startTimeMs); + evt[ETW_FIELD_STARTTIME] = utils::formatUtcTimestampNsAsISO8601(startTimeNs); #ifdef ETW_FIELD_ENDTTIME // ETW has its own precise timestamp at envelope layer for every event. // However, in some scenarios it is easier to deal with ISO8601 strings. // In that case we convert the app-created timestamp and place it into // Payload[$ETW_FIELD_TIME] field. The option configurable at compile-time. - evt[ETW_FIELD_ENDTTIME] = utils::formatUtcTimestampMsAsISO8601(endTimeMs); + evt[ETW_FIELD_ENDTTIME] = utils::formatUtcTimestampNsAsISO8601(endTimeNs); #endif - // Duration of Span in milliseconds - evt[ETW_FIELD_DURATION] = endTimeMs - startTimeMs; + // Duration of Span in nanoseconds + evt[ETW_FIELD_DURATION] = endTimeNs - startTimeNs; // Presently we assume that all spans are server spans evt[ETW_FIELD_SPAN_KIND] = uint32_t(opentelemetry::trace::SpanKind::kServer); UpdateStatus(currentSpan, evt); @@ -622,8 +622,8 @@ class Tracer : public opentelemetry::trace::Tracer, #ifdef HAVE_FIELD_TIME { auto timeNow = std::chrono::system_clock::now().time_since_epoch(); - auto millis = std::chrono::duration_cast(timeNow).count(); - evt[ETW_FIELD_TIME] = utils::formatUtcTimestampMsAsISO8601(millis); + auto nanosecs = std::chrono::duration_cast(timeNow).count(); + evt[ETW_FIELD_TIME] = utils::formatUtcTimestampNsAsISO8601(nanosecs); } #endif diff --git a/exporters/etw/include/opentelemetry/exporters/etw/utils.h b/exporters/etw/include/opentelemetry/exporters/etw/utils.h index 4d38c1fb6f..ef6edc5ca2 100644 --- a/exporters/etw/include/opentelemetry/exporters/etw/utils.h +++ b/exporters/etw/include/opentelemetry/exporters/etw/utils.h @@ -234,37 +234,38 @@ static inline int64_t getUtcSystemTimeinTicks() #endif } +constexpr unsigned int NANOSECS_PRECISION = 1000000000; /** - * @brief Convert local system milliseconds time to ISO8601 string UTC time + * @brief Convert local system nanoseconds time to ISO8601 string UTC time * - * @param timestampMs Milliseconds since epoch in system time + * @param timestampNs Milliseconds since epoch in system time * - * @return ISO8601 UTC string with microseconds part set to 000 + * @return ISO8601 UTC string with nanoseconds */ -static inline std::string formatUtcTimestampMsAsISO8601(int64_t timestampMs) +static inline std::string formatUtcTimestampNsAsISO8601(int64_t timestampNs) { - char buf[sizeof("YYYY-MM-DDTHH:MM:SS.ssssssZ") + 1] = {0}; + char buf[sizeof("YYYY-MM-DDTHH:MM:SS.sssssssssZ") + 1] = {0}; #ifdef _WIN32 - __time64_t seconds = static_cast<__time64_t>(timestampMs / 1000); - int milliseconds = static_cast(timestampMs % 1000); + __time64_t seconds = static_cast<__time64_t>(timestampNs / NANOSECS_PRECISION); + int nanoseconds = static_cast(timestampNs % NANOSECS_PRECISION); tm tm; if (::_gmtime64_s(&tm, &seconds) != 0) { memset(&tm, 0, sizeof(tm)); } - ::_snprintf_s(buf, _TRUNCATE, "%04d-%02d-%02dT%02d:%02d:%02d.%06dZ", 1900 + tm.tm_year, - 1 + tm.tm_mon, tm.tm_mday, tm.tm_hour, tm.tm_min, tm.tm_sec, 1000 * milliseconds); + ::_snprintf_s(buf, _TRUNCATE, "%04d-%02d-%02dT%02d:%02d:%02d.%09dZ", 1900 + tm.tm_year, + 1 + tm.tm_mon, tm.tm_mday, tm.tm_hour, tm.tm_min, tm.tm_sec, nanoseconds); #else - time_t seconds = static_cast(timestampMs / 1000); - int milliseconds = static_cast(timestampMs % 1000); + time_t seconds = static_cast(timestampNs / NANOSECS_PRECISION); + int nanoseconds = static_cast(timestampNs % NANOSECS_PRECISION); tm tm; bool valid = (gmtime_r(&seconds, &tm) != NULL); if (!valid) { memset(&tm, 0, sizeof(tm)); } - (void)snprintf(buf, sizeof(buf), "%04d-%02d-%02dT%02d:%02d:%02d.%06dZ", 1900 + tm.tm_year, - 1 + tm.tm_mon, tm.tm_mday, tm.tm_hour, tm.tm_min, tm.tm_sec, 1000 * milliseconds); + (void)snprintf(buf, sizeof(buf), "%04d-%02d-%02dT%02d:%02d:%02d.%09dZ", 1900 + tm.tm_year, + 1 + tm.tm_mon, tm.tm_mday, tm.tm_hour, tm.tm_min, tm.tm_sec, nanoseconds); #endif return buf; } diff --git a/exporters/etw/test/etw_logger_test.cc b/exporters/etw/test/etw_logger_test.cc index 4e2210118f..7d9040b553 100644 --- a/exporters/etw/test/etw_logger_test.cc +++ b/exporters/etw/test/etw_logger_test.cc @@ -33,7 +33,7 @@ const char *kGlobalProviderName = "OpenTelemetry-ETW-TLD"; * "Payload": { * "Name": "test", * "SpanId": "0000000000000000", - * "Timestamp": "2021-09-30T23:40:40.081000Z", + * "Timestamp": "2021-09-30T23:40:40.066411500Z", * "TraceId": "00000000000000000000000000000000", * "_name": "Log", * "body": "This is test message", @@ -72,7 +72,7 @@ TEST(ETWLogger, LoggerCheckWithBody) * "Payload": { * "Name": "test", * "SpanId": "0000000000000000", - * "Timestamp": "2021-09-30T22:04:15.422000Z", + * "Timestamp": "2021-09-30T22:04:15.066411500Z", * "TraceId": "00000000000000000000000000000000", * "_name": "Log", * "attrib1": 1, diff --git a/exporters/etw/test/etw_tracer_test.cc b/exporters/etw/test/etw_tracer_test.cc index d80323be22..a23345ddd9 100644 --- a/exporters/etw/test/etw_tracer_test.cc +++ b/exporters/etw/test/etw_tracer_test.cc @@ -356,11 +356,11 @@ TEST(ETWTracer, GlobalSingletonTracer) "ActivityID": "6ed94703-6b0a-4e76-0000-000000000000", "RelatedActivityID": null, "Payload": { - "Duration": 0, + "Duration": 23456, "Kind": 1, "Name": "Span1", "SpanId": "0347d96e0a6b764e", - "StartTime": "2021-05-10T18:45:27.028000Z", + "StartTime": "2021-05-10T18:45:27.066411500Z", "StatusCode": 0, "StatusMessage": "", "Success": "True", @@ -388,11 +388,11 @@ TEST(ETWTracer, GlobalSingletonTracer) "ActivityID": "3b7b2ecb-2e84-4903-0000-000000000000", "RelatedActivityID": null, "Payload": { - "Duration": 0, + "Duration": 03434, "Kind": 1, "Name": "Span2", "SpanId": "cb2e7b3b842e0349", - "StartTime": "2021-05-10T18:45:27.028000Z", + "StartTime": "2021-05-10T18:45:27.066411500Z", "StatusCode": 0, "StatusMessage": "", "Success": "True", @@ -420,11 +420,11 @@ TEST(ETWTracer, GlobalSingletonTracer) "ActivityID": "0a970247-ba0e-4d4b-0000-000000000000", "RelatedActivityID": null, "Payload": { - "Duration": 1, + "Duration": 12323, "Kind": 1, "Name": "Span3", "SpanId": "4702970a0eba4b4d", - "StartTime": "2021-05-10T18:45:27.028000Z", + "StartTime": "2021-05-10T18:45:27.066411500Z", "StatusCode": 0, "StatusMessage": "", "Success": "True",