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.

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

Conversation

timothyklemm
Copy link
Contributor

@timothyklemm timothyklemm commented Apr 19, 2024

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:

  • This change is a bug fix (non-breaking change which fixes an issue).
  • This change is a new feature (non-breaking change which adds functionality).
  • This change improves the code (refactor or other change that does not change the functionality)
  • This change fixes warnings (the fix does not alter the functionality or the generated code)
  • This change is a breaking change (fix or feature that will cause existing behavior to change).
  • This change alters the query API (existing queries will have to be recompiled)

Checklist:

  • My code follows the code style of this project.
    • My code does not create any new warnings from compiler, build system, or lint.
  • The commit message is properly formatted and free of typos.
    • The commit message title makes sense in a changelog, by itself.
    • The commit is signed.
  • My change requires a change to the documentation.
    • I have updated the documentation accordingly, or...
    • I have created a JIRA ticket to update the documentation.
    • Any new interfaces or exported functions are appropriately commented.
  • I have read the CONTRIBUTORS document.
  • The change has been fully tested:
    • I have added tests to cover my changes.
    • All new and existing tests passed.
    • I have checked that this change does not introduce memory leaks.
    • I have used Valgrind or similar tools to check for potential issues.
  • I have given due consideration to all of the following potential concerns:
    • Scalability
    • Performance
    • Security
    • Thread-safety
    • Cloud-compatibility
    • Premature optimization
    • Existing deployed queries will not be broken
    • This change fixes the problem, not just the symptom
    • The target branch of this pull request is appropriate for such a change.
  • There are no similar instances of the same problem that should be addressed
    • I have addressed them here
    • I have raised JIRA issues to address them separately
  • This is a user interface / front-end modification
    • I have tested my changes in multiple modern browsers
    • The component(s) render as expected

Smoketest:

  • Send notifications about my Pull Request position in Smoketest queue.
  • Test my draft Pull Request.

Testing:

Copy link

Jira Issue: https://hpccsystems.atlassian.net//browse/HPCC-31381

Jirabot Action Result:
Workflow Transition: Merge Pending
Updated PR

@AttilaVamos
Copy link
Contributor

AttilaVamos commented Apr 22, 2024

@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.

@timothyklemm
Copy link
Contributor Author

@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.

@AttilaVamos
Copy link
Contributor

@timothyklemm It seems fine now, thanks.

@timothyklemm timothyklemm force-pushed the hpcc-31381-txs_otel_connector branch from ee533ad to 794cabc Compare April 22, 2024 19:35
@timothyklemm
Copy link
Contributor Author

I missed the threaded active span functionality, which can improve this implementation. Will submit an updated version.

@timothyklemm timothyklemm force-pushed the hpcc-31381-txs_otel_connector branch from 794cabc to 27a2f2a Compare April 23, 2024 14:12
@timothyklemm timothyklemm requested a review from rpastrana April 23, 2024 17:39
Copy link
Member

@rpastrana rpastrana left a 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

Copy link
Member

@rpastrana rpastrana left a 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
Copy link
Member

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

Copy link
Contributor Author

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.

Copy link
Member

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.

@@ -104,6 +105,7 @@ class CTxSummary;
interface IEspSecureContext;
interface IEspSecureContextEx;
class CumulativeTimer;
enum class TxUnits;
Copy link
Member

Choose a reason for hiding this comment

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

OriginalTimingUnits?
OrigTimeUnits?
OrigAttributeUnits?

Copy link
Contributor Author

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?

@@ -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;
Copy link
Member

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?

Copy link
Contributor Author

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.

@@ -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);
Copy link
Member

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.

namespace
{
// Iteration of summary entries occurs without knowledge of the summary or its connector.
static thread_local CTxOpenTelemetryConnector* otelConnector = nullptr;
Copy link
Member

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.

Copy link
Contributor Author

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?

else if (requestedStyle & TXSUMMARY_FWD_OTEL)
{
if (otelConnector)
otelConnector->forwardAttribute(name, nullptr, value->getTotalMillis(), TxUnits::millis, queryLogLevel(), queryGroup());
Copy link
Member

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?

Copy link
Contributor Author

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.

// 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;
Copy link
Member

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?

Copy link
Contributor Author

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.

@@ -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
Copy link
Member

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.

return false;
}

#define ENSURE_TARGET_AND_NAME \
Copy link
Member

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?

Copy link
Contributor Author

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.

@timothyklemm
Copy link
Contributor Author

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?

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.

@ghalliday
Copy link
Member

On my radar - I am planning to take a look next week.

Tim Klemm added 2 commits May 2, 2024 14:27
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]>
@timothyklemm timothyklemm force-pushed the hpcc-31381-txs_otel_connector branch from 27a2f2a to 4e5337e Compare May 2, 2024 18:27
@timothyklemm timothyklemm requested a review from rpastrana May 3, 2024 10:27
Copy link
Member

@ghalliday ghalliday left a 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.

{
// 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();
Copy link
Member

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());
}

Copy link
Contributor Author

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.

{
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");
Copy link
Member

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.

Copy link
Contributor Author

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?

Copy link
Contributor Author

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.

@timothyklemm
Copy link
Contributor Author

@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.

@timothyklemm
Copy link
Contributor Author

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants