[ETW Exporter] Fix span timestamp(s) precision to nanoseconds (open-t…

…elemetry#1726)

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<std::chrono::milliseconds>(timeNow).count();
-      evt[ETW_FIELD_TIME] = utils::formatUtcTimestampMsAsISO8601(millis);
+      auto nanos          = std::chrono::duration_cast<std::chrono::nanoseconds>(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<std::chrono::milliseconds>(ts.time_since_epoch()).count();
-    evt[ETW_FIELD_TIMESTAMP] = utils::formatUtcTimestampMsAsISO8601(tsMs);
+    int64_t tsNs =
+        std::chrono::duration_cast<std::chrono::nanoseconds>(ts.time_since_epoch()).count();
+    evt[ETW_FIELD_TIMESTAMP] = utils::formatUtcTimestampNsAsISO8601(tsNs);
     int severity_index       = static_cast<int>(severity);
     if (severity_index < 0 ||
         severity_index >= std::extent<decltype(opentelemetry::logs::SeverityNumToText)>::value)

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<std::chrono::milliseconds>(startTime.time_since_epoch())
+      int64_t startTimeNs =
+          std::chrono::duration_cast<std::chrono::nanoseconds>(startTime.time_since_epoch())
               .count();
-      int64_t endTimeMs =
-          std::chrono::duration_cast<std::chrono::milliseconds>(endTime.time_since_epoch()).count();
+      int64_t endTimeNs =
+          std::chrono::duration_cast<std::chrono::nanoseconds>(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<std::chrono::milliseconds>(timeNow).count();
-      evt[ETW_FIELD_TIME] = utils::formatUtcTimestampMsAsISO8601(millis);
+      auto nanosecs       = std::chrono::duration_cast<std::chrono::nanoseconds>(timeNow).count();
+      evt[ETW_FIELD_TIME] = utils::formatUtcTimestampNsAsISO8601(nanosecs);
     }
 #endif
 

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<int>(timestampMs % 1000);
+  __time64_t seconds = static_cast<__time64_t>(timestampNs / NANOSECS_PRECISION);
+  int nanoseconds    = static_cast<int>(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<time_t>(timestampMs / 1000);
-  int milliseconds = static_cast<int>(timestampMs % 1000);
+  time_t seconds  = static_cast<time_t>(timestampNs / NANOSECS_PRECISION);
+  int nanoseconds = static_cast<int>(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;
 }

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,

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",