Long running spans - pending trace track all spans approach#4966
Conversation
There was a problem hiding this comment.
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?
There was a problem hiding this comment.
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
There was a problem hiding this comment.
I don't see why we needed a separate tracker. Please explain why this is needed.
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
The casting here is rather ugly. I see that was already here, but it is making this hard to follow.
42fca6d to
0bace59
Compare
BenchmarksParameters
See matching parameters
SummaryFound 0 performance improvements and 0 performance regressions! Performance is the same for 22 cases. See unchanged results
|
0bace59 to
1e73c47
Compare
1660862 to
a7e2155
Compare
| public abstract class PendingTraceBuffer implements AutoCloseable { | ||
| private static final int BUFFER_SIZE = 1 << 12; // 4096 | ||
|
|
||
| public boolean runningSpansEnabled() { |
There was a problem hiding this comment.
longRunningSpansEnabled() ?
|
|
||
| if (pendingTrace == null) { | ||
| continue; | ||
| } |
There was a problem hiding this comment.
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; |
There was a problem hiding this comment.
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); |
There was a problem hiding this comment.
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.", |
There was a problem hiding this comment.
splitting the string between the sentences is more readable, rather than splitting mid-word
There was a problem hiding this comment.
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"() { |
There was a problem hiding this comment.
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 = |
There was a problem hiding this comment.
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); |
There was a problem hiding this comment.
should be longRunningTracesDropped and longRunningTracesExpired to match the actual metrics names
| } | ||
|
|
||
| @Override | ||
| public void onLongRunningUpdate(final int missedAdd, final int writes, final int expires) { |
There was a problem hiding this comment.
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) {} |
There was a problem hiding this comment.
dropped, write, expired to match the actual metrics names?
| } | ||
|
|
||
| public boolean isLongRunningTracesEnabled() { | ||
| return longRunningTraceEnabled; |
There was a problem hiding this comment.
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) { |
There was a problem hiding this comment.
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; |
There was a problem hiding this comment.
dropped, write, expired to match actual metric names for consistency?
| } | ||
|
|
||
| private void addTrace(PendingTrace trace) { | ||
| if (trace == null || trace.empty()) { |
There was a problem hiding this comment.
AFAICT this is only called by add which guarantees it will only pass non-null traces so the null check can be removed here
There was a problem hiding this comment.
yes, it passes the null insertion test once removed
| boolean runningSpanSeen = false; | ||
| long firstRunningSpanID = 0; | ||
| long nowNano = getCurrentTimeNano(); | ||
| setLastWriteTime(nowNano); |
There was a problem hiding this comment.
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?
There was a problem hiding this comment.
Nice catch, this was an easy one to removed and it simplified PendingTraceBuffer tests
mcculls
left a comment
There was a problem hiding this comment.
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=" |
There was a problem hiding this comment.
Mixing traces and trace..
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
Protocol
Configuration
Implementation overhead
Feature disabled
pendingTraceBuffer.runningSpansEnabled()Feature enabled
all traces
other
PendingTraceBuffer is waked up every 1s
Breakdown of the required:
Track running spans (PendingTrace)
Writes are triggered by PendingTraces and the PendingTraceBuffer. They only point to completed spans.
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.spanslist.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
LongRunningTracesTrackerwith a few helpers.A LongRunningState has been added to the PendingTrace to ensure that the changes of state happen only once. Exemples
Encode new tags on spans
The 4 following constraints made this particularly challenging:
CoreSpaninterface is passed through tracer write logic and we must not add methods on the public interfaceThe proposed solution to meet the constraint is:
MetadataConsumer. The MetadataConsumer is used in the v04 and v05 encoders to set tags.getDurationNano(CoreSpan<?> span. Given that the flushed running spans volume is low, this is acceptable.Avoid computing stats
A helper
shouldComputeMetricsis added and running spans are filtered out by checking the span duratio. Notespan.isFinished()is not available on the CoresSpan public interface, that's whyspan.getDuration() == 0is used.