-
Notifications
You must be signed in to change notification settings - Fork 304
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.
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-31381 Forward trace summary values to Open Telemetry spans #18560
HPCC-31381 Forward trace summary values to Open Telemetry spans #18560
Conversation
Jira Issue: https://hpccsystems.atlassian.net//browse/HPCC-31381 Jirabot Action Result: |
@timothyklemm I don't know why, but no ECL code can run on the platform build from this PR. I can't find any error or crash message in log files or core file. It seems the whole platform stalled somewhere. All components are up and running. |
@AttilaVamos I noticed. I also noticed that other PRs aren't failing as consistently. I don't have an explanation yet, which is why I haven't asked for any reviews. |
@timothyklemm It seems fine now, thanks. |
ee533ad
to
794cabc
Compare
I missed the threaded active span functionality, which can improve this implementation. Will submit an updated version. |
794cabc
to
27a2f2a
Compare
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I might have missed it, but I didn't see explanation of changes in the commit message, take a look at this guide:
https://github.com/hpcc-systems/HPCC-Platform/wiki/Git-commit-message-guidelines
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Left a few comments/questions.
I think one of the main concerns has been the TxSummary lifespan is different than the active span, are we ensuring all TxSummary attributes are being forwarded/set on the current span while it is active?
@@ -93,6 +93,7 @@ typedef enum LogRequest_ | |||
|
|||
#define TXSUMMARY_OUT_TEXT 0x00000001 | |||
#define TXSUMMARY_OUT_JSON 0x00000002 |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Why'd we choose that higher (out of order) bit to signify FWD_OTEL? perhaps a comment would be helpful if we're reserving the lower bits for specific TXSUMMARY_OUT types, and want to use the last few bits for another set of flags
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
We support serialization of summary content using the two output styles. I'm piggybacking on that mechanism to cause cumulative timer forwarding at the end of a transaction and thought the value separation for the new bit would be an additional clue that it isn't a serialization output. Plus, as the span takes over I can envision adding an otel output style that does request serialization in the future.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Perfect. Let's not just leave clues, let's be explicit to avoid any potential future misunderstandings.
esp/platform/esp.hpp
Outdated
@@ -104,6 +105,7 @@ class CTxSummary; | |||
interface IEspSecureContext; | |||
interface IEspSecureContextEx; | |||
class CumulativeTimer; | |||
enum class TxUnits; |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
OriginalTimingUnits?
OrigTimeUnits?
OrigAttributeUnits?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I'm reluctant to include time or timing in the name, because size scaling might become a thing. Since the ESP context interface refers to adding a "trace summary value", maybe something like TraceValueUnits
?
esp/platform/esp.hpp
Outdated
@@ -197,9 +199,15 @@ interface IEspContext : extends IInterface | |||
|
|||
virtual CTxSummary* queryTxSummary()=0; | |||
virtual void addTraceSummaryValue(unsigned logLevel, const char *name, const char *value, const unsigned int group = TXSUMMARY_GRP_CORE)=0; | |||
virtual void addTraceSummaryValue(unsigned logLevel, const char *name, const char *value, const char* otName, unsigned group = TXSUMMARY_GRP_CORE)=0; |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I can infer otName signifies "alternate name to be used by opentelemetry", but I'm not sure it's as obvious and self documenting as it could be. Can we use a self documenting name which ensures future developer will know exactly what this param is for?
Also, is this param only for OpenTelemetry?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
It is absolutely only for open telemetry. Alternate names for other outputs are handled internally by the optional profile. Once passed to the connector, it has no purpose.
esp/platform/espcontext.cpp
Outdated
@@ -123,7 +123,7 @@ class CEspContext : public CInterface, implements IEspContext | |||
if (m_txSummary) | |||
{ | |||
m_txSummary->tailor(this); | |||
m_txSummary->log(getTxSummaryLevel(), getTxSummaryGroup(), getTxSummaryStyle()); | |||
m_txSummary->log(getTxSummaryLevel(), getTxSummaryGroup(), getTxSummaryStyle() | TXSUMMARY_FWD_OTEL); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
we might want to avoid forwarding to otel (really jtrace) if tracing not enabled.
esp/platform/txsummary.cpp
Outdated
namespace | ||
{ | ||
// Iteration of summary entries occurs without knowledge of the summary or its connector. | ||
static thread_local CTxOpenTelemetryConnector* otelConnector = nullptr; |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I assume the connector normalizes values/names to Otel standards, is that what we mean by "connector" here?
Also, we're actually interfacing w/ Jtrace rather than otel.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
The connector has full responsibility for anything needed to normalize names and values for jtrace. I was viewing jtrace as an encapsulation for open telemetry, but if either name here is an issue, should I just make a wholesale change reset back from open telemetry?
esp/platform/txsummary.cpp
Outdated
else if (requestedStyle & TXSUMMARY_FWD_OTEL) | ||
{ | ||
if (otelConnector) | ||
otelConnector->forwardAttribute(name, nullptr, value->getTotalMillis(), TxUnits::millis, queryLogLevel(), queryGroup()); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
forwardAttribute implies some sort of connection, what is that function actually doing? Normalizing? Transforming?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
In this case, the current cumulative timer value is passed to the current thread's connector. The connector will normalize the name and scale the milliseconds measurement. This is triggered during ESP context destruction when the root server span should be the active span.
esp/platform/txsummary.cpp
Outdated
// request. Timer values have not been forwarded, and should forward their values. | ||
otelConnector = connector.get(); | ||
serialize(summary.clear(), logLevel, requestedGroup, TXSUMMARY_FWD_OTEL); | ||
otelConnector = nullptr; |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
what's the lifespan of the "connectors" one per thread/request?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
The connector exists for the duration of the CTxSummary, which is basically the duration of the the ESP context. This method is triggered from the context destructor.
esp/platform/txsummary.cpp
Outdated
@@ -663,3 +684,67 @@ CTxSummary::TxEntryBase* CTxSummary::queryEntry(const char* key) | |||
|
|||
return nullptr; | |||
} | |||
|
|||
StringBuffer& CTxOpenTelemetryConnector::normalizeKey(const char* txKey, const char* otKey, StringBuffer& normalized) const |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
txKey is originalKeyName, and otkey is alternateKeyName, right?
If so, let's use the most selfdocumenting names when possible.
esp/platform/txsummary.cpp
Outdated
return false; | ||
} | ||
|
||
#define ENSURE_TARGET_AND_NAME \ |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
what's the advantage of encapsulating this logic in a define?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Five identical blocks of setup logic with incredibly simple usage. It could be put into a method returning target (or nullptr) if that's preferred.
With the exception of cumulative timer values, values added to the trace summary are forwarded to a span before the summary stores the value for its own use. Timers can't logically be forwarded before the end of the transaction, thus targeting the root server span, because the internal timer object is exposed to the ESP for updates at any time during the transaction. This solution does not cache attributes prior to the existence of an active span. Both the ESP context and the HTTP server add values to the trace summary before creating the root server span, and these values are not forwarded. But the ESP context will reset the values it adds in its constructor before logging the summary, so those values will be forwarded then. |
On my radar - I am planning to take a look next week. |
Signed-off-by: Tim Klemm <[email protected]>
Forward all trace summary values recorded using the CTxSummary class to the current thread's active trace span. Cumulative timers are forwarded at the end of each transaction, while all other values are forwarded immediately. While the trace summary avoids duplicated names, duplicate names will be forwarded. Support Open Telemetry naming conventions by accepting a span attribute name for all values other than cumulative timers. This name is optional. The summary name is forwarded by default. All names are converted to snake case prior to forwarding. Support Open Telemetry expected units of measurement by accepting a summary value scaling indicator for all integral values. This indicator is optional. No scaling is applied by default, with the exception of cumulative timer and timestamp values that are presumed to be milliseconds. Encapsulate forwarding logic for portability to alternate ESP implementations. Signed-off-by: Tim Klemm <[email protected]>
27a2f2a
to
4e5337e
Compare
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
@timothyklemm what is the status of this PR? It looks like it is stuck.
This PR is more complex that I would have expected - I was expecting something very simple to add some of the summary information to a span, and then gradually extend the capabilities to cover more situations.
esp/platform/txsummary.cpp
Outdated
{ | ||
// String values have already been forwarded and should ignore this serialization | ||
// request. Timer values have not been forwarded, and should forward their values. | ||
otelConnector = connector.get(); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
setting a thread local variable around a single function call looks wrong. Really this should be passed in as a parameter.
In this case, inlining the executed code would seem to be much simpler. I think it would be:
{
if(shouldSerialize(requestedLevel, requestedGroup))
otelConnector->forwardAttribute(name, nullptr, value->getTotalMillis(), TxUnits::millis, queryLogLevel(), queryGroup());
}
which would be even better removing the scaling:
{
if(shouldSerialize(requestedLevel, requestedGroup))
otelConnector->forwardAttribute(name, nullptr, value->getTotalNanos(), queryLogLevel(), queryGroup());
}
I am not convinced of the benefit of the class and would further simplify to:
{
if(shouldSerialize(requestedLevel, requestedGroup))
queryThreadedActiveSpan()->setSpanAttribute(name, value->getTotalNanos());
}
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Our TxSummary implementation is very different from what's in scapps. The class was an attempt to create a shareable solution that minimized the integration points in each of the implementations.
esp/platform/espcontext.cpp
Outdated
{ | ||
if (m_txSummary && !isEmptyString(name)) | ||
m_txSummary->append(name, m_txSummary->getElapsedTime(), logLevel, group, "ms"); | ||
m_txSummary->append(name, m_txSummary->getElapsedTime(), otName, TxUnits::millis, logLevel, group, "ms"); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Reflections:
I started off wondering if rather than introducing a units parameter and scaling within the function, it is possible to pass normalized values to the append function? And/or you could pass the type using StatisticMeasure and deduce the suffix (and scaling) from that when generating the existing logging.
That would then allow you to increase the resolution at a later date.
However looking through the code it is fairly complex, and could be simplified. One example - append and set have template parameters for the TSerializer. But as far as I can see they are never overridden - they could be removed and a local tokenSerialiser class used instead.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
You are correct that we have not found a reason to use the templated serializer. It could removed, if we're comfortable changing an interface that has been available to external ESP developers for years.
The suffix is obsolete, at least to us. Our only use of it was to attach units to numbers. With the suffix attached to the value when appended, it caused invalid JSON numeric output. It too could be removed.
Would it be better to consider these changes in a separate PR?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
One of my (possibly misguided) goals was to minimize the changes made to the existing trace summary interfaces. Based on the assumption that scapps might adopt the solution, I thought that keeping as much of the change as possible behind the existing interface would encourage adoption.
Scapps will not be adopting the solution. I believe they have taken the approach of adding new annotations for otel, leaving their TxSummary values and behavior unchanged. I'm wondering if we shouldn't do the same thing.
Most of the existing TxSummary instrumentation is millisecond measurements. Existing TxSummary analytics expect milliseconds. Changing the values to nanoseconds to satisfy otel either invalidates TxSummary output or requires scaling values back to milliseconds.
After some discussion with @rpastrana, it seems we'll consider replacing many of the timing values that represent start and end offsets with client spans that can't be represented in the TxSummary.
Is there still enough value to make a single interface that updates both otel and TxSummary?
If yes, should the inputs satisfy otel expectations, or TxSummary?
If inputs satisfy otel expectations, is maintaining current TxSummary expectations for the same values a requirement?
To be clear, I'm not arguing for any solution. Two reviewers have now made it clear that I completely misunderstood the problem statement. I need more guidance to know the problem I'm trying to solve.
@ghalliday this has been waiting for feedback after my last update. Now the feedback has me questioning if I understand the problem I'm attempting to solve. |
Will no longer attempt to reuse instrumentation. TxSummary will remain unchanged for now. Values we want in spans will be added directly to the appropriate span. |
Forward all trace summary values recorded using the CTxSummary class to the
current thread's active trace span. Cumulative timers are forwarded at the end
of each transaction, while all other values are forwarded immediately. While the
trace summary avoids duplicated names, duplicate names will be forwarded.
Support Open Telemetry naming conventions by accepting a span attribute name for
all values other than cumulative timers. This name is optional. The summary name
is forwarded by default. All names are converted to snake case prior to
forwarding.
Support Open Telemetry expected units of measurement by accepting a summary
value scaling indicator for all integral values. This indicator is optional.
No scaling is applied by default, with the exception of cumulative timer and
timestamp values that are presumed to be milliseconds.
Encapsulate forwarding logic for portability to alternate ESP implementations.
Signed-off-by: Tim Klemm [email protected]
Type of change:
Checklist:
Smoketest:
Testing: