Skip to content

Long running spans - pending trace track all spans approach#4966

Merged
raphaelgavache merged 25 commits into
masterfrom
raphael/long_running_spans_v3
May 15, 2023
Merged

Long running spans - pending trace track all spans approach#4966
raphaelgavache merged 25 commits into
masterfrom
raphael/long_running_spans_v3

Conversation

@raphaelgavache

@raphaelgavache raphaelgavache commented Mar 27, 2023

Copy link
Copy Markdown
Member

Overview

This PR adds support for the long running spans feature, which enables periodic snapshots of running spans to be written. It also includes changes to the PendingTrace and PendingTraceBuffer classes to track long running traces and trigger periodic writes.

Long running spans spec

Long running spans are tracked

  • priority > 0
  • while they last less then 12H

Protocol

  • write the span with all tags
  • span.Duration = write time
  • if running span.Metric["_dd.partial_version"] is set. The highest version is the most recent one
  • if previously running a complete span will have span.Metric["_dd.was_longrunning"] = 1

Configuration

  • feature is disabled by default
  • periodic flushes in [20s, 7.5min] with a default of 5min

Implementation overhead

Feature disabled

  • additional if statement at span initialisation and termination with pendingTraceBuffer.runningSpansEnabled()
  • no-op on the rest

Feature enabled

all traces

  • PendingTrace keeps track of all spans including running ones
  • On write we iterate on all spans including running ones
  • PendingTrace is referenced up to 1 second
  • One insertion to the PendingTraceBuffer queue per trace
  • Running spans are also written if the trace lasts longer then the configured runningFlushInterval (default 5 mins, hard coded min 20s)

other

PendingTraceBuffer is waked up every 1s

Breakdown of the required:

  • track running spans
  • periodically trigger writes
  • encode new tags on spans
  • avoid computing stats on running spans

Track running spans (PendingTrace)

Writes are triggered by PendingTraces and the PendingTraceBuffer. They only point to completed spans.

current links:
span ---> pendingTrace ---> completedSpans
                     |
                     ------->  trigger writes

New approach when the feature is enabled the pendingTrace will track all spans including runningSpans.
To avoid additional allocations all spans are stored in the pendingTrace.spans list.

new links
span -> pendingTrace -> allSpans (running, completed)
                     |
                     ------->  trigger writes

Periodic write triggers (PendingTraceBuffer)

The PendingTraceBuffer is an existing thread that can trigger partial writes. It listens to a queue where PendingTraces that meet certain conditions are inserted.
This makes it the perfect place to track long running traces and trigger periodic traces.

A 1 second periodic wakeup is added to the PendingTraceBuffer thread. On wakeup runningTraces are re-evaluated: a write can be triggered, and traces already completed are cleaned up.

The runningTraces are stored in a dedicated array LongRunningTracesTracker with a few helpers.

A LongRunningState has been added to the PendingTrace to ensure that the changes of state happen only once. Exemples

  • PendingTrace is sent only once to the PendingTraceBuffer to be tracked
  • priority is evaluated only once
  • the LongRunningTracker does not contain duplicate PendingTrace
PendingTrace state changes

                                  priority <= 0
                    UNDEFINED  --------------------------> NOT_TRACKED
                         |
                         |   priority > 0
                         v
                    TO_TRACK 
                         |
                         |   added to the LongRunningTraceTracker by PendingTraceBuffer
                         v
                    TRACKED 
                         |
                         |   agent feature enabled AND trace is older than flush period
                         v
                    WRITE_RUNNING   //writes will now write running spans
                         |
                         |   trace longer then 12h  
                         v
                    EXPIRED
                      

Encode new tags on spans

The 4 following constraints made this particularly challenging:

  • a public CoreSpan interface is passed through tracer write logic and we must not add methods on the public interface
  • span.Duration == 0 is used in the tracer to know if a span is finished
  • long running span tags should be added in the transport layer
  • spans should not be cloned

The proposed solution to meet the constraint is:

  1. add a version on DDSpan and pass it through the MetadataConsumer. The MetadataConsumer is used in the v04 and v05 encoders to set tags.
  2. fetch the write time from the PendingTrace if duration == 0 at write time. This unfortunately requires to cast CoreSpan to DDSpan. Check getDurationNano(CoreSpan<?> span. Given that the flushed running spans volume is low, this is acceptable.

Avoid computing stats

A helper shouldComputeMetrics is added and running spans are filtered out by checking the span duratio. Note span.isFinished() is not available on the CoresSpan public interface, that's why span.getDuration() == 0 is used.

Comment thread dd-trace-core/src/main/java/datadog/trace/core/PendingTrace.java Outdated

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

What are the rules for longRunningVersion? I'd prefer to not have to keep tracking of a version per span if possible.

Could we simply have a version per PendingTrace instead?
Is the version on a span supposed to be consecutive?
Would it be okay to just have a continually increasingly version number that can skip numbers for a given span?

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

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

It's okay to have an increasing version number that skip numbers on a span, I've updated it to use flush time in milliseconds.
Unfortunately we still need to keep track of it at the span level to know if the span was a long running one or not

Comment thread dd-trace-core/src/main/java/datadog/trace/core/CoreSpan.java Outdated
Comment thread dd-trace-core/src/main/java/datadog/trace/core/DDSpan.java Outdated
Comment thread dd-trace-core/src/main/java/datadog/trace/core/DDSpan.java Outdated

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

I don't see why we needed a separate tracker. Please explain why this is needed.

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

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

I replaced it with using the pendingTraceBuffer. I added a separate tracker to allow continuous eviction of completed pendingTrace. By using the pendingTraceBuffer queue and sleeps, pendingTraces that are already flushed are taking the place of long running traces.
With the sleep time of 70ms, and the 4k slots in the array, it takes 286s to pass through the complete queue.

Comment thread dd-trace-core/src/main/java/datadog/trace/core/PendingTrace.java Outdated
Comment thread dd-trace-core/src/main/java/datadog/trace/core/PendingTrace.java Outdated

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

The casting here is rather ugly. I see that was already here, but it is making this hard to follow.

Comment thread dd-trace-core/src/main/java/datadog/trace/core/PendingTraceBuffer.java Outdated
Comment thread dd-trace-core/src/main/java/datadog/trace/core/PendingTrace.java Outdated
Comment thread dd-trace-core/src/main/java/datadog/trace/core/PendingTraceBuffer.java Outdated
@raphaelgavache
raphaelgavache force-pushed the raphael/long_running_spans_v3 branch 2 times, most recently from 42fca6d to 0bace59 Compare April 27, 2023 22:42
@raphaelgavache raphaelgavache changed the title [draft] Long running spans 2nd approach prototype Long running spans - pending trace track all spans approach Apr 27, 2023
@pr-commenter

pr-commenter Bot commented Apr 27, 2023

Copy link
Copy Markdown

Benchmarks

Parameters

Baseline Candidate
commit 1.15.0-SNAPSHOT~0300405b48 1.15.0-SNAPSHOT~aee6c5ccec
config baseline candidate
See matching parameters
Baseline Candidate
module Agent Agent
parent None None

Summary

Found 0 performance improvements and 0 performance regressions! Performance is the same for 22 cases.

See unchanged results
scenario Δ mean execution_time
scenario:Startup-base-Agent same
scenario:Startup-base-Agent.start same
scenario:Startup-base-BytebuddyAgent same
scenario:Startup-base-GlobalTracer same
scenario:Startup-base-AppSec same
scenario:Startup-base-Remote Config same
scenario:Startup-base-Telemetry same
scenario:Startup-iast-Agent same
scenario:Startup-iast-Agent.start same
scenario:Startup-iast-BytebuddyAgent same
scenario:Startup-iast-GlobalTracer same
scenario:Startup-iast-AppSec same
scenario:Startup-iast-IAST same
scenario:Startup-iast-Remote Config same
scenario:Startup-iast-Telemetry same
scenario:Startup-waf-Agent same
scenario:Startup-waf-Agent.start same
scenario:Startup-waf-BytebuddyAgent same
scenario:Startup-waf-GlobalTracer same
scenario:Startup-waf-AppSec same
scenario:Startup-waf-Remote Config same
scenario:Startup-waf-Telemetry same

@raphaelgavache
raphaelgavache force-pushed the raphael/long_running_spans_v3 branch from 0bace59 to 1e73c47 Compare April 27, 2023 23:19
@raphaelgavache
raphaelgavache force-pushed the raphael/long_running_spans_v3 branch from 1660862 to a7e2155 Compare April 28, 2023 09:14
public abstract class PendingTraceBuffer implements AutoCloseable {
private static final int BUFFER_SIZE = 1 << 12; // 4096

public boolean runningSpansEnabled() {

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

longRunningSpansEnabled() ?


if (pendingTrace == null) {
continue;
}

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

This check can be moved into the if (runningSpansEnabled()) { block as queue.take() guarantees that pendingTrace will be non-null (or the call gets interrupted, in which case an exception will be raised breaking out of the while loop)

}

public long getLongRunningFlushInterval() {
return longRunningTraceFlushInterval;

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

could you update the field / method names to be consistent - ie. foo and getFoo(), bar and isBar() - thanks

this.longRunningTraceFlushInterval =
configProvider.getLong(
TracerConfig.TRACE_LONG_RUNNING_FLUSH_INTERVAL,
ConfigDefaults.DEFAULT_LONG_RUNNING_TRACE_FLUSH_INTERVAL);

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

could you also make these consistent, ie. name the default as DEFAULT_XYZ for a flag called XYZ

&& (longRunningTraceFlushInterval < 20 || longRunningTraceFlushInterval > 450)) {
log.warn(
"Provided long running trace flush interval of {} seconds. It should be between 20 seconds and 7.5 minutes. T"
+ "he feature is disabled.",

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

splitting the string between the sentences is more readable, rather than splitting mid-word

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Also would it be better to move the flush interval inside the allowed range and keep it enabled? (Can still warn that the original value was outside the accepted range and has been adjusted.)

1 * healthMetrics.onCreateTrace()
}

def "don't write running spans"() {

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

would be useful to have test names that describe the expectation, because currently the names contradict each other (at the moment it's like having Test Foo and Test Not Foo)

CountersFactory.createFixedSizeStripedCounter(8);
private final FixedSizeStripedLongCounter clientSpansWithoutContext =
CountersFactory.createFixedSizeStripedCounter(8);
private final FixedSizeStripedLongCounter longRunningTracesWrite =

@mcculls mcculls May 11, 2023

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

longRunningTracesWrites to match the other new metric names?

EDIT: looking at the actual metric name, this is ok - it's the other fields that need renaming

private final FixedSizeStripedLongCounter longRunningTracesMisses =
CountersFactory.createFixedSizeStripedCounter(8);
private final FixedSizeStripedLongCounter longRunningTracesExpires =
CountersFactory.createFixedSizeStripedCounter(8);

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

should be longRunningTracesDropped and longRunningTracesExpired to match the actual metrics names

}

@Override
public void onLongRunningUpdate(final int missedAdd, final int writes, final int expires) {

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

dropped, write, expired to match the actual metrics names?

public void onFailedSend(
final int traceCount, final int sizeInBytes, final RemoteApi.Response response) {}

public void onLongRunningUpdate(final int missedAdd, final int writes, final int expires) {}

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

dropped, write, expired to match the actual metrics names?

}

public boolean isLongRunningTracesEnabled() {
return longRunningTraceEnabled;

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Consider adding this flag to the toString() method as it will help support identify users that have this enabled

LongRunningTracesTracker.TO_TRACK, LongRunningTracesTracker.NOT_TRACKED);
}

public static long getDurationNano(CoreSpan<?> span) {

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

At the moment this method is only called in the trace mappers - could we add a comment explaining when this should be used instead of span.getDurationNano() ?

private final List<PendingTrace> traceArray = new ArrayList<>(1 << 4);
private int missedAdd = 0;
private int writes = 0;
private int expires = 0;

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

dropped, write, expired to match actual metric names for consistency?

}

private void addTrace(PendingTrace trace) {
if (trace == null || trace.empty()) {

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

AFAICT this is only called by add which guarantees it will only pass non-null traces so the null check can be removed here

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

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

yes, it passes the null insertion test once removed

boolean runningSpanSeen = false;
long firstRunningSpanID = 0;
long nowNano = getCurrentTimeNano();
setLastWriteTime(nowNano);

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

previously we just added the finished spans to the trace - now we also get the current time and write it to a volatile even when long-running traces are not enabled

is there a way we can keep the simpler loop (and skip the time check and volatile write) when we know we aren't capturing long-running traces?

@raphaelgavache raphaelgavache May 12, 2023

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

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

Nice catch, this was an easy one to removed and it simplified PendingTraceBuffer tests

@mcculls mcculls left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Mostly comments about naming consistency, plus a question whether we can keep the simpler enqueuing of finished spans when long-running traces are not enabled - but no blockers

+ cwsTlsRefresh
+ ", longRunningTracesEnabled="
+ longRunningTraceEnabled
+ ", longRunningTraceFlushInterval="

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Mixing traces and trace..

@raphaelgavache
raphaelgavache merged commit f1d7596 into master May 15, 2023
@raphaelgavache
raphaelgavache deleted the raphael/long_running_spans_v3 branch May 15, 2023 14:48
@github-actions github-actions Bot added this to the 1.15.0 milestone May 15, 2023
@raphaelgavache raphaelgavache added inst: apache spark Apache Spark instrumentation tag: experimental Experimental changes tag: no release notes Changes to exclude from release notes and removed inst: apache spark Apache Spark instrumentation labels May 16, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

tag: experimental Experimental changes tag: no release notes Changes to exclude from release notes

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants