From b7bedbaa1de5f71d8979ea3384f60c3ac7ab2ff8 Mon Sep 17 00:00:00 2001 From: Rodrigo Pastrana Date: Fri, 8 Dec 2023 15:25:13 -0500 Subject: [PATCH] HPCC-30374 Provide JTrace option to declare span start time - Exposes helper method to obtain system and steady clock time_points - Exposes createServerSpan function w/ optional starttime params - Adds simple cppunit tests excersizing both newly exposed functions Signed-off-by: Rodrigo Pastrana --- system/jlib/jtrace.cpp | 13 +++++++- system/jlib/jtrace.hpp | 28 ++++++++++++++++- testing/unittests/jlibtests.cpp | 55 +++++++++++++++++++++++++++++++++ 3 files changed, 94 insertions(+), 2 deletions(-) diff --git a/system/jlib/jtrace.cpp b/system/jlib/jtrace.cpp index b187b6f8aec..cc036a9b796 100644 --- a/system/jlib/jtrace.cpp +++ b/system/jlib/jtrace.cpp @@ -458,6 +458,7 @@ class CTraceManager : implements ITraceManager, public CInterface CTraceManager(); IMPLEMENT_IINTERFACE + virtual ISpan * createServerSpan(const char * name, const IProperties * httpHeaders, const SpanTimeStamp * spanStartTimeStamp, SpanFlags flags) const override; virtual ISpan * createServerSpan(const char * name, StringArray & httpHeaders, SpanFlags flags) const override; virtual ISpan * createServerSpan(const char * name, const IProperties * httpHeaders, SpanFlags flags) const override; @@ -987,9 +988,15 @@ class CServerSpan : public CSpan } public: - CServerSpan(const char * spanName, const IProperties * httpHeaders, SpanFlags flags) + CServerSpan(const char * spanName, const IProperties * httpHeaders, SpanFlags flags, const SpanTimeStamp * spanStartTimeStamp = nullptr) : CSpan(spanName) { + if (spanStartTimeStamp && spanStartTimeStamp->isInitialized()) + { + opts.start_system_time = opentelemetry::common::SystemTimestamp(spanStartTimeStamp->systemClockTime); + opts.start_steady_time = opentelemetry::common::SteadyTimestamp(spanStartTimeStamp->steadyClockTime); + } + opts.kind = opentelemetry::trace::SpanKind::kServer; setSpanContext(httpHeaders, flags); init(flags); @@ -1339,6 +1346,10 @@ ISpan * CTraceManager::createServerSpan(const char * name, const IProperties * h return new CServerSpan(name, httpHeaders, flags); } +ISpan * CTraceManager::createServerSpan(const char * name, const IProperties * httpHeaders, const SpanTimeStamp * spanStartTimeStamp, SpanFlags flags) const +{ + return new CServerSpan(name, httpHeaders, flags, spanStartTimeStamp); +} //--------------------------------------------------------------------------------------------------------------------- diff --git a/system/jlib/jtrace.hpp b/system/jlib/jtrace.hpp index aa2a46a077f..6e0b34137e0 100644 --- a/system/jlib/jtrace.hpp +++ b/system/jlib/jtrace.hpp @@ -17,6 +17,8 @@ #ifndef JTRACE_HPP #define JTRACE_HPP +#include + /** * @brief This follows open telemetry's span attribute naming conventions * Known HPCC span Keys could be added here @@ -75,8 +77,32 @@ interface ISpan : extends IInterface extern jlib_decl IProperties * getClientHeaders(const ISpan * span); extern jlib_decl IProperties * getSpanContext(const ISpan * span); +struct SpanTimeStamp +{ + std::chrono::nanoseconds steadyClockTime = std::chrono::nanoseconds::zero(); + std::chrono::nanoseconds systemClockTime = std::chrono::nanoseconds::zero(); + + void now() + { + systemClockTime = std::chrono::duration_cast(std::chrono::system_clock::now().time_since_epoch()); + steadyClockTime = std::chrono::duration_cast(std::chrono::steady_clock::now().time_since_epoch()); + } + + void setMSTickTime(const unsigned int msTickTime) + { + systemClockTime = std::chrono::duration_cast(std::chrono::system_clock::now().time_since_epoch() - std::chrono::milliseconds(msTick() - msTickTime)); + steadyClockTime = std::chrono::duration_cast(std::chrono::steady_clock::now().time_since_epoch() - std::chrono::milliseconds(msTick() - msTickTime)); + } + + bool isInitialized() const + { + return systemClockTime != std::chrono::nanoseconds::zero(); + } +}; + interface ITraceManager : extends IInterface { + virtual ISpan * createServerSpan(const char * name, const IProperties * httpHeaders, const SpanTimeStamp * spanStartTimeStamp, SpanFlags flags = SpanFlags::None) const = 0; virtual ISpan * createServerSpan(const char * name, StringArray & httpHeaders, SpanFlags flags = SpanFlags::None) const = 0; virtual ISpan * createServerSpan(const char * name, const IProperties * httpHeaders, SpanFlags flags = SpanFlags::None) const = 0; virtual bool isTracingEnabled() const = 0; @@ -85,6 +111,7 @@ interface ITraceManager : extends IInterface extern jlib_decl ISpan * getNullSpan(); extern jlib_decl void initTraceManager(const char * componentName, const IPropertyTree * componentConfig, const IPropertyTree * globalConfig); extern jlib_decl ITraceManager & queryTraceManager(); + /* Temporarily disabled due to build issues in certain environments #ifdef _USE_CPPUNIT @@ -96,7 +123,6 @@ extern jlib_decl void testJLogExporterPrintAttributes(StringBuffer & out, const #endif */ - //The following class is responsible for ensuring that the active span is restored in a context when the scope is exited //Use a template class so it can be reused for IContextLogger and IEspContext template diff --git a/testing/unittests/jlibtests.cpp b/testing/unittests/jlibtests.cpp index 3a1ece2eb20..b513393190d 100644 --- a/testing/unittests/jlibtests.cpp +++ b/testing/unittests/jlibtests.cpp @@ -66,6 +66,7 @@ class JlibTraceTest : public CppUnit::TestFixture //CPPUNIT_TEST(testJTraceJLOGExporterprintResources); //CPPUNIT_TEST(testJTraceJLOGExporterprintAttributes); + CPPUNIT_TEST(manualTestsDeclaredSpanStartTime); CPPUNIT_TEST_SUITE_END(); const char * simulatedGlobalYaml = R"!!(global: @@ -188,6 +189,60 @@ class JlibTraceTest : public CppUnit::TestFixture CPPUNIT_ASSERT_EQUAL_MESSAGE("Missing resource attribute detected", true, jtraceAsTree->hasProp("resources/telemetry.sdk.name")); }*/ + //not able to programmatically test yet, but can visually inspect trace output + void manualTestsDeclaredSpanStartTime() + { + Owned emptyMockHTTPHeaders = createProperties(); + SpanTimeStamp declaredSpanStartTime; + declaredSpanStartTime.now(); // must be initialized via now(), or setMSTickTime + MilliSleep(125); + + { + //duration should be at least 125 milliseconds + Owned serverSpan = queryTraceManager().createServerSpan("declaredSpanStartTime", emptyMockHTTPHeaders, &declaredSpanStartTime); + //{ "type": "span", "name": "declaredSpanStartTime", "trace_id": "0a2eff24e1996540056745aaeb2f5824", "span_id": "46d0faf8b4da893e", + //"start": 1702672311203213259, "duration": 125311051 } + } + + auto reqStartMSTick = msTick(); + // a good test would track chrono::system_clock::now() at the point of span creation + // ensure a measurable sleep time between reqStartMSTick and msTickOffsetTimeStamp + // then compare OTel reported span start timestamp to span creation-time timestamp + SpanTimeStamp msTickOffsetTimeStamp; + msTickOffsetTimeStamp.setMSTickTime(reqStartMSTick); + //sleep for 50 milliseconds after span creation and mstick offset, expect at least 50 milliseconds duration output + MilliSleep(50); + + { + SpanTimeStamp nowTimeStamp; //not used, printed out as "start" time for manual comparison + nowTimeStamp.now(); + { + Owned serverSpan = queryTraceManager().createServerSpan("msTickOffsetStartTime", emptyMockHTTPHeaders, &msTickOffsetTimeStamp); + } + + DBGLOG("MsTickOffset span actual start-time timestamp: %lld", (long long)(nowTimeStamp.systemClockTime).count()); + //14:49:13.776139 904 MsTickOffset span actual start-time timestamp: 1702669753775893057 + //14:49:13.776082 904 { "type": "span", "name": "msTickOffsetStartTime", "trace_id": "6e89dd6082ff647daed523089f032240", "span_id": "fd359b41a0a9626d", + //"start": 1702669753725771035, "duration": 50285323 } + //Actual start - declared start: 1702669753775893057-1702669753725771035 = 50162022 + } + + //uninitialized SpanTimeStamp will be ignored, and current time will be used + SpanTimeStamp uninitializedTS; + CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected initialized spanTimeStamp", false, uninitializedTS.isInitialized()); + CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected initialized spanTimeStamp", true, uninitializedTS.systemClockTime == std::chrono::nanoseconds::zero()); + CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected initialized spanTimeStamp", true, uninitializedTS.steadyClockTime == std::chrono::nanoseconds::zero()); + { + Owned serverSpan = queryTraceManager().createServerSpan("uninitializeddeclaredSpanStartTime", emptyMockHTTPHeaders, &uninitializedTS); + //sleep for 75 milliseconds after span creation, expect at least 75 milliseconds duration output + MilliSleep(75); + + //14:22:37.865509 30396 { "type": "span", "name": "uninitializeddeclaredSpanStartTime", "trace_id": "f7844c5c09b413e008f912ded0e12dec", "span_id": "7fcf9042a090c663", + //"start": 1702668157790080022, + //"duration": 75316248 } + } + } + void testTraceDisableConfig() { Owned testTree = createPTreeFromYAMLString(disableTracingYaml, ipt_none, ptr_ignoreWhiteSpace, nullptr);