From 47859cc37e977f70515bbaaf6c4a560899b0ffcd Mon Sep 17 00:00:00 2001 From: Max Golovanov Date: Wed, 30 Jun 2021 19:37:27 -0700 Subject: [PATCH 1/2] ETW example and tests clean-up (#882) --- .../opentelemetry/context/runtime_context.h | 2 +- examples/CMakeLists.txt | 3 + examples/etw_threads/CMakeLists.txt | 6 + examples/etw_threads/README.md | 32 ++++ examples/etw_threads/main.cc | 154 ++++++++++++++++++ exporters/etw/test/etw_tracer_test.cc | 151 +++++++++++++++-- 6 files changed, 337 insertions(+), 11 deletions(-) create mode 100644 examples/etw_threads/CMakeLists.txt create mode 100644 examples/etw_threads/README.md create mode 100644 examples/etw_threads/main.cc diff --git a/api/include/opentelemetry/context/runtime_context.h b/api/include/opentelemetry/context/runtime_context.h index 400b3de544..afefa93e7d 100644 --- a/api/include/opentelemetry/context/runtime_context.h +++ b/api/include/opentelemetry/context/runtime_context.h @@ -169,7 +169,7 @@ inline Token::~Token() } // The ThreadLocalContextStorage class is a derived class from -// RuntimeContextStorage and provides a wrapper for propogating context through +// RuntimeContextStorage and provides a wrapper for propagating context through // cpp thread locally. This file must be included to use the RuntimeContext // class if another implementation has not been registered. class ThreadLocalContextStorage : public RuntimeContextStorage diff --git a/examples/CMakeLists.txt b/examples/CMakeLists.txt index 9ea0a544fb..782f20d18e 100644 --- a/examples/CMakeLists.txt +++ b/examples/CMakeLists.txt @@ -2,6 +2,9 @@ if(WITH_OTLP_GRPC OR WITH_OTLP_HTTP) add_subdirectory(otlp) add_subdirectory(grpc) endif() +if(WITH_ETW) + add_subdirectory(etw_threads) +endif() if(WITH_JAEGER) add_subdirectory(jaeger) endif() diff --git a/examples/etw_threads/CMakeLists.txt b/examples/etw_threads/CMakeLists.txt new file mode 100644 index 0000000000..fd6ac76443 --- /dev/null +++ b/examples/etw_threads/CMakeLists.txt @@ -0,0 +1,6 @@ +project(etw_threadpool) + +add_executable(etw_threadpool main.cc) + +target_link_libraries(etw_threadpool ${CMAKE_THREAD_LIBS_INIT} + opentelemetry_api opentelemetry_exporter_etw) diff --git a/examples/etw_threads/README.md b/examples/etw_threads/README.md new file mode 100644 index 0000000000..a004a9f55b --- /dev/null +++ b/examples/etw_threads/README.md @@ -0,0 +1,32 @@ +# ETW Exporter multithreaded context propagation example + +## Preface + +This example shows how to pass context from main dispatcher thread to worker threads. +While this example is convenient to run in Visual Studio with ETW exporter, the same +logic should apply to any other exporter. Only the initial portion that obtains ETW +Tracer is unique to ETW, the rest can be reused. + +## How to debug events in Visual Studio 2019 or newer + +Specify your component instrumentation name, which should match the destination ETW +Provider Name or GUID. Example uses "OpenTelemetry-ETW-TLD" for the instrument / +instrumentation name. + +In Visual Studio IDE: + +- navigate to `View -> Other Windows -> Diagnostic Events...` +- click `Configure...` gear on top. +- specify `OpenTelemetry-ETW-TLD` in the list of providers to monitor. +- run example. +- `Diagnostic Events` view shows you the event flow in realtime. + +## Explanation of the code flow + +`main` function acts as a dispatcher to manage thread pool called `pool`. `beep_bop` +span is started in the `main`. Then in a loop up to `kMaxThreads` get started +concurrently. Each thread executing `beep` function with a parent scope of `main`. +`beep` subsequently calls into `bop` function, with a parent scope of `beep` span. +Entire execution of all threads is grouped under the main span called `beep_bop`. +At the end of execution, the `main` function joins all pending threads and ends +the main span. diff --git a/examples/etw_threads/main.cc b/examples/etw_threads/main.cc new file mode 100644 index 0000000000..d25883d1d1 --- /dev/null +++ b/examples/etw_threads/main.cc @@ -0,0 +1,154 @@ +// Copyright The OpenTelemetry Authors +// SPDX-License-Identifier: Apache-2.0 + +// Include common Trace Provider API and processor +#include "opentelemetry/sdk/trace/simple_processor.h" +#include "opentelemetry/sdk/trace/tracer_provider.h" +#include "opentelemetry/trace/provider.h" + +#include "opentelemetry/exporters/etw/etw_tracer_exporter.h" + +#include +#include + +#include +#ifndef LOG_DEBUG +# include + +/** + * @brief Thread-safe logger routine. + * @param format + * @param args + * @return + */ +static inline int log_vprintf(const char *format, va_list args) +{ + static std::mutex cout_mutex; + std::lock_guard lk(cout_mutex); + return vprintf(format, args); +}; + +/** + * @brief Thread-safe logger routine. + * @param format + * @param + * @return + */ +static inline int log_printf(const char *format, ...) +{ + int result; + va_list ap; + va_start(ap, format); + result = log_vprintf(format, ap); + va_end(ap); + return result; +}; + +// Debug macros +# define LOG_DEBUG(fmt_, ...) log_printf(" " fmt_ "\n", ##__VA_ARGS__) +# define LOG_TRACE(fmt_, ...) log_printf(" " fmt_ "\n", ##__VA_ARGS__) +# define LOG_INFO(fmt_, ...) log_printf(" " fmt_ "\n", ##__VA_ARGS__) +# define LOG_WARN(fmt_, ...) log_printf(" " fmt_ "\n", ##__VA_ARGS__) +# define LOG_ERROR(fmt_, ...) log_printf(" " fmt_ "\n", ##__VA_ARGS__) +#endif + +using namespace OPENTELEMETRY_NAMESPACE; + +using namespace opentelemetry::exporter::etw; + +// Specify destination ETW Provider Name or GUID. +// +// In Visual Studio: +// - View -> Other Windows -> Diagnostic Events... +// - Click Configure (gear on top). +// - Specify "OpenTelemetry-ETW-TLD" in the list of providers. +// +// Event view shows event flow in realtime. +const char *kGlobalProviderName = "OpenTelemetry-ETW-TLD"; + +std::string providerName = kGlobalProviderName; + +// One provider can be used to associate with different destinations. +exporter::etw::TracerProvider provider; + +// Code below is generic and may be reused with any other TracerProvider. +// In ETW provider case - instrumentation name must match destination +// ETW provider name. +nostd::shared_ptr tracer = provider.GetTracer(providerName, "1.0"); + +// Obtain numeric thread id +static inline uint64_t gettid() +{ + std::stringstream ss; + ss << std::this_thread::get_id(); + uint64_t id = std::stoull(ss.str()); + return id; +} + +// bop gets called by beep. +void bop() +{ + LOG_TRACE("bop worker tid=%u", gettid()); + auto span = tracer->StartSpan("bop"); + span->AddEvent("BopEvent", {{"tid", gettid()}}); + span->SetAttribute("attrib", 2); + span->End(); +} + +// beep gets called in its own thread. +// It is running in a thread pool, invoked via lambda by dispatcher. +void beep() +{ + LOG_TRACE("beep worker tid=%u", gettid()); + auto span = tracer->StartSpan("beep"); + span->AddEvent("BeepEvent", {{"tid", gettid()}}); + span->SetAttribute("attrib", 1); + { + auto bopScope = tracer->WithActiveSpan(span); + bop(); + } + span->End(); +} + +// Max number of threads to spawn +constexpr int kMaxThreads = 10; + +int main(int arc, char **argv) +{ + std::thread pool[kMaxThreads]; + + // Main dispatcher span: parent of all child thread spans. + auto mainSpan = tracer->StartSpan("beep_bop"); + mainSpan->SetAttribute("attrib", 0); + + // Start several threads to perform beep-bop actions. + LOG_TRACE("beep-boop dispatcher tid=%u", gettid()); + for (auto i = 0; i < kMaxThreads; i++) + { + pool[i] = std::thread([&]() { + // This code runs in its own worker thread. + auto beepScope = tracer->WithActiveSpan(mainSpan); + // call beep -> bop + beep(); + }); + }; + + // Join all worker threads in the pool + for (auto &th : pool) + { + try + { + if (th.joinable()) + th.join(); + } + catch (...) + { + // thread might have been gracefully terminated already + } + } + + // End span + mainSpan->End(); + + return 0; +} diff --git a/exporters/etw/test/etw_tracer_test.cc b/exporters/etw/test/etw_tracer_test.cc index 45d49356c8..400099bbe7 100644 --- a/exporters/etw/test/etw_tracer_test.cc +++ b/exporters/etw/test/etw_tracer_test.cc @@ -14,6 +14,8 @@ using namespace OPENTELEMETRY_NAMESPACE; using namespace opentelemetry::exporter::etw; +const char *kGlobalProviderName = "OpenTelemetry-ETW-TLD"; + std::string getTemporaryValue() { return std::string("Value from Temporary std::string"); @@ -43,11 +45,10 @@ TEST(ETWTracer, TracerCheck) // Windows Defender Firewall API - GP {0EFF663F-8B6E-4E6D-8182-087A8EAA29CB} // Windows Defender Firewall Driver {D5E09122-D0B2-4235-ADC1-C89FAAAF1069} - std::string providerName = "OpenTelemetry-ETW-TLD"; // supply unique instrumentation name here + std::string providerName = kGlobalProviderName; // supply unique instrumentation name here exporter::etw::TracerProvider tp; - // TODO: this code should fallback to MsgPack if TLD is not available - auto tracer = tp.GetTracer(providerName, "TLD"); + auto tracer = tp.GetTracer(providerName); // Span attributes Properties attribs = @@ -117,7 +118,7 @@ TEST(ETWTracer, TracerCheck) /* { "Timestamp": "2021-03-19T21:04:38.411193-07:00", - "ProviderName": "OpenTelemetry-ETW-Provider", + "ProviderName": "OpenTelemetry-ETW-TLD", "Id": 13, "Message": null, "ProcessId": 15120, @@ -131,7 +132,7 @@ TEST(ETWTracer, TracerCheck) */ TEST(ETWTracer, TracerCheckMinDecoration) { - std::string providerName = "OpenTelemetry-ETW-TLD"; + std::string providerName = kGlobalProviderName; exporter::etw::TracerProvider tp ({ {"enableTraceId", false}, @@ -141,7 +142,7 @@ TEST(ETWTracer, TracerCheckMinDecoration) {"enableRelatedActivityId", false}, {"enableAutoParent", false} }); - auto tracer = tp.GetTracer(providerName, "TLD"); + auto tracer = tp.GetTracer(providerName); { auto aSpan = tracer->StartSpan("A.min"); auto aScope = tracer->WithActiveSpan(aSpan); @@ -166,7 +167,7 @@ TEST(ETWTracer, TracerCheckMinDecoration) /* { "Timestamp": "2021-03-19T21:04:38.4120274-07:00", - "ProviderName": "OpenTelemetry-ETW-Provider", + "ProviderName": "OpenTelemetry-ETW-TLD", "Id": 21, "Message": null, "ProcessId": 15120, @@ -183,7 +184,7 @@ TEST(ETWTracer, TracerCheckMinDecoration) */ TEST(ETWTracer, TracerCheckMaxDecoration) { - std::string providerName = "OpenTelemetry-ETW-TLD"; + std::string providerName = kGlobalProviderName; exporter::etw::TracerProvider tp ({ {"enableTraceId", true}, @@ -192,7 +193,7 @@ TEST(ETWTracer, TracerCheckMaxDecoration) {"enableRelatedActivityId", true}, {"enableAutoParent", true} }); - auto tracer = tp.GetTracer(providerName, "TLD" ); + auto tracer = tp.GetTracer(providerName); { auto aSpan = tracer->StartSpan("A.max"); auto aScope = tracer->WithActiveSpan(aSpan); @@ -222,7 +223,7 @@ TEST(ETWTracer, TracerCheckMsgPack) {"enableRelatedActivityId", true}, {"enableAutoParent", true} }); - auto tracer = tp.GetTracer(providerName, "MsgPack" ); + auto tracer = tp.GetTracer(providerName); { auto aSpan = tracer->StartSpan("A.max"); auto aScope = tracer->WithActiveSpan(aSpan); @@ -249,6 +250,136 @@ TEST(ETWTracer, TracerCheckMsgPack) tracer->CloseWithMicroseconds(0); } +/** + * @brief Global Tracer singleton may be placed in .h header and + * shared across different compilation units. All would get the + * same object. + * + * @return Single global tracer instance. +*/ +static OPENTELEMETRY_NAMESPACE::trace::TracerProvider& GetGlobalTracerProvider() +{ + static exporter::etw::TracerProvider tp + ({ + {"enableTraceId", true}, + {"enableSpanId", true}, + {"enableActivityId", true}, + {"enableRelatedActivityId", true}, + {"enableAutoParent", true} + }); + return tp; +} + +static OPENTELEMETRY_NAMESPACE::trace::Tracer& GetGlobalTracer() +{ + static auto tracer = GetGlobalTracerProvider().GetTracer(kGlobalProviderName); + return (*tracer.get()); +} + +TEST(ETWTracer, GlobalSingletonTracer) +{ + // Obtain a global tracer using C++11 magic static. + auto& globalTracer = GetGlobalTracer(); + auto s1 = globalTracer.StartSpan("Span1"); + auto traceId1 = s1->GetContext().trace_id(); + s1->End(); +/* === Span 1 - "TraceId": "182a64258fb1864ca4e1a542eecbd9bf" +{ + "Timestamp": "2021-05-10T11:45:27.028827-07:00", + "ProviderName": "OpenTelemetry-ETW-TLD", + "Id": 5, + "Message": null, + "ProcessId": 23712, + "Level": "Always", + "Keywords": "0x0000000000000000", + "EventName": "Span", + "ActivityID": "6ed94703-6b0a-4e76-0000-000000000000", + "RelatedActivityID": null, + "Payload": { + "Duration": 0, + "Kind": 1, + "Name": "Span1", + "SpanId": "0347d96e0a6b764e", + "StartTime": "2021-05-10T18:45:27.028000Z", + "StatusCode": 0, + "StatusMessage": "", + "Success": "True", + "TraceId": "182a64258fb1864ca4e1a542eecbd9bf", + "_name": "Span" + } +} +*/ + + // Obtain a different tracer withs its own trace-id. + auto localTracer = GetGlobalTracerProvider().GetTracer(kGlobalProviderName); + auto s2 = localTracer->StartSpan("Span2"); + auto traceId2 = s2->GetContext().trace_id(); + s2->End(); +/* === Span 2 - "TraceId": "334bf9a1eed98d40a873a606295a9368" +{ + "Timestamp": "2021-05-10T11:45:27.0289654-07:00", + "ProviderName": "OpenTelemetry-ETW-TLD", + "Id": 5, + "Message": null, + "ProcessId": 23712, + "Level": "Always", + "Keywords": "0x0000000000000000", + "EventName": "Span", + "ActivityID": "3b7b2ecb-2e84-4903-0000-000000000000", + "RelatedActivityID": null, + "Payload": { + "Duration": 0, + "Kind": 1, + "Name": "Span2", + "SpanId": "cb2e7b3b842e0349", + "StartTime": "2021-05-10T18:45:27.028000Z", + "StatusCode": 0, + "StatusMessage": "", + "Success": "True", + "TraceId": "334bf9a1eed98d40a873a606295a9368", + "_name": "Span" + } +} +*/ + + // Obtain the same global tracer with the same trace-id as before. + auto& globalTracer2 = GetGlobalTracer(); + auto s3 = globalTracer2.StartSpan("Span3"); + auto traceId3 = s3->GetContext().trace_id(); + s3->End(); +/* === Span 3 - "TraceId": "182a64258fb1864ca4e1a542eecbd9bf" +{ + "Timestamp": "2021-05-10T11:45:27.0290936-07:00", + "ProviderName": "OpenTelemetry-ETW-TLD", + "Id": 5, + "Message": null, + "ProcessId": 23712, + "Level": "Always", + "Keywords": "0x0000000000000000", + "EventName": "Span", + "ActivityID": "0a970247-ba0e-4d4b-0000-000000000000", + "RelatedActivityID": null, + "Payload": { + "Duration": 1, + "Kind": 1, + "Name": "Span3", + "SpanId": "4702970a0eba4b4d", + "StartTime": "2021-05-10T18:45:27.028000Z", + "StatusCode": 0, + "StatusMessage": "", + "Success": "True", + "TraceId": "182a64258fb1864ca4e1a542eecbd9bf", + "_name": "Span" + } +} +*/ + EXPECT_NE(traceId1, traceId2); + EXPECT_EQ(traceId1, traceId3); + + localTracer->CloseWithMicroseconds(0); + globalTracer.CloseWithMicroseconds(0); +} + /* clang-format on */ #endif From 85564852048e908e7d579374c52f6214e9dca1a6 Mon Sep 17 00:00:00 2001 From: Lalit Kumar Bhasin Date: Thu, 1 Jul 2021 08:43:50 +0530 Subject: [PATCH 2/2] Few minor fixes for zipkin exporter (#886) --- .../opentelemetry/exporters/zipkin/zipkin_exporter.h | 6 +++--- exporters/zipkin/src/recordable.cc | 2 +- exporters/zipkin/test/zipkin_recordable_test.cc | 12 +++++------- 3 files changed, 9 insertions(+), 11 deletions(-) diff --git a/exporters/zipkin/include/opentelemetry/exporters/zipkin/zipkin_exporter.h b/exporters/zipkin/include/opentelemetry/exporters/zipkin/zipkin_exporter.h index a69eaf9caf..cb244867d7 100644 --- a/exporters/zipkin/include/opentelemetry/exporters/zipkin/zipkin_exporter.h +++ b/exporters/zipkin/include/opentelemetry/exporters/zipkin/zipkin_exporter.h @@ -17,11 +17,11 @@ namespace exporter namespace zipkin { -const char *kZipkinEndpointDefault = "http://localhost:9411/api/v2/spans"; - -static const std::string GetDefaultZipkinEndpoint() +inline const std::string GetDefaultZipkinEndpoint() { const char *otel_exporter_zipkin_endpoint_env = "OTEL_EXPORTER_ZIPKIN_ENDPOINT"; + const char *kZipkinEndpointDefault = "http://localhost:9411/api/v2/spans"; + #if defined(_MSC_VER) // avoid calling std::getenv which is deprecated in MSVC. size_t required_size = 0; diff --git a/exporters/zipkin/src/recordable.cc b/exporters/zipkin/src/recordable.cc index bbdc85c548..07d9b09c9d 100644 --- a/exporters/zipkin/src/recordable.cc +++ b/exporters/zipkin/src/recordable.cc @@ -225,7 +225,7 @@ void Recordable::SetStartTime(opentelemetry::common::SystemTimestamp start_time) void Recordable::SetDuration(std::chrono::nanoseconds duration) noexcept { - span_["duration"] = duration.count(); + span_["duration"] = std::chrono::duration_cast(duration).count(); } void Recordable::SetSpanKind(opentelemetry::trace::SpanKind span_kind) noexcept diff --git a/exporters/zipkin/test/zipkin_recordable_test.cc b/exporters/zipkin/test/zipkin_recordable_test.cc index 51ba1024b6..7a5feb8bdb 100644 --- a/exporters/zipkin/test/zipkin_recordable_test.cc +++ b/exporters/zipkin/test/zipkin_recordable_test.cc @@ -12,8 +12,6 @@ #include "opentelemetry/common/timestamp.h" #include "opentelemetry/exporters/zipkin/recordable.h" -#include - #include namespace trace = opentelemetry::trace; @@ -69,16 +67,16 @@ TEST(ZipkinSpanRecordable, SetStartTime) TEST(ZipkinSpanRecordable, SetDuration) { - json j_span = {{"duration", 10}, {"timestamp", 0}}; + std::chrono::nanoseconds durationNS(1000000000); // in ns + std::chrono::microseconds durationMS = + std::chrono::duration_cast(durationNS); // in ms + json j_span = {{"duration", durationMS.count()}, {"timestamp", 0}}; opentelemetry::exporter::zipkin::Recordable rec; // Start time is 0 opentelemetry::common::SystemTimestamp start_timestamp; - std::chrono::nanoseconds duration(10); - uint64_t unix_end = duration.count(); - rec.SetStartTime(start_timestamp); - rec.SetDuration(duration); + rec.SetDuration(durationNS); EXPECT_EQ(rec.span(), j_span); }