Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[ETW Exporter] Fix span timestamp(s) precision to nanoseconds #1726

Merged
merged 8 commits into from
Nov 1, 2022
Merged

[ETW Exporter] Fix span timestamp(s) precision to nanoseconds #1726

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
8 commits
Select commit Hold shift + click to select a range
06e9280
fix timestamp precision
lalitb Nov 1, 2022
76683de
fix ts
lalitb Nov 1, 2022
e6aa0d8
fix
lalitb Nov 1, 2022
2047952
format
lalitb Nov 1, 2022
1e14902
Merge branch 'main' into etw-ts_precision
lalitb Nov 1, 2022
748556a
fix
lalitb Nov 1, 2022
7fe3c45
fix
lalitb Nov 1, 2022
710e1d8
format
lalitb Nov 1, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
10 changes: 5 additions & 5 deletions exporters/etw/include/opentelemetry/exporters/etw/etw_logger.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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_);
Expand All @@ -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)
Expand Down
22 changes: 11 additions & 11 deletions exporters/etw/include/opentelemetry/exporters/etw/etw_tracer.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down Expand Up @@ -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

Expand Down
27 changes: 14 additions & 13 deletions exporters/etw/include/opentelemetry/exporters/etw/utils.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}
Expand Down
4 changes: 2 additions & 2 deletions exporters/etw/test/etw_logger_test.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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",
Expand Down Expand Up @@ -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,
Expand Down
12 changes: 6 additions & 6 deletions exporters/etw/test/etw_tracer_test.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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",
Expand Down Expand Up @@ -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",
Expand Down Expand Up @@ -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",
Expand Down