in src/Elastic.Apm/Model/Span.cs [415:599]
public void End()
{
// If the outcome is still unknown and it was not specifically set to unknown, then it's success
if (Outcome == Outcome.Unknown && !_outcomeChangedThroughApi)
Outcome = Outcome.Success;
var formattedTimestamp = _logger.IsEnabled(LogLevel.Trace) ? TimeUtils.FormatTimestampForLog(Timestamp) : string.Empty;
if (Duration.HasValue)
{
_logger?.Trace()?.Log("Ended {Span} (with Duration already set)." +
" Start time: {Time} (as timestamp: {Timestamp}), Duration: {Duration}ms",
this, formattedTimestamp, Timestamp, Duration);
if (_parentSpan != null)
_parentSpan?._childDurationTimer.OnChildEnd((long)(Timestamp + Duration.Value * 1000));
else
_enclosingTransaction.ChildDurationTimer.OnChildEnd((long)(Timestamp + Duration.Value * 1000));
_childDurationTimer.OnSpanEnd((long)(Timestamp + Duration.Value * 1000));
}
else
{
Assertion.IfEnabled?.That(!_isEnded,
$"Span's Duration doesn't have value even though {nameof(End)} method was already called." +
$" It contradicts the invariant enforced by {nameof(End)} method - Duration should have value when {nameof(End)} method exits" +
$" and {nameof(_isEnded)} field is set to true only when {nameof(End)} method exits." +
$" Context: this: {this}; {nameof(_isEnded)}: {_isEnded}");
var endTimestamp = TimeUtils.TimestampNow();
Duration = TimeUtils.DurationBetweenTimestamps(Timestamp, endTimestamp);
if (_parentSpan != null)
_parentSpan?._childDurationTimer.OnChildEnd(endTimestamp);
else
_enclosingTransaction.ChildDurationTimer.OnChildEnd(endTimestamp);
_childDurationTimer.OnSpanEnd(endTimestamp);
_logger?.Trace()?.Log("Ended {Span}. Start time: {Time} (as timestamp: {Timestamp})," +
" End time: {Time} (as timestamp: {Timestamp}), Duration: {Duration}ms",
this, formattedTimestamp, Timestamp,
TimeUtils.FormatTimestampForLog(endTimestamp), endTimestamp, Duration);
}
var isFirstEndCall = !_isEnded;
_isEnded = true;
var handler = Ended;
handler?.Invoke(this, EventArgs.Empty);
Ended = null;
if (_enclosingTransaction.SpanTimings.ContainsKey(new SpanTimerKey(Type, Subtype)))
_enclosingTransaction.SpanTimings[new SpanTimerKey(Type, Subtype)].IncrementTimer(SelfDuration);
else
_enclosingTransaction.SpanTimings.TryAdd(new SpanTimerKey(Type, Subtype), new SpanTimer(SelfDuration));
try
{
DeduceServiceTarget();
}
catch (Exception e)
{
_logger?.Warning()?.LogException(e, "Failed deducing destination fields for span.");
}
if (_isDropped && _context.IsValueCreated)
{
_enclosingTransaction.UpdateDroppedSpanStats(Context?.Service?.Target?.Type, Context?.Service?.Target?.Name,
Context?.Destination?.Service?.Resource, _outcome, Duration!.Value);
}
else if (_isDropped && !_context.IsValueCreated && DroppedSpanStatCache.HasValue)
{
_enclosingTransaction.UpdateDroppedSpanStats(DroppedSpanStatCache.Value.Target.Type, DroppedSpanStatCache.Value.Target.Name,
DroppedSpanStatCache.Value.DestinationServiceResource, _outcome, Duration!.Value);
}
if (ShouldBeSentToApmServer && isFirstEndCall)
{
// If we recorded the stack trace on start, but the duration of the span does not require
// inclusion of the stack trace, remove it.
if (RawStackTrace is not null && !DurationRequiresCaptureStackTrace())
RawStackTrace = null;
// Spans are sent only for sampled transactions so it's only worth capturing stack trace for sampled spans
// ReSharper disable once CompareOfFloatsByEqualityOperator
if (IsCaptureStackTraceOnEndEnabled())
RawStackTrace = new StackTrace(true);
var buffered = _parentSpan?._compressionBuffer ?? _enclosingTransaction.CompressionBuffer;
if (Configuration.SpanCompressionEnabled && _apmServerInfo?.Version >= new ElasticVersion(8, 0, 0, string.Empty))
{
if (!IsCompressionEligible() || _parentSpan is { _isEnded: true })
{
if (buffered != null)
{
QueueSpan(buffered);
if (_parentSpan != null)
_parentSpan._compressionBuffer = null;
_enclosingTransaction.CompressionBuffer = null;
}
//If this is a span which has buffered children, we send the composite.
if (_compressionBuffer != null)
QueueSpan(_compressionBuffer);
QueueSpan(this);
if (isFirstEndCall)
_currentExecutionSegmentsContainer.CurrentSpan = _parentSpan;
return;
}
if (buffered == null)
{
SetThisToParentsBuffer();
if (isFirstEndCall)
_currentExecutionSegmentsContainer.CurrentSpan = _parentSpan;
return;
}
if (!buffered.TryToCompress(this))
{
QueueSpan(buffered);
SetThisToParentsBuffer();
if (isFirstEndCall)
_currentExecutionSegmentsContainer.CurrentSpan = _parentSpan;
}
}
else
QueueSpan(this);
}
if (isFirstEndCall)
_currentExecutionSegmentsContainer.CurrentSpan = _parentSpan;
void QueueSpan(Span span)
{
if (span.Composite != null)
{
var endTimestamp = TimeUtils.TimestampNow();
span.Duration = TimeUtils.DurationBetweenTimestamps(span.Timestamp, endTimestamp);
}
if (span.Discardable)
{
if (span.Composite != null && span.Duration < span.Configuration.ExitSpanMinDuration)
{
switch (_context.IsValueCreated)
{
case true:
_enclosingTransaction.UpdateDroppedSpanStats(Context?.Service?.Target?.Type, Context?.Service?.Target?.Name,
Context?.Destination?.Service?.Resource, _outcome, Duration!.Value);
break;
case false when DroppedSpanStatCache.HasValue:
_enclosingTransaction.UpdateDroppedSpanStats(DroppedSpanStatCache.Value.Target.Type,
DroppedSpanStatCache.Value.Target.Name,
DroppedSpanStatCache.Value.DestinationServiceResource, _outcome, Duration!.Value);
break;
}
_logger?.Trace()?.Log("Dropping fast exit span on composite span. Composite duration: {duration}", span.Composite.Sum);
return;
}
if (span.Duration < span.Configuration.ExitSpanMinDuration)
{
switch (_context.IsValueCreated)
{
case true:
_enclosingTransaction.UpdateDroppedSpanStats(Context?.Service?.Target?.Type, Context?.Service?.Target?.Name,
Context?.Destination?.Service?.Resource, _outcome, Duration!.Value);
break;
case false when DroppedSpanStatCache.HasValue:
_enclosingTransaction.UpdateDroppedSpanStats(DroppedSpanStatCache.Value.Target.Type,
DroppedSpanStatCache.Value.Target.Name,
DroppedSpanStatCache.Value.DestinationServiceResource, _outcome, Duration!.Value);
break;
}
_logger?.Trace()?.Log("Dropping fast exit span. Duration: {duration}", span.Duration);
return;
}
}
_payloadSender.QueueSpan(span);
}
}