Skip to content

Commit

Permalink
[ETW Exporter] Fix span timestamp(s) precision to nanoseconds (#1726)
Browse files Browse the repository at this point in the history
  • Loading branch information
@lalitb
lalitb authored Nov 1, 2022
1 parent e5590c5 commit ac179dd
Show file tree
Hide file tree
Showing 5 changed files with 38 additions and 37 deletions.
10 changes: 5 additions & 5 deletions exporters/etw/include/opentelemetry/exporters/etw/etw_logger.h
View file
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
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
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
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
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

2 comments on commit ac179dd

@github-actions
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

⚠️ Performance Alert ⚠️

Possible performance regression was detected for benchmark 'OpenTelemetry-cpp api Benchmark'.
Benchmark result of this commit is worse than the previous benchmark result exceeding threshold 2.

Benchmark suite Current: ac179dd Previous: e5590c5 Ratio
BM_ThreadYieldSpinLockThrashing/2/process_time/real_time 33.19579362869263 ms/iter 14.324691560533312 ms/iter 2.32
BM_SpanIdDefaultConstructor 3.42811152012342 ns/iter 1.6903945509782228 ns/iter 2.03

This comment was automatically generated by workflow using github-action-benchmark.

@github-actions
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

⚠️ Performance Alert ⚠️

Possible performance regression was detected for benchmark 'OpenTelemetry-cpp sdk Benchmark'.
Benchmark result of this commit is worse than the previous benchmark result exceeding threshold 2.

Benchmark suite Current: ac179dd Previous: e5590c5 Ratio
BM_BaselineBuffer/2 6305492.877960205 ns/iter 2291829.824447632 ns/iter 2.75

This comment was automatically generated by workflow using github-action-benchmark.

Please sign in to comment.