HPCC-30474 LastCodeReview

- Fixes typo - Adds cppunit tests, and comments Signed-off-by: Rodrigo Pastrana <[email protected]>
hpcc-systems · Dec 15, 2023 · 496aab3 · 496aab3
1 parent c62932e
commit 496aab3
Show file tree

Hide file tree

Showing 3 changed files with 33 additions and 7 deletions.
diff --git a/system/jlib/jtrace.cpp b/system/jlib/jtrace.cpp
@@ -991,7 +991,7 @@ class CServerSpan : public CSpan
     CServerSpan(const char * spanName, const IProperties * httpHeaders, SpanFlags flags, const SpanTimeStamp * spanStartTimeStamp = nullptr)
     : CSpan(spanName)
     {
-        if (spanStartTimeStamp && spanStartTimeStamp->isInitilized())
+        if (spanStartTimeStamp && spanStartTimeStamp->isInitialized())
         {
             opts.start_system_time = opentelemetry::common::SystemTimestamp(spanStartTimeStamp->systemClockTime);
             opts.start_steady_time = opentelemetry::common::SteadyTimestamp(spanStartTimeStamp->steadyClockTime);

diff --git a/system/jlib/jtrace.hpp b/system/jlib/jtrace.hpp
@@ -94,7 +94,7 @@ struct SpanTimeStamp
         steadyClockTime = std::chrono::duration_cast<std::chrono::nanoseconds>(std::chrono::steady_clock::now().time_since_epoch() - std::chrono::milliseconds(msTick() - msTickTime));
     }
 
-    bool isInitilized() const
+    bool isInitialized() const
     {
         return systemClockTime != std::chrono::nanoseconds::zero();
     }

diff --git a/testing/unittests/jlibtests.cpp b/testing/unittests/jlibtests.cpp
@@ -23,7 +23,6 @@
 #ifdef _USE_CPPUNIT
 #include <memory>
 #include <chrono>
-#include <thread>
 #include <algorithm>
 #include "jsem.hpp"
 #include "jfile.hpp"
@@ -196,24 +195,51 @@ class JlibTraceTest : public CppUnit::TestFixture
         Owned<IProperties> emptyMockHTTPHeaders = createProperties();
         SpanTimeStamp declaredSpanStartTime;
         declaredSpanStartTime.now(); // must be initialized via now(), or setMSTickTime
-        std::this_thread::sleep_for(std::chrono::milliseconds(50));
+        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);
-        std::this_thread::sleep_for(std::chrono::milliseconds(50));
+        //sleep for 50 milliseconds after span creation and mstick offset, expect at least 50 milliseconds duration output
+        MilliSleep(50);
+
         {
-            Owned<ISpan> serverSpan = queryTraceManager().createServerSpan("msTickOffsetStartTime", emptyMockHTTPHeaders, &msTickOffsetTimeStamp);
+            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 }
         }
     }