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