Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

HPCC-30374 Provide JTrace option to declare span start time #18130

Merged
merged 1 commit into from
Dec 19, 2023
Merged

HPCC-30374 Provide JTrace option to declare span start time #18130

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
13 changes: 12 additions & 1 deletion system/jlib/jtrace.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;

Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -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);
}

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

Expand Down
28 changes: 27 additions & 1 deletion system/jlib/jtrace.hpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ok, this gives us two possible ways of instrumenting ESP and Roxie. Either add add SpanTimeStamp (and maybe get rid of the msStartTime that's there now, or just use the existing msStartTime with this function.

{
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;
Expand All @@ -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
Expand All @@ -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>
Expand Down
55 changes: 55 additions & 0 deletions testing/unittests/jlibtests.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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:
Expand Down Expand Up @@ -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
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Since I squashed the commits, I wanted to point out these new comments and varying sleep times and also actual CPPUNIT_ASSERTs on uninitialized states.

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);
Expand Down
Loading