Skip to content

Commit

Permalink
HPCC-30474 Provide JTrace option to declare span start time
Browse files Browse the repository at this point in the history 
- Exposes spantimestamp struct which insulates internal timestamp logic
- Exposes createServerSpan function w/ optional starttime param
- Adds simple manual cppunit tests

Signed-off-by: Rodrigo Pastrana <[email protected]>
  • Loading branch information
@rpastrana
rpastrana committed Dec 14, 2023
1 parent ff24036 commit 1dc3979
Show file tree
Hide file tree
Showing 3 changed files with 50 additions and 41 deletions.
28 changes: 8 additions & 20 deletions system/jlib/jtrace.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -458,7 +458,7 @@ class CTraceManager : implements ITraceManager, public CInterface
CTraceManager();
IMPLEMENT_IINTERFACE

virtual ISpan * createServerSpan(const char * name, const IProperties * httpHeaders, const std::chrono::time_point<std::chrono::system_clock, std::chrono::nanoseconds> spanStartTime, const std::chrono::time_point<std::chrono::steady_clock, std::chrono::nanoseconds> spanStartSteadyTime, SpanFlags flags) const override;
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;

Expand Down Expand Up @@ -988,14 +988,13 @@ class CServerSpan : public CSpan
}

public:
CServerSpan(const char * spanName, const IProperties * httpHeaders, SpanFlags flags, const std::chrono::time_point<std::chrono::system_clock, std::chrono::nanoseconds> sytemClockStartTime = {}, const std::chrono::time_point<std::chrono::steady_clock, std::chrono::nanoseconds> steadyClockStartTime = {})
CServerSpan(const char * spanName, const IProperties * httpHeaders, SpanFlags flags, const SpanTimeStamp * spanStartTimeStamp = nullptr)
: CSpan(spanName)
{
if (sytemClockStartTime.time_since_epoch() != std::chrono::nanoseconds::zero() &&
steadyClockStartTime.time_since_epoch() != std::chrono::nanoseconds::zero())
if (spanStartTimeStamp && spanStartTimeStamp->isInitilized())
{
opts.start_system_time = opentelemetry::common::SystemTimestamp(sytemClockStartTime);
opts.start_steady_time = opentelemetry::common::SteadyTimestamp(steadyClockStartTime);
opts.start_system_time = opentelemetry::common::SystemTimestamp(spanStartTimeStamp->systemClockTime);
opts.start_steady_time = opentelemetry::common::SteadyTimestamp(spanStartTimeStamp->steadyClockTime);
}

opts.kind = opentelemetry::trace::SpanKind::kServer;
Expand Down Expand Up @@ -1044,18 +1043,6 @@ class CServerSpan : public CSpan

//---------------------------------------------------------------------------------------------------------------------

const std::chrono::time_point<std::chrono::system_clock, std::chrono::nanoseconds> nowSystemClock()
{
const std::chrono::time_point<std::chrono::system_clock, std::chrono::nanoseconds> nowTimePoint = std::chrono::system_clock::now();
return nowTimePoint;
}

const std::chrono::time_point<std::chrono::steady_clock, std::chrono::nanoseconds> nowSteadyClock()
{
const std::chrono::time_point<std::chrono::steady_clock, std::chrono::nanoseconds> nowTimePoint = std::chrono::steady_clock::now();
return nowTimePoint;
}

IProperties * getClientHeaders(const ISpan * span)
{
Owned<IProperties> headers = createProperties(true);
Expand Down Expand Up @@ -1359,10 +1346,11 @@ 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 std::chrono::time_point<std::chrono::system_clock, std::chrono::nanoseconds> systemClockStartTime, const std::chrono::time_point<std::chrono::steady_clock, std::chrono::nanoseconds> steadyClockStartTime, SpanFlags flags = SpanFlags::None) const
ISpan * CTraceManager::createServerSpan(const char * name, const IProperties * httpHeaders, const SpanTimeStamp * spanStartTimeStamp, SpanFlags flags = SpanFlags::None) const
{
return new CServerSpan(name, httpHeaders, flags, systemClockStartTime, steadyClockStartTime);
return new CServerSpan(name, httpHeaders, flags, spanStartTimeStamp);
}

//---------------------------------------------------------------------------------------------------------------------

MODULE_INIT(INIT_PRIORITY_STANDARD)
Expand Down
31 changes: 25 additions & 6 deletions system/jlib/jtrace.hpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -77,10 +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 isInitilized() const
{
return systemClockTime != std::chrono::nanoseconds::zero();
}
};

interface ITraceManager : extends IInterface
{
//virtual ISpan * createDelayedServerSpan(const char * name, const IProperties * httpHeaders, std::chrono::nanoseconds spanStartTime, std::chrono::nanoseconds spanStartSteadyTime = std::chrono::nanoseconds::zero(), SpanFlags flags = SpanFlags::None) const = 0;
virtual ISpan * createServerSpan(const char * name, const IProperties * httpHeaders, const std::chrono::time_point<std::chrono::system_clock, std::chrono::nanoseconds> systemClockStartTime, const std::chrono::time_point<std::chrono::steady_clock, std::chrono::nanoseconds> steadyClockStartTime, SpanFlags flags = SpanFlags::None) const = 0;
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;
Expand All @@ -89,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
Expand All @@ -100,10 +123,6 @@ extern jlib_decl void testJLogExporterPrintAttributes(StringBuffer & out, const
#endif
*/

extern jlib_decl const std::chrono::time_point<std::chrono::system_clock, std::chrono::nanoseconds> nowSystemClock();
extern jlib_decl const std::chrono::time_point<std::chrono::steady_clock, std::chrono::nanoseconds> nowSteadyClock();


//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>
Expand Down
32 changes: 17 additions & 15 deletions testing/unittests/jlibtests.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -23,6 +23,7 @@
#ifdef _USE_CPPUNIT
#include <memory>
#include <chrono>
#include <thread>
#include <algorithm>
#include "jsem.hpp"
#include "jfile.hpp"
Expand Down Expand Up @@ -66,7 +67,7 @@ class JlibTraceTest : public CppUnit::TestFixture

//CPPUNIT_TEST(testJTraceJLOGExporterprintResources);
//CPPUNIT_TEST(testJTraceJLOGExporterprintAttributes);
CPPUNIT_TEST(testDeclaredSpanStartTime);
CPPUNIT_TEST(manualTestsDeclaredSpanStartTime);
CPPUNIT_TEST_SUITE_END();

const char * simulatedGlobalYaml = R"!!(global:
Expand Down Expand Up @@ -189,29 +190,30 @@ class JlibTraceTest : public CppUnit::TestFixture
CPPUNIT_ASSERT_EQUAL_MESSAGE("Missing resource attribute detected", true, jtraceAsTree->hasProp("resources/telemetry.sdk.name"));
}*/

void testDeclaredSpanStartTime()
//not able to programmatically test yet, but can visually inspect trace output
void manualTestsDeclaredSpanStartTime()
{
Owned<IProperties> emptyMockHTTPHeaders = createProperties();
std::chrono::time_point<std::chrono::system_clock, std::chrono::nanoseconds> systemClockTimePoint = {};
std::chrono::time_point<std::chrono::steady_clock, std::chrono::nanoseconds> steadyClockTimePoint = {};

SpanTimeStamp declaredSpanStartTime;
declaredSpanStartTime.now(); // must be initialized via now(), or setMSTickTime
std::this_thread::sleep_for(std::chrono::milliseconds(50));
{
Owned<ISpan> serverSpan = queryTraceManager().createServerSpan("uninitializedStartTimePoints", emptyMockHTTPHeaders, systemClockTimePoint, steadyClockTimePoint);
//{ "type": "span", "name": "uninitializedStartTimePoints", "trace_id": "b75d55036323192bf361764a01301742", "span_id": "e20e42d895a165be", "start": 1702430078380386963, "duration": 2075504 }
Owned<ISpan> serverSpan = queryTraceManager().createServerSpan("declaredSpanStartTime", emptyMockHTTPHeaders, &declaredSpanStartTime);
}

systemClockTimePoint += std::chrono::milliseconds(1000);
steadyClockTimePoint += std::chrono::milliseconds(10);
auto reqStartMSTick = msTick();

SpanTimeStamp msTickOffsetTimeStamp;
msTickOffsetTimeStamp.setMSTickTime(reqStartMSTick);
std::this_thread::sleep_for(std::chrono::milliseconds(50));
{
Owned<ISpan> serverSpan = queryTraceManager().createServerSpan("longAgoStartTimePoints", emptyMockHTTPHeaders, systemClockTimePoint, steadyClockTimePoint);
//{ "type": "span", "name": "oldStartTimePoints", "trace_id": "c69b30421fe1bc2284dc1067fe8df65a", "span_id": "e7f8f28943717b65", "start": 1000000000, "duration": 13235212449700 }
Owned<ISpan> serverSpan = queryTraceManager().createServerSpan("msTickOffsetStartTime", emptyMockHTTPHeaders, &msTickOffsetTimeStamp);
}

systemClockTimePoint = nowSystemClock();
steadyClockTimePoint = nowSteadyClock() + std::chrono::hours(1);
//uninitialized SpanTimeStamp will be ignored, and current time will be used
SpanTimeStamp uninitializedTS;
{
Owned<ISpan> serverSpan = queryTraceManager().createServerSpan("futureSteadyTimePoint", emptyMockHTTPHeaders, systemClockTimePoint, steadyClockTimePoint);
//{ "type": "span", "name": "futureSteadyTimePoint", "trace_id": "3676cdd536686f37da7d39b87b314bc5", "span_id": "c0987a831cb361e0", "start": 1702430699582015756, "duration": -3598764616294 }
Owned<ISpan> serverSpan = queryTraceManager().createServerSpan("uninitializeddeclaredSpanStartTime", emptyMockHTTPHeaders, &uninitializedTS);
}
}

Expand Down

0 comments on commit 1dc3979

Please sign in to comment.