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 <[email protected]>
hpcc-systems · Dec 18, 2023 · b7bedba · b7bedba
1 parent c7fb903
commit b7bedba
Show file tree

Hide file tree

Showing 3 changed files with 94 additions and 2 deletions.
diff --git 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
@@ -17,6 +17,8 @@
 
 #ifndef JTRACE_HPP
 #define JTRACE_HPP
+#include <chrono>
+
 /**
  * @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::nanoseconds>(std::chrono::system_clock::now().time_since_epoch());
+        steadyClockTime = std::chrono::duration_cast<std::chrono::nanoseconds>(std::chrono::steady_clock::now().time_since_epoch());
+    }
+
+    void setMSTickTime(const unsigned int msTickTime)
+    {
+        systemClockTime = std::chrono::duration_cast<std::chrono::nanoseconds>(std::chrono::system_clock::now().time_since_epoch() - std::chrono::milliseconds(msTick() - msTickTime));
+        steadyClockTime = std::chrono::duration_cast<std::chrono::nanoseconds>(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 <class CONTEXT>

diff --git 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<IProperties> emptyMockHTTPHeaders = createProperties();
+        SpanTimeStamp declaredSpanStartTime;
+        declaredSpanStartTime.now(); // must be initialized via now(), or setMSTickTime
+        MilliSleep(125);
+
+        {
+            //duration should be at least 125 milliseconds
+            Owned<ISpan> 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<ISpan> 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<ISpan> 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<IPropertyTree> testTree = createPTreeFromYAMLString(disableTracingYaml, ipt_none, ptr_ignoreWhiteSpace, nullptr);