diff --git a/src/Elastic.Apm/Api/SpanCount.cs b/src/Elastic.Apm/Api/SpanCount.cs index af53b4167..a1299ab3c 100644 --- a/src/Elastic.Apm/Api/SpanCount.cs +++ b/src/Elastic.Apm/Api/SpanCount.cs @@ -29,6 +29,17 @@ public class SpanCount internal void IncrementDropped() => Interlocked.Increment(ref _dropped); + /// + /// Moves spans that were started but then discarded instead of being reported + /// (see exit_span_min_duration) from to , so that + /// keeps reflecting the number of spans that are actually recorded. + /// + internal void MoveStartedToDropped(int count) + { + Interlocked.Add(ref _started, -count); + Interlocked.Add(ref _dropped, count); + } + internal int IncrementTotal() => Interlocked.Increment(ref _total); public override string ToString() => diff --git a/src/Elastic.Apm/Instrumentations/SqlClient/SqlClientDiagnosticListener.cs b/src/Elastic.Apm/Instrumentations/SqlClient/SqlClientDiagnosticListener.cs index 882c08d17..8d1b4d11f 100644 --- a/src/Elastic.Apm/Instrumentations/SqlClient/SqlClientDiagnosticListener.cs +++ b/src/Elastic.Apm/Instrumentations/SqlClient/SqlClientDiagnosticListener.cs @@ -45,13 +45,6 @@ internal SqlClientDiagnosticListener(IApmAgent apmAgent, PendingSpanStore spanSt // prefix - Microsoft.Data.SqlClient. or System.Data.SqlClient. protected override void HandleOnNext(KeyValuePair value) { - // check for competing instrumentation - if (ApmAgent.Tracer.CurrentSpan is Span span) - { - if (span.InstrumentationFlag == InstrumentationFlag.EfCore || span.InstrumentationFlag == InstrumentationFlag.EfClassic) - return; - } - if (!value.Key.StartsWith("Microsoft.Data.SqlClient.") && !value.Key.StartsWith("System.Data.SqlClient.")) return; @@ -76,6 +69,15 @@ private void HandleStartCommand(object payloadData, PropertyFetcherSet propertyF if (propertyFetcherSet.StartCorrelationId.Fetch(payloadData) is Guid operationId && propertyFetcherSet.StartCommand.Fetch(payloadData) is IDbCommand dbCommand) { + // The command is already traced by a competing instrumentation (Entity Framework or the profiler's ADO.NET + // integrations), so don't start a nested span for the very same command. The matching After/Error event is + // still handled and finds no pending span to end. + if (CompetingInstrumentation.IsCommandTracedByOtherModule(ApmAgent, dbCommand)) + { + Logger.Trace()?.Log("WriteCommandBefore event is skipped, the command is traced by a competing instrumentation."); + return; + } + var span = DbSpanCommon.StartSpan(ApmAgent, dbCommand, InstrumentationFlag.SqlClient, ApiConstants.SubtypeMssql, makeCurrent: false); _spans.Add(operationId, span, GetMaxSpanAge(dbCommand)); diff --git a/src/Elastic.Apm/Instrumentations/SqlClient/SqlEventListener.cs b/src/Elastic.Apm/Instrumentations/SqlClient/SqlEventListener.cs index fa3cf9616..8c0a96706 100644 --- a/src/Elastic.Apm/Instrumentations/SqlClient/SqlEventListener.cs +++ b/src/Elastic.Apm/Instrumentations/SqlClient/SqlEventListener.cs @@ -50,28 +50,43 @@ protected override void OnEventWritten(EventWrittenEventArgs eventData) if (eventData?.Payload == null) return; - // Check for competing instrumentation - if (_apmAgent.TracerInternal.CurrentSpan is Span span) - { - if (span.InstrumentationFlag == InstrumentationFlag.EfCore || span.InstrumentationFlag == InstrumentationFlag.EfClassic) - return; - } + HandleEvent(eventData.EventId, eventData.Payload); + } + + /// + /// Handles a SqlClient EventSource event. Separated from so that it can be exercised + /// without an . + /// + internal void HandleEvent(int eventId, IReadOnlyList payload) + { + if (payload == null) + return; try { - switch (eventData.EventId) + switch (eventId) { case BeginExecuteEventId: - ProcessBeginExecute(eventData.Payload); + // The command is already traced by a competing instrumentation (Entity Framework or the profiler's + // ADO.NET integrations), so don't start a nested span for the very same command. The matching + // EndExecute event is still handled below and finds nothing to end. Unlike the diagnostic listener + // this event source carries no command object, so the competing span cannot be matched to the command. + if (CompetingInstrumentation.IsCommandTracedByOtherModule(_apmAgent)) + { + _logger?.Trace()?.Log("BeginExecute event is skipped, the command is traced by a competing instrumentation."); + return; + } + + ProcessBeginExecute(payload); break; case EndExecuteId: - ProcessEndExecute(eventData.Payload); + ProcessEndExecute(payload); break; } } catch (Exception ex) { - _logger?.Error()?.LogException(ex, "Error has occurred during handle event from SqlClient. EventData: {EventData}", eventData); + _logger?.Error()?.LogException(ex, "Error has occurred during handle event from SqlClient. EventId: {EventId}", eventId); } } @@ -101,8 +116,10 @@ private void ProcessBeginExecute(IReadOnlyList payload) ? commandText.Replace(Environment.NewLine, "") : database; + // A SQL command is an exit span that never has legitimate children, so it isn't made the current span. This also + // guarantees that a current span flagged SqlClient belongs to a competing instrumentation, never to this listener. var span = ExecutionSegmentCommon.StartSpanOnCurrentExecutionSegment(_apmAgent, spanName, ApiConstants.TypeDb, ApiConstants.SubtypeMssql, - InstrumentationFlag.SqlClient, isExitSpan: true); + InstrumentationFlag.SqlClient, isExitSpan: true, makeCurrent: false); if (span == null) return; @@ -148,8 +165,10 @@ private void ProcessEndExecute(IReadOnlyList payload) if (!_processingSpans.TryRemove(id, out var item)) { - _logger?.Warning() - ?.Log("Failed capturing sql statement (failed to remove from ProcessingSpans)."); + // Expected whenever BeginExecute did not start a span: no current transaction, or the command is traced by a + // competing instrumentation. + _logger?.Debug() + ?.Log("No span to end for EndExecute event. Id: {Id}. The command was started outside of a transaction or is traced by a competing instrumentation.", id); return; } diff --git a/src/Elastic.Apm/Model/CompetingInstrumentation.cs b/src/Elastic.Apm/Model/CompetingInstrumentation.cs new file mode 100644 index 000000000..bab973a21 --- /dev/null +++ b/src/Elastic.Apm/Model/CompetingInstrumentation.cs @@ -0,0 +1,50 @@ +// Licensed to Elasticsearch B.V under one or more agreements. +// Elasticsearch B.V licenses this file to you under the Apache 2.0 License. +// See the LICENSE file in the project root for more information + +using System.Data; + +namespace Elastic.Apm.Model +{ + /// + /// Detects whether the database command an instrumentation module is about to trace is already traced by a competing + /// module. Competing modules keep their span current while the command executes, so the current span identifies them. + /// + internal static class CompetingInstrumentation + { + /// + /// Entity Framework Core and Entity Framework 6, which trace the command they hand to ADO.NET. + /// + private const InstrumentationFlag EntityFramework = InstrumentationFlag.EfCore | InstrumentationFlag.EfClassic; + + /// + /// The profiler's ADO.NET CallTarget integrations, which flag their spans as + /// (SqlCommand) or (DbCommand). + /// Neither of the SqlClient listeners makes its own spans current, so a current span carrying one of these flags + /// always belongs to the profiler. + /// + private const InstrumentationFlag AdoNetProfiler = InstrumentationFlag.SqlClient | InstrumentationFlag.AdoNet; + + /// + /// For the SqlClient listeners: both Entity Framework and the profiler trace the very same command. + /// + internal static bool IsCommandTracedByOtherModule(IApmAgent agent, IDbCommand command = null) => + IsCommandTracedBy(agent, EntityFramework | AdoNetProfiler, command); + + /// + /// For the Entity Framework modules: the profiler's ADO.NET integrations trace the very same command. + /// + internal static bool IsCommandTracedByAdoNetModule(IApmAgent agent, IDbCommand command = null) => + IsCommandTracedBy(agent, AdoNetProfiler, command); + + private static bool IsCommandTracedBy(IApmAgent agent, InstrumentationFlag modules, IDbCommand command) + { + if (agent?.Tracer.CurrentSpan is not Span span || (span.InstrumentationFlag & modules) == 0) + return false; + + // Where the command is available, require the competing span to describe this very command, as the profiler + // itself does in DbSpanFactory. A competing span for a different command must not suppress this one. + return command is null || span.Name == DbSpanCommon.GetDbSpanName(command); + } + } +} diff --git a/src/Elastic.Apm/Model/DroppedSpanStats.cs b/src/Elastic.Apm/Model/DroppedSpanStats.cs index 63121a0be..30b949a14 100644 --- a/src/Elastic.Apm/Model/DroppedSpanStats.cs +++ b/src/Elastic.Apm/Model/DroppedSpanStats.cs @@ -16,10 +16,10 @@ namespace Elastic.Apm.Model internal class DroppedSpanStats { public DroppedSpanStats(string serviceTargetType, string serviceTargetName, string destinationServiceResource, Outcome outcome, - double durationSumUs + double durationSumUs, int count ) { - Duration = new DroppedSpanDuration { Count = 1, Sum = new DroppedSpanDuration.DroppedSpanDurationSum { UsRaw = durationSumUs } }; + Duration = new DroppedSpanDuration { Count = count, Sum = new DroppedSpanDuration.DroppedSpanDurationSum { UsRaw = durationSumUs } }; ServiceTargetType = serviceTargetType; ServiceTargetName = serviceTargetName; DestinationServiceResource = destinationServiceResource; @@ -73,7 +73,7 @@ internal class DroppedSpanDurationSum public double UsRaw { get; set; } // As `duration.sum.us` is an integer in the intake API we round during serialization. - public int Us => Convert.ToInt32(UsRaw); + public long Us => Convert.ToInt64(UsRaw); } } } diff --git a/src/Elastic.Apm/Model/Span.cs b/src/Elastic.Apm/Model/Span.cs index c681605b4..6cfce53fe 100644 --- a/src/Elastic.Apm/Model/Span.cs +++ b/src/Elastic.Apm/Model/Span.cs @@ -48,7 +48,23 @@ internal class Span : ISpan // which points to this span. private bool _hasPropagatedContext; - private bool Discardable => IsExitSpan && !_hasPropagatedContext && Outcome == Outcome.Success && Configuration.SpanCompressionEnabled; + /// + /// Whether a child span that can reach APM Server was started under this span. Such a span must keep its identity, + /// otherwise the child it is the parent of is orphaned: it is neither discarded for being a fast exit span nor + /// compressed into a sibling's composite. Children that can never be reported do not set this, so that a huge trace + /// whose spans are dropped by transaction_max_spans does not also lose compression. + /// + private volatile bool _hasChildren; + + private bool Discardable => IsExitSpan && !_hasPropagatedContext && !_hasChildren + && Outcome == Outcome.Success && Configuration.SpanCompressionEnabled; + + private static readonly ElasticVersion ServerVersion80 = new(8, 0, 0, string.Empty); + + /// + /// Span compression is only applied when it is enabled and APM Server understands composite spans (8.0 and later). + /// + private bool IsSpanCompressionActive => Configuration.SpanCompressionEnabled && _apmServerInfo?.Version >= ServerVersion80; [JsonConstructor] // ReSharper disable once UnusedMember.Local - this is meant for deserialization @@ -131,6 +147,10 @@ public Span(string name, else SampleRate = 0; + // Only now is it known whether this child can reach APM Server, see the field for why that matters. + if (_parentSpan != null && ShouldBeSentToApmServer) + _parentSpan._hasChildren = true; + CheckAndCaptureBaggage(); if (makeCurrent) @@ -505,16 +525,12 @@ public void End() _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 (_isDropped) + RecordDroppedSpanStats(); + + // Span compression, see https://github.com/elastic/apm/blob/main/specs/agents/handling-huge-traces/tracing-spans-compress.md + // A span that ends must first report the child span it has buffered, if any (spec: onEnd). + ReportBufferedChild(); if (ShouldBeSentToApmServer) { @@ -528,95 +544,13 @@ public void End() 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); - _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); - RestoreCurrentSpan(); - return; - } - if (buffered == null) - { - SetThisToParentsBuffer(); - RestoreCurrentSpan(); - return; - } - - if (!buffered.TryToCompress(this)) - { - QueueSpan(buffered); - SetThisToParentsBuffer(); - RestoreCurrentSpan(); - } - } + if (IsSpanCompressionActive) + EndWithCompression(); else - QueueSpan(this); + Report(); } RestoreCurrentSpan(); - - 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); - } } private void RestoreCurrentSpan() @@ -644,9 +578,15 @@ internal void Abandon() _childDurationTimer.OnSpanEnd(TimeUtils.TimestampNow()); Ended = null; + ReportBufferedChild(); RestoreCurrentSpan(); } + /// + /// Merges into this span, which its parent has buffered, turning this span into a + /// composite one (spec: tryToCompress). Only loses its identity, so only it has to be + /// compression eligible; this span keeps its own id and may therefore have children of its own. + /// private bool TryToCompress(Span sibling) { var isAlreadyComposite = Composite != null; @@ -664,6 +604,12 @@ private bool TryToCompress(Span sibling) Composite.Count++; Composite.Sum += sibling.Duration!.Value; + + // The composite span covers the period from the start of the first compressed span to the end of the last one + // (spec: gross duration), so extend the duration when the sibling ended after this span did. + var grossDuration = TimeUtils.DurationBetweenTimestamps(Timestamp, sibling.Timestamp) + sibling.Duration.Value; + if (grossDuration > Duration) + Duration = grossDuration; return true; } @@ -730,15 +676,126 @@ internal void InsertSpanLinkInternal(IEnumerable links) Links = new List(newList); } - private void SetThisToParentsBuffer() + /// + /// Implements the parent's side of the span compression algorithm (spec: onChildEnd) for this ending span: it is either + /// reported right away, becomes the buffered span of its parent, or is merged into the span its parent has buffered. + /// The parent is the direct parent only. A span whose parent span has nothing buffered must never fall back to the + /// transaction's buffer, since that buffer holds a sibling of the parent, not a sibling of this span. + /// The decision is taken under the transaction's compression lock so that siblings ending concurrently can neither + /// report the same buffered span twice nor overwrite each other's buffered span. + /// + private void EndWithCompression() + { + Span previouslyBuffered = null; + var reportThis = false; + + lock (_enclosingTransaction.CompressionBufferLock) + { + var parentEnded = _parentSpan?.IsEnded ?? _enclosingTransaction.IsEnded; + var buffered = GetParentCompressionBuffer(); + + if (!IsCompressionEligible() || parentEnded) + { + // Neither this span nor the span buffered so far can take part in any further compression. + previouslyBuffered = buffered; + SetParentCompressionBuffer(null); + reportThis = true; + } + else if (buffered == null) + SetParentCompressionBuffer(this); + else if (!buffered.TryToCompress(this)) + { + previouslyBuffered = buffered; + SetParentCompressionBuffer(this); + } + // otherwise this span has been merged into the buffered span and is not reported on its own + } + + previouslyBuffered?.Report(); + + if (reportThis) + Report(); + } + + /// + /// Reports the child span this span has buffered for compression, if any. A buffered span is reported once its parent + /// ends (spec: onEnd); this must also happen when the parent is explicitly abandoned. + /// + private void ReportBufferedChild() + { + Span buffered; + lock (_enclosingTransaction.CompressionBufferLock) + { + buffered = _compressionBuffer; + _compressionBuffer = null; + } + + buffered?.Report(); + } + + private Span GetParentCompressionBuffer() => + _parentSpan != null ? _parentSpan._compressionBuffer : _enclosingTransaction.CompressionBuffer; + + private void SetParentCompressionBuffer(Span span) { if (_parentSpan != null) - _parentSpan._compressionBuffer = this; + _parentSpan._compressionBuffer = span; else - _enclosingTransaction.CompressionBuffer = this; + _enclosingTransaction.CompressionBuffer = span; } - public bool IsCompressionEligible() => IsExitSpan && !_hasPropagatedContext && Outcome is Outcome.Success or Outcome.Unknown; + /// + /// Queues this span to be sent to APM Server, unless it is a discardable exit span shorter than exit_span_min_duration, + /// in which case it is dropped and only its dropped span statistics are recorded. Every span, including a composite span + /// and a span flushed from a compression buffer, is reported through this method. + /// + internal void Report() + { + if (Discardable && Duration < Configuration.ExitSpanMinDuration) + { + RecordDroppedSpanStats(); + + // Every span this one stands for was counted as started when it began, and none of them is reported + // (spec: dropping fast exit spans increments span_count.dropped). + _enclosingTransaction.SpanCount.MoveStartedToDropped(Composite?.Count ?? 1); + + if (Composite != null) + { + _logger?.Trace()?.Log("Dropping fast composite span. Duration: {Duration}ms, sum of compressed spans: {Sum}ms", + Duration, Composite.Sum); + } + else + _logger?.Trace()?.Log("Dropping fast exit span. Duration: {Duration}ms", Duration); + + return; + } + + _payloadSender.QueueSpan(this); + } + + private void RecordDroppedSpanStats() + { + var count = Composite?.Count ?? 1; + var duration = Composite?.Sum ?? Duration!.Value; + if (_context.IsValueCreated) + { + _enclosingTransaction.UpdateDroppedSpanStats(Context?.Service?.Target?.Type, Context?.Service?.Target?.Name, + Context?.Destination?.Service?.Resource, _outcome, duration, count); + } + else if (DroppedSpanStatCache.HasValue) + { + _enclosingTransaction.UpdateDroppedSpanStats(DroppedSpanStatCache.Value.Target.Type, DroppedSpanStatCache.Value.Target.Name, + DroppedSpanStatCache.Value.DestinationServiceResource, _outcome, duration, count); + } + } + + /// + /// Spec: exit && !context.hasPropagated && (outcome == null || outcome == "success"). The + /// has-no-children condition is an addition: a span that is compressed into a sibling's composite loses its + /// identity, which would orphan any child referencing it. + /// + public bool IsCompressionEligible() => IsExitSpan && !_hasPropagatedContext && !_hasChildren + && Outcome is Outcome.Success or Outcome.Unknown; public void CaptureException(Exception exception, string culprit = null, bool isHandled = false, string parentId = null, Dictionary labels = null diff --git a/src/Elastic.Apm/Model/Transaction.cs b/src/Elastic.Apm/Model/Transaction.cs index dbe58f7f4..f64ea1b5c 100644 --- a/src/Elastic.Apm/Model/Transaction.cs +++ b/src/Elastic.Apm/Model/Transaction.cs @@ -376,7 +376,13 @@ private void CheckAndCaptureBaggage() /// private ConcurrentDictionary _droppedSpanStatsMap; - private bool _isEnded; + private volatile bool _isEnded; + + /// + /// Whether has been called. Read by ending child spans to decide whether they may still be buffered + /// for span compression, see . + /// + internal bool IsEnded => _isEnded; private string _name; @@ -394,8 +400,18 @@ private void CheckAndCaptureBaggage() private bool _outcomeChangedThroughApi; internal ChildDurationTimer ChildDurationTimer { get; } = new(); + /// + /// The span buffered for compression directly under the transaction, see . + /// Only accessed while holding . + /// internal Span CompressionBuffer; + /// + /// Guards the compression buffer of the transaction and of every span in it. The span compression spec requires + /// setting and retrieving a buffered span to be atomic, as sibling spans may end concurrently. + /// + internal readonly object CompressionBufferLock = new(); + /// /// Holds configuration snapshot (which is immutable) that was current when this transaction started. /// We would like transaction data to be consistent and not to be affected by possible changes in agent's configuration @@ -590,9 +606,11 @@ private Activity StartActivity(bool shouldRestartTrace) private readonly object _lock = new(); internal void UpdateDroppedSpanStats(string serviceTargetType, string serviceTargetName, string destinationServiceResource, Outcome outcome, - double duration + double duration, int count ) { + var durationSumUs = duration * 1000; + //lock the lazy initialization of the dictionary if (_droppedSpanStatsMap == null) { @@ -607,14 +625,14 @@ double duration //AddOrUpdate callbacks can run multiple times so still wrapping this in a lock var key = new DroppedSpanStatsKey(serviceTargetType, serviceTargetName, outcome); _droppedSpanStatsMap.AddOrUpdate(key, - _ => new DroppedSpanStats(serviceTargetType, serviceTargetName, destinationServiceResource, outcome, duration), + _ => new DroppedSpanStats(serviceTargetType, serviceTargetName, destinationServiceResource, outcome, durationSumUs, count), (_, stats) => { stats.Duration ??= new DroppedSpanStats.DroppedSpanDuration { Sum = new DroppedSpanStats.DroppedSpanDuration.DroppedSpanDurationSum() }; - stats.Duration.Count++; - stats.Duration.Sum.UsRaw += duration; + stats.Duration.Count += count; + stats.Duration.Sum.UsRaw += durationSumUs; return stats; }); } @@ -785,17 +803,24 @@ public void End() handler?.Invoke(this, EventArgs.Empty); Ended = null; - if (CompressionBuffer != null) + // Report the span buffered for compression, if any (spec: onEnd). Taken under the lock so that a child span ending + // concurrently either sees the transaction as ended and reports itself, or is picked up here - never neither or both. + Span buffered; + lock (CompressionBufferLock) { - if (!CompressionBuffer.IsSampled && _apmServerInfo?.Version >= new ElasticVersion(8, 0, 0, string.Empty)) + buffered = CompressionBuffer; + CompressionBuffer = null; + } + + if (buffered != null) + { + if (!buffered.IsSampled && _apmServerInfo?.Version >= new ElasticVersion(8, 0, 0, string.Empty)) { _logger?.Debug()?.Log("Dropping unsampled compressed span - unsampled span won't be sent on APM Server v8+. SpanId: {id}", - CompressionBuffer.Id); + buffered.Id); } else - _sender.QueueSpan(CompressionBuffer); - - CompressionBuffer = null; + buffered.Report(); } if (IsSampled || _apmServerInfo?.Version < new ElasticVersion(8, 0, 0, string.Empty)) diff --git a/src/instrumentations/Elastic.Apm.EntityFramework6/Ef6Interceptor.cs b/src/instrumentations/Elastic.Apm.EntityFramework6/Ef6Interceptor.cs index dd2c2b8f3..1618252fe 100644 --- a/src/instrumentations/Elastic.Apm.EntityFramework6/Ef6Interceptor.cs +++ b/src/instrumentations/Elastic.Apm.EntityFramework6/Ef6Interceptor.cs @@ -27,34 +27,33 @@ public class Ef6Interceptor : IDbCommandInterceptor { private const string ThisClassName = nameof(Ef6Interceptor); - private readonly Lazy _impl = new Lazy(() => new Impl()); + private readonly Lazy _impl = new(() => new Impl()); public void NonQueryExecuting(DbCommand command, DbCommandInterceptionContext interceptCtx) => - CreateImplIfReadyAndNoConflict()?.StartSpan(command, interceptCtx); + CreateImplIfReadyAndNoConflict(command)?.StartSpan(command, interceptCtx); public void NonQueryExecuted(DbCommand command, DbCommandInterceptionContext interceptCtx) => - CreateImplIfReadyAndNoConflict()?.EndSpan(command, interceptCtx); + CreateImplIfReadyAndNoConflict(command)?.EndSpan(command, interceptCtx); public void ReaderExecuting(DbCommand command, DbCommandInterceptionContext interceptCtx) => - CreateImplIfReadyAndNoConflict()?.StartSpan(command, interceptCtx); + CreateImplIfReadyAndNoConflict(command)?.StartSpan(command, interceptCtx); public void ReaderExecuted(DbCommand command, DbCommandInterceptionContext interceptCtx) => - CreateImplIfReadyAndNoConflict()?.EndSpan(command, interceptCtx); + CreateImplIfReadyAndNoConflict(command)?.EndSpan(command, interceptCtx); public void ScalarExecuting(DbCommand command, DbCommandInterceptionContext interceptCtx) => - CreateImplIfReadyAndNoConflict()?.StartSpan(command, interceptCtx); + CreateImplIfReadyAndNoConflict(command)?.StartSpan(command, interceptCtx); public void ScalarExecuted(DbCommand command, DbCommandInterceptionContext interceptCtx) => - CreateImplIfReadyAndNoConflict()?.EndSpan(command, interceptCtx); + CreateImplIfReadyAndNoConflict(command)?.EndSpan(command, interceptCtx); /// /// DB spans can be created only when there's a current transaction /// which in turn means agent singleton instance should already be created. - /// Also checks for competing instrumentation. If SqlClient already instrumented, it'll return null, so the interceptor - /// won't create - /// duplicate spans + /// Also checks for competing instrumentation. If the profiler's ADO.NET integrations already trace this command, + /// it'll return null, so the interceptor won't create duplicate spans. /// - private Impl CreateImplIfReadyAndNoConflict() + private Impl CreateImplIfReadyAndNoConflict(IDbCommand command) { // Make sure agent is configured var impl = Agent.IsConfigured ? _impl.Value : null; @@ -62,10 +61,7 @@ private Impl CreateImplIfReadyAndNoConflict() return null; // Make sure DB spans were not already captured - if (!(Agent.Tracer.CurrentSpan is Span span)) - return impl; - - return span.InstrumentationFlag == InstrumentationFlag.SqlClient ? null : impl; + return CompetingInstrumentation.IsCommandTracedByAdoNetModule(Agent.Instance, command) ? null : impl; } private class Impl diff --git a/src/instrumentations/Elastic.Apm.EntityFrameworkCore/EfCoreDiagnosticListener.cs b/src/instrumentations/Elastic.Apm.EntityFrameworkCore/EfCoreDiagnosticListener.cs index b34cfdde3..ad3e56b10 100644 --- a/src/instrumentations/Elastic.Apm.EntityFrameworkCore/EfCoreDiagnosticListener.cs +++ b/src/instrumentations/Elastic.Apm.EntityFrameworkCore/EfCoreDiagnosticListener.cs @@ -7,6 +7,7 @@ using System.Collections.Generic; using Elastic.Apm.Api; using Elastic.Apm.DiagnosticListeners; +using Elastic.Apm.Logging; using Elastic.Apm.Model; using Microsoft.EntityFrameworkCore.Diagnostics; @@ -25,15 +26,19 @@ internal class EfCoreDiagnosticListener : DiagnosticListenerBase protected override void HandleOnNext(KeyValuePair kv) { - // check for competing instrumentation - if (_agent?.TracerInternal.CurrentSpan is Span { InstrumentationFlag: InstrumentationFlag.SqlClient }) - return; - switch (kv.Key) { case { } k when k == RelationalEventId.CommandExecuting.Name && ApmAgent.Tracer.CurrentTransaction != null: if (kv.Value is CommandEventData commandEventData) { + // The command is already traced by the profiler's ADO.NET integrations, so don't start a nested span + // for the very same command. The matching Executed/Error event is still handled and finds nothing to end. + if (CompetingInstrumentation.IsCommandTracedByAdoNetModule(_agent, commandEventData.Command)) + { + Logger.Trace()?.Log("CommandExecuting event is skipped, the command is traced by a competing instrumentation."); + return; + } + var newSpan = DbSpanCommon.StartSpan(ApmAgent, commandEventData.Command, InstrumentationFlag.EfCore, captureStackTraceOnStart: true); _spans.TryAdd(commandEventData.CommandId, newSpan); diff --git a/test/Elastic.Apm.Tests/DroppedSpansStatsTests.cs b/test/Elastic.Apm.Tests/DroppedSpansStatsTests.cs index e0cd2453e..63d7ef267 100644 --- a/test/Elastic.Apm.Tests/DroppedSpansStatsTests.cs +++ b/test/Elastic.Apm.Tests/DroppedSpansStatsTests.cs @@ -60,7 +60,7 @@ public void SingleDroppedSpanTest() //This span will be dropped var span1 = transaction.StartSpan("foo", "bar", isExitSpan: true); span1.Context.Http = new Http { Method = "GET", StatusCode = 200, Url = "https://foo.bar" }; - span1.Duration = 100.001; + span1.Duration = 100.0014; span1.End(); transaction.End(); @@ -75,7 +75,7 @@ public void SingleDroppedSpanTest() payloadSender.FirstTransaction.DroppedSpanStats.First().ServiceTargetType.Should().Be("bar"); payloadSender.FirstTransaction.DroppedSpanStats.First().Outcome.Should().Be(Outcome.Success); payloadSender.FirstTransaction.DroppedSpanStats.First().Duration.Count.Should().Be(1); - payloadSender.FirstTransaction.DroppedSpanStats.First().Duration.Sum.Us.Should().Be(100); // This should be rounded and will be sent in the JSON + payloadSender.FirstTransaction.DroppedSpanStats.First().Duration.Sum.Us.Should().Be(100001); } [Fact] @@ -130,22 +130,22 @@ public void MultipleDroppedSpanTest() payloadSender.FirstTransaction.DroppedSpanStats.Should() .Contain(n => n.Outcome == Outcome.Success - && n.Duration.Count == 2 && Math.Abs(n.Duration.Sum.UsRaw - 250) < 1 && n.DestinationServiceResource == "foo.bar:443" + && n.Duration.Count == 2 && Math.Abs(n.Duration.Sum.UsRaw - 250000) < 1 && n.DestinationServiceResource == "foo.bar:443" && n.ServiceTargetName == "foo.bar:443" && n.ServiceTargetType == "bar"); payloadSender.FirstTransaction.DroppedSpanStats.Should() .Contain(n => n.Outcome == Outcome.Failure - && n.Duration.Count == 1 && Math.Abs(n.Duration.Sum.UsRaw - 50) < 1 && n.DestinationServiceResource == "foo.bar:443" + && n.Duration.Count == 1 && Math.Abs(n.Duration.Sum.UsRaw - 50000) < 1 && n.DestinationServiceResource == "foo.bar:443" && n.ServiceTargetName == "foo.bar:443" && n.ServiceTargetType == "bar"); payloadSender.FirstTransaction.DroppedSpanStats.Should() .Contain(n => n.Outcome == Outcome.Success - && n.Duration.Count == 1 && Math.Abs(n.Duration.Sum.UsRaw - 15) < 1 && n.DestinationServiceResource == "foo2.bar:443" + && n.Duration.Count == 1 && Math.Abs(n.Duration.Sum.UsRaw - 15000) < 1 && n.DestinationServiceResource == "foo2.bar:443" && n.ServiceTargetName == "foo2.bar:443" && n.ServiceTargetType == "bar"); payloadSender.FirstTransaction.DroppedSpanStats.Should() .Contain(n => n.Outcome == Outcome.Success - && n.Duration.Count == 50 && Math.Abs(n.Duration.Sum.UsRaw - 50 * 50) < 1 && n.DestinationServiceResource == "mysql"); + && n.Duration.Count == 50 && Math.Abs(n.Duration.Sum.UsRaw - 50 * 50000) < 1 && n.DestinationServiceResource == "mysql"); } /// diff --git a/test/Elastic.Apm.Tests/SerializationTests.cs b/test/Elastic.Apm.Tests/SerializationTests.cs index d24381168..b4c5ef4d0 100644 --- a/test/Elastic.Apm.Tests/SerializationTests.cs +++ b/test/Elastic.Apm.Tests/SerializationTests.cs @@ -477,8 +477,11 @@ public void SpanContext_Destination_Service_Should_Serialize_Name_And_Type_As_Em /// Asserts that dropped span statistic is not flattened but sent as an object to APM Server. /// APM Server expects object and flattening caused issues. /// - [Fact] - public void DroppedSpanStatsTest() + [Theory] + [InlineData(100, 100000L)] + [InlineData(100.0014, 100001L)] + [InlineData(3000000, 3000000000L)] + public void DroppedSpanStatsTest(double duration, long expectedMicroseconds) { using var apmAgent = new ApmAgent(new TestAgentComponents(configuration: new MockConfiguration(transactionMaxSpans: "1"))); @@ -489,13 +492,13 @@ public void DroppedSpanStatsTest() //This span will be dropped var span1 = transaction.StartSpan("foo", "bar", isExitSpan: true); span1.Context.Http = new Http { Method = "GET", StatusCode = 200, Url = "https://foo.bar" }; - span1.Duration = 100; + span1.Duration = duration; span1.End(); transaction.End(); var json = _payloadItemSerializer.Serialize(transaction); - json.Should().Contain("\"duration\":{\"count\":1,\"sum\":{\"us\":100}}"); + json.Should().Contain("\"duration\":{\"count\":1,\"sum\":{\"us\":" + expectedMicroseconds + "}}"); } /// diff --git a/test/Elastic.Apm.Tests/SpanCompressionBufferTests.cs b/test/Elastic.Apm.Tests/SpanCompressionBufferTests.cs new file mode 100644 index 000000000..cb8b0c47b --- /dev/null +++ b/test/Elastic.Apm.Tests/SpanCompressionBufferTests.cs @@ -0,0 +1,616 @@ +// Licensed to Elasticsearch B.V under one or more agreements. +// Elasticsearch B.V licenses this file to you under the Apache 2.0 License. +// See the LICENSE file in the project root for more information + +using System; +using System.Collections.Generic; +using System.Linq; +using System.Threading; +using System.Threading.Tasks; +using Elastic.Apm.Api; +using Elastic.Apm.Helpers; +using Elastic.Apm.Model; +using Elastic.Apm.Report.Serialization; +using Elastic.Apm.Tests.Utilities; +using FluentAssertions; +using Xunit; + +namespace Elastic.Apm.Tests +{ + /// + /// Regression tests for the span compression buffer handling in and . + /// Spec: https://github.com/elastic/apm/blob/main/specs/agents/handling-huge-traces/tracing-spans-compress.md + /// + /// Ended, sampled spans must be reported exactly once unless explicitly dropped or abandoned. Compression must preserve + /// their total count and the parent references of reported children. + /// + /// The OpenTelemetry bridge is disabled for the same reason as in . + /// + public class SpanCompressionBufferTests + { + private static ApmAgent CreateAgent(MockPayloadSender payloadSender, string exitSpanMinDuration = "0", + string sameKindMaxDuration = null, string exactMatchMaxDuration = null, bool spanCompressionEnabled = true, + string transactionMaxSpans = null + ) => + new(new TestAgentComponents(apmServerInfo: MockApmServerInfo.Version80, payloadSender: payloadSender, + configuration: new MockConfiguration(spanCompressionEnabled: spanCompressionEnabled.ToString(), exitSpanMinDuration: exitSpanMinDuration, + spanCompressionSameKindMaxDuration: sameKindMaxDuration, spanCompressionExactMatchMaxDuration: exactMatchMaxDuration, + transactionMaxSpans: transactionMaxSpans, openTelemetryBridgeEnabled: "false"))); + + /// + /// Starts a db exit span (the shape produced by the SQL instrumentations) under a transaction or under another span. + /// + private static Span StartDbSpan(IExecutionSegment parent, string name, long? timestamp = null, string instance = "01", + bool makeCurrent = true) + { + var span = parent switch + { + Transaction transaction => transaction.StartSpanInternal(name, ApiConstants.TypeDb, ApiConstants.SubtypeMssql, + timestamp: timestamp, isExitSpan: true, makeCurrent: makeCurrent), + Span parentSpan => parentSpan.StartSpanInternal(name, ApiConstants.TypeDb, ApiConstants.SubtypeMssql, + timestamp: timestamp, isExitSpan: true, makeCurrent: makeCurrent), + _ => throw new ArgumentException("Unexpected execution segment type", nameof(parent)) + }; + + span.Context.Db = new Database { Type = Database.TypeSql, Instance = instance }; + return span; + } + + /// + /// The number of ended spans a reported span stands for: itself, or every span merged into it when it is a composite. + /// + private static int Represents(ISpan span) => (span as Span)?.Composite?.Count ?? 1; + + private static IEnumerable Composites(MockPayloadSender payloadSender) => + payloadSender.Spans.OfType().Where(s => s.Composite != null); + + private static void AssertNoOrphanedSpans(MockPayloadSender payloadSender) + { + var ids = new HashSet(payloadSender.Spans.Select(s => s.Id) + .Concat(payloadSender.Transactions.Select(t => t.Id))); + payloadSender.Spans.Should().OnlyContain(s => ids.Contains(s.ParentId), + "compression and fast-exit dropping must preserve the parents of reported spans"); + } + + /// + /// The shape seen in the field when two instrumentations trace the same SQL command: an outer db exit span with a + /// db exit child of the same name, repeated for every command in the transaction. The child ends first with a precise + /// duration, the outer span ends with a duration of 0 (coarse clock). Despite matching the same-kind duration threshold, + /// the outer spans must be retained individually because their children reference them. + /// Before the fix the child fell through to the transaction's compression buffer, reported that buffered span without + /// replacing it, and the very same span object was then enqueued once per subsequent command and once more when the + /// transaction ended. The children were never reported at all. + /// + [Fact] + public void NestedExitSpans_AreReportedExactlyOnce() + { + var payloadSender = new MockPayloadSender(); + var innerIds = new List(); + const int commands = 5; + + using (var agent = CreateAgent(payloadSender)) + { + var transaction = agent.Tracer.StartTransaction("GET Home/Index", ApiConstants.TypeRequest); + + for (var i = 0; i < commands; i++) + { + var outer = StartDbSpan(transaction, $"[dbo].[usp{i}]"); + var inner = StartDbSpan(outer, $"[dbo].[usp{i}]"); + innerIds.Add(inner.Id); + + inner.Duration = 1.2; + inner.End(); + + outer.Duration = 0; + outer.End(); + } + + transaction.End(); + } + + payloadSender.Spans.Select(s => s.Id).Should().OnlyHaveUniqueItems("a span must never be reported twice"); + payloadSender.Spans.Sum(Represents).Should().Be(commands * 2, "every ended span must be accounted for exactly once"); + + // the children are reported individually when their parent ends + foreach (var innerId in innerIds) + payloadSender.Spans.Should().ContainSingle(s => s.Id == innerId); + + Composites(payloadSender).Should().BeEmpty(); + payloadSender.Spans.Should().HaveCount(commands * 2); + AssertNoOrphanedSpans(payloadSender); + } + + /// + /// Parents with identical names and short durations must not be compressed away when their buffered children + /// are reported, otherwise the children reference parent IDs that will never be sent. + /// + [Fact] + public void BufferedChildSpan_IsReported_AndItsParentIsNotCompressedAway() + { + var payloadSender = new MockPayloadSender(); + var childIds = new List(); + const int commands = 3; + + using (var agent = CreateAgent(payloadSender)) + { + var transaction = agent.Tracer.StartTransaction("GET Home/Index", ApiConstants.TypeRequest); + + for (var i = 0; i < commands; i++) + { + var outer = StartDbSpan(transaction, "SELECT * FROM Table"); + var child = StartDbSpan(outer, "SELECT * FROM Table"); + childIds.Add(child.Id); + + child.Duration = 1; + child.End(); + + outer.Duration = 1; + outer.End(); + } + + transaction.End(); + } + + payloadSender.Spans.Select(s => s.Id).Should().OnlyHaveUniqueItems(); + payloadSender.Spans.Sum(Represents).Should().Be(commands * 2); + + foreach (var childId in childIds) + payloadSender.Spans.Should().ContainSingle(s => s.Id == childId); + + Composites(payloadSender).Should().BeEmpty(); + payloadSender.Spans.Should().HaveCount(commands * 2); + AssertNoOrphanedSpans(payloadSender); + } + + [Theory] + [InlineData(true, true, true)] + [InlineData(true, true, false)] + [InlineData(true, false, true)] + [InlineData(true, false, false)] + [InlineData(false, true, true)] + [InlineData(false, true, false)] + [InlineData(false, false, true)] + [InlineData(false, false, false)] + public void FastParent_WithReportedChild_IsNotDropped(bool compressionEnabled, bool childEndsFirst, bool makeChildCurrent) + { + var payloadSender = new MockPayloadSender(); + using var agent = CreateAgent(payloadSender, exitSpanMinDuration: "10ms", spanCompressionEnabled: compressionEnabled); + var transaction = agent.Tracer.StartTransaction("transaction", "type"); + var parent = StartDbSpan(transaction, "parent"); + var child = StartDbSpan(parent, "child", makeCurrent: makeChildCurrent); + parent.Duration = 1; + child.Duration = 20; + + if (childEndsFirst) + child.End(); + + parent.End(); + child.End(); + transaction.End(); + + payloadSender.Spans.Should().HaveCount(2); + payloadSender.Spans.Select(s => s.Id).Should().OnlyHaveUniqueItems(); + payloadSender.Spans.Should().ContainSingle(s => s.Id == parent.Id); + payloadSender.Spans.Should().ContainSingle(s => s.Id == child.Id && s.ParentId == parent.Id); + AssertNoOrphanedSpans(payloadSender); + } + + [Fact] + public void ParentWithCompressibleChildren_IsRetained_WhileChildrenStillCompress() + { + var payloadSender = new MockPayloadSender(); + using var agent = CreateAgent(payloadSender); + var transaction = agent.Tracer.StartTransaction("transaction", "type"); + + for (var i = 0; i < 2; i++) + { + var parent = StartDbSpan(transaction, "parent"); + for (var j = 0; j < 2; j++) + { + var child = StartDbSpan(parent, "child"); + child.Duration = 1; + child.End(); + } + parent.Duration = 1; + parent.End(); + } + transaction.End(); + + payloadSender.Spans.Should().HaveCount(4); + payloadSender.Spans.Sum(Represents).Should().Be(6); + Composites(payloadSender).Should().HaveCount(2).And.OnlyContain(s => s.Name == "child" && s.Composite.Count == 2); + AssertNoOrphanedSpans(payloadSender); + } + + /// + /// A buffered span that acquires a child keeps its own id when it absorbs a sibling, so the child is not orphaned + /// and compression may continue. Only the sibling merged into the composite loses its identity, which is why + /// is checked on the ending span rather than on the buffered one. + /// + [Fact] + public void BufferedSpan_AcquiringChild_StillCompressesWithSibling_AndKeepsItsChild() + { + var payloadSender = new MockPayloadSender(); + using var agent = CreateAgent(payloadSender); + var transaction = agent.Tracer.StartTransaction("transaction", "type"); + var parent = StartDbSpan(transaction, "SELECT 1"); + parent.Duration = 1; + parent.End(); + + var child = StartDbSpan(parent, "child"); + var sibling = StartDbSpan(transaction, "SELECT 1"); + sibling.Duration = 1; + sibling.End(); + child.End(); + transaction.End(); + + payloadSender.Spans.Should().HaveCount(2); + payloadSender.Spans.Sum(Represents).Should().Be(3); + Composites(payloadSender).Should().ContainSingle().Which.Id.Should().Be(parent.Id); + payloadSender.Spans.Should().ContainSingle(s => s.Id == child.Id && s.ParentId == parent.Id); + AssertNoOrphanedSpans(payloadSender); + } + + /// + /// A child that can never reach APM Server cannot be orphaned, so it must not stop its parent from being compressed. + /// Otherwise compression switches off once transaction_max_spans is reached, which is exactly the huge trace + /// it exists to shrink. + /// + [Fact] + public void ChildDroppedByMaxSpans_DoesNotPreventItsParentFromCompressing() + { + var payloadSender = new MockPayloadSender(); + using var agent = CreateAgent(payloadSender, transactionMaxSpans: "2"); + var transaction = agent.Tracer.StartTransaction("transaction", "type"); + + var first = StartDbSpan(transaction, "SELECT 1"); + var second = StartDbSpan(transaction, "SELECT 1"); + + // the third span of the transaction exceeds transaction_max_spans and is never reported + var droppedChild = StartDbSpan(first, "child"); + droppedChild.Duration = 1; + droppedChild.End(); + + first.Duration = 1; + first.End(); + second.Duration = 1; + second.End(); + transaction.End(); + + var composite = payloadSender.Spans.Should().ContainSingle().Which.As(); + composite.Id.Should().Be(first.Id); + composite.Composite.Count.Should().Be(2); + payloadSender.FirstTransaction.SpanCount.Dropped.Should().Be(1); + } + + /// + /// Spans discarded for being faster than exit_span_min_duration are not reported, so they move from the + /// started count to the dropped count, a composite counting for every span it represents. + /// + [Fact] + public void DroppedFastExitSpans_AreCountedInSpanCount() + { + var payloadSender = new MockPayloadSender(); + using var agent = CreateAgent(payloadSender, exitSpanMinDuration: "10ms"); + var transaction = agent.Tracer.StartTransaction("transaction", "type"); + var start = TimeUtils.TimestampNow(); + + // two fast spans that compress into a composite which is then dropped as a whole + var first = StartDbSpan(transaction, "SELECT 1", timestamp: start); + first.Duration = 1; + first.End(); + var second = StartDbSpan(transaction, "SELECT 1", timestamp: start + 3000); + second.Duration = 1; + second.End(); + + // ends the compression sequence and is itself slow enough to be kept + var slow = StartDbSpan(transaction, "SELECT 2", timestamp: start + 10_000); + slow.Duration = 20; + slow.End(); + + transaction.End(); + + payloadSender.Spans.Should().ContainSingle().Which.Id.Should().Be(slow.Id); + payloadSender.FirstTransaction.SpanCount.Started.Should().Be(1); + payloadSender.FirstTransaction.SpanCount.Dropped.Should().Be(2); + } + + [Fact] + public void Grandchild_DoesNotConsumeTransactionsCompressionBuffer() + { + var payloadSender = new MockPayloadSender(); + using var agent = CreateAgent(payloadSender); + var transaction = agent.Tracer.StartTransaction("transaction", "type"); + var sibling = StartDbSpan(transaction, "SELECT 1"); + sibling.Duration = 1; + sibling.End(); + + var parent = StartDbSpan(transaction, "parent"); + var child = StartDbSpan(parent, "SELECT 1"); + child.Duration = 1; + child.End(); + payloadSender.Spans.Should().BeEmpty("the child belongs in its direct parent's buffer"); + + parent.End(); + transaction.End(); + + payloadSender.Spans.Should().HaveCount(3); + payloadSender.Spans.Select(s => s.Id).Should().OnlyHaveUniqueItems(); + Composites(payloadSender).Should().BeEmpty(); + AssertNoOrphanedSpans(payloadSender); + } + + /// + /// The spec treats the transaction like any other parent: a compression eligible span that ends after its parent has + /// ended must be reported immediately. Before the fix such a span was placed into the transaction's compression buffer + /// after that buffer had already been flushed, so it was never reported. + /// + [Fact] + public void EligibleSpan_EndingAfterTransactionEnded_IsReported() + { + var payloadSender = new MockPayloadSender(); + + using (var agent = CreateAgent(payloadSender)) + { + var transaction = agent.Tracer.StartTransaction("GET Home/Index", ApiConstants.TypeRequest); + var span = StartDbSpan(transaction, "SELECT 1"); + + transaction.End(); + span.End(); + + payloadSender.Spans.Should().ContainSingle().Which.Id.Should().Be(span.Id); + } + } + + /// + /// A span abandoned by an instrumentation (see ) is not reported itself, but a child it + /// buffered has ended normally and must still be reported. + /// + [Fact] + public void AbandonedParent_StillReportsItsBufferedChild() + { + var payloadSender = new MockPayloadSender(); + + using (var agent = CreateAgent(payloadSender)) + { + var transaction = agent.Tracer.StartTransaction("GET Home/Index", ApiConstants.TypeRequest); + var parent = StartDbSpan(transaction, "outer"); + var child = StartDbSpan(parent, "inner"); + + child.Duration = 1; + child.End(); + + parent.Abandon(); + transaction.End(); + + payloadSender.Spans.Should().ContainSingle().Which.Id.Should().Be(child.Id); + } + } + + /// + /// The exit_span_min_duration threshold applies to buffered spans too. Before the fix, the span left in the + /// transaction's compression buffer was queued directly by and bypassed the check that + /// every other reported span goes through. + /// + [Fact] + public void FastExitSpan_FlushedAtTransactionEnd_IsDroppedByExitSpanMinDuration() + { + var payloadSender = new MockPayloadSender(); + + using (var agent = CreateAgent(payloadSender, exitSpanMinDuration: "10ms")) + { + var transaction = agent.Tracer.StartTransaction("GET Home/Index", ApiConstants.TypeRequest); + var span = StartDbSpan(transaction, "SELECT 1"); + + span.Duration = 1; + span.End(); + transaction.End(); + } + + payloadSender.Spans.Should().BeEmpty(); + var stats = payloadSender.FirstTransaction.DroppedSpanStats.Should().ContainSingle().Subject; + stats.ServiceTargetType.Should().Be(ApiConstants.SubtypeMssql); + stats.Duration.Count.Should().Be(1); + stats.Duration.Sum.Us.Should().Be(1000); + } + + [Theory] + [InlineData("transaction", false)] + [InlineData("transaction", true)] + [InlineData("sibling", false)] + [InlineData("sibling", true)] + [InlineData("parent", false)] + [InlineData("parent", true)] + public void DroppedComposite_PreservesCallCountAndNetDuration(string flushTrigger, bool sameKind) + { + var payloadSender = new MockPayloadSender(); + using var agent = CreateAgent(payloadSender, exitSpanMinDuration: "10ms", sameKindMaxDuration: "1ms"); + var transaction = agent.Tracer.StartTransaction("transaction", "type"); + var parent = flushTrigger == "parent" ? transaction.StartSpan("parent", "app") : null; + var owner = parent ?? (IExecutionSegment)transaction; + var start = TimeUtils.TimestampNow(); + + var first = StartDbSpan(owner, "SELECT 1", timestamp: start); + first.Duration = 1; + first.End(); + var second = StartDbSpan(owner, sameKind ? "SELECT 2" : "SELECT 1", timestamp: start + 3000); + second.Duration = 1; + second.End(); + + first.Composite.Should().NotBeNull(); + first.Composite.CompressionStrategy.Should().Be(sameKind ? "same_kind" : "exact_match"); + first.Duration.Should().Be(4); + + if (flushTrigger == "sibling") + owner.StartSpan("flush", "app").End(); + parent?.End(); + transaction.End(); + + payloadSender.Spans.Should().NotContain(s => s.Type == ApiConstants.TypeDb); + var stats = payloadSender.FirstTransaction.DroppedSpanStats.Should().ContainSingle().Subject; + stats.ServiceTargetType.Should().Be(ApiConstants.SubtypeMssql); + stats.ServiceTargetName.Should().Be("01"); + stats.Outcome.Should().Be(Outcome.Success); + stats.Duration.Count.Should().Be(2); + stats.Duration.Sum.UsRaw.Should().Be(2000); + stats.Duration.Sum.Us.Should().Be(2000); + new PayloadItemSerializer().Serialize(payloadSender.FirstTransaction) + .Should().Contain("\"duration\":{\"count\":2,\"sum\":{\"us\":2000}}"); + } + + [Fact] + public void DroppedComposites_AccumulateWithIndividualSpans() + { + var payloadSender = new MockPayloadSender(); + using var agent = CreateAgent(payloadSender, exitSpanMinDuration: "10ms"); + var transaction = agent.Tracer.StartTransaction("transaction", "type"); + var start = TimeUtils.TimestampNow(); + + for (var group = 0; group < 3; group++) + { + var count = group == 1 ? 1 : 2; + for (var i = 0; i < count; i++) + { + var span = StartDbSpan(transaction, "SELECT 1", timestamp: start + group * 10000 + i * 3000); + span.Duration = 1; + span.End(); + } + transaction.StartSpan("flush", "app").End(); + } + transaction.End(); + + payloadSender.Spans.Should().HaveCount(3).And.OnlyContain(s => s.Type == "app"); + var stats = payloadSender.FirstTransaction.DroppedSpanStats.Should().ContainSingle().Subject; + stats.Duration.Count.Should().Be(5); + stats.Duration.Sum.Us.Should().Be(5000); + } + + /// + /// When a buffered span is dropped because a non-compressible sibling ends, the dropped span statistics must describe + /// the dropped span, not the sibling that caused it to be flushed. Before the fix the sibling's context was used, which + /// here has no destination at all, so nothing was recorded. + /// + [Fact] + public void DroppedSpanStats_DescribeTheDroppedSpan_NotTheSpanThatFlushedIt() + { + var payloadSender = new MockPayloadSender(); + + using (var agent = CreateAgent(payloadSender, exitSpanMinDuration: "10ms")) + { + var transaction = agent.Tracer.StartTransaction("GET Home/Index", ApiConstants.TypeRequest); + + var fastDbSpan = StartDbSpan(transaction, "SELECT 1", instance: "dbA"); + fastDbSpan.Duration = 1; + fastDbSpan.End(); + + // a non-exit span is never compression eligible, so ending it flushes (and here drops) the buffered db span + var appSpan = transaction.StartSpan("work", "app"); + appSpan.End(); + + transaction.End(); + + payloadSender.Spans.Should().ContainSingle().Which.Id.Should().Be(appSpan.Id); + } + + var stats = payloadSender.FirstTransaction.DroppedSpanStats.Should().ContainSingle().Subject; + stats.ServiceTargetType.Should().Be(ApiConstants.SubtypeMssql); + stats.ServiceTargetName.Should().Be("dbA"); + stats.Duration.Count.Should().Be(1); + } + + /// + /// The duration of a composite span is the gross duration of the spans it represents: the end of the last compressed + /// span minus the start of the first one. Before the fix the duration was recomputed as "now" when the composite was + /// reported, which added the idle time between the last compressed span and the end of the transaction. + /// + [Fact] + public void CompositeDuration_IsGrossDurationOfCompressedSpans_NotTheReportTime() + { + var payloadSender = new MockPayloadSender(); + + using (var agent = CreateAgent(payloadSender)) + { + var transaction = agent.Tracer.StartTransaction("GET Home/Index", ApiConstants.TypeRequest); + var start = TimeUtils.TimestampNow(); + + var first = StartDbSpan(transaction, "SELECT 1", timestamp: start); + first.Duration = 5; + first.End(); + + // starts 10ms after the first span and lasts 5ms, so the pair spans 15ms gross with a net sum of 10ms + var second = StartDbSpan(transaction, "SELECT 1", timestamp: start + 10_000); + second.Duration = 5; + second.End(); + + Thread.Sleep(60); + transaction.End(); + } + + var composite = payloadSender.Spans.Should().ContainSingle().Which.As(); + composite.Composite.Should().NotBeNull(); + composite.Composite.Count.Should().Be(2); + composite.Composite.Sum.Should().Be(10); + composite.Duration.Should().Be(15); + } + + [Fact] + public void ConcurrentlyEndingParentsAndChildren_PreserveParentReferences() + { + var payloadSender = new MockPayloadSender(); + using var agent = CreateAgent(payloadSender, exitSpanMinDuration: "10ms"); + var transaction = agent.Tracer.StartTransaction("transaction", "type"); + var spans = new List(); + for (var i = 0; i < 100; i++) + { + var parent = StartDbSpan(transaction, "parent", makeCurrent: false); + var child = StartDbSpan(parent, "child", makeCurrent: false); + parent.Duration = 1; + child.Duration = 20; + spans.Add(parent); + spans.Add(child); + } + + Parallel.ForEach(spans, new ParallelOptions { MaxDegreeOfParallelism = 8 }, span => span.End()); + transaction.End(); + + payloadSender.Spans.Should().HaveCount(spans.Count); + payloadSender.Spans.Select(s => s.Id).Should().OnlyHaveUniqueItems(); + AssertNoOrphanedSpans(payloadSender); + } + + /// + /// The spec requires setting and retrieving the buffered span to be atomic. Siblings ending concurrently must neither + /// report the same buffered span twice nor overwrite (and thereby lose) each other's buffered span. + /// + [Fact] + public void ConcurrentlyEndingSiblings_AreNeitherLostNorDuplicated() + { + const int spansPerTransaction = 400; + + for (var iteration = 0; iteration < 5; iteration++) + { + var payloadSender = new MockPayloadSender(); + + using (var agent = CreateAgent(payloadSender)) + { + var transaction = agent.Tracer.StartTransaction("GET Home/Index", ApiConstants.TypeRequest); + + // a mix of names and durations so that some siblings compress and others do not + var spans = Enumerable.Range(0, spansPerTransaction) + .Select(i => StartDbSpan(transaction, $"SELECT {i % 4}")) + .ToList(); + + for (var i = 0; i < spans.Count; i++) + spans[i].Duration = i % 3; + + Parallel.ForEach(spans, new ParallelOptions { MaxDegreeOfParallelism = 8 }, span => span.End()); + + transaction.End(); + } + + payloadSender.Spans.Select(s => s.Id).Should().OnlyHaveUniqueItems($"iteration {iteration}"); + payloadSender.Spans.Sum(Represents).Should().Be(spansPerTransaction, $"iteration {iteration}"); + } + } + } +} diff --git a/test/instrumentations/Elastic.Apm.SqlClient.Tests/SqlClientDiagnosticListenerUnitTests.cs b/test/instrumentations/Elastic.Apm.SqlClient.Tests/SqlClientDiagnosticListenerUnitTests.cs index 3dd0303f6..65c117232 100644 --- a/test/instrumentations/Elastic.Apm.SqlClient.Tests/SqlClientDiagnosticListenerUnitTests.cs +++ b/test/instrumentations/Elastic.Apm.SqlClient.Tests/SqlClientDiagnosticListenerUnitTests.cs @@ -370,6 +370,100 @@ public void SubscriptionDispose_ClearsPendingSpans_AndAbandonsThem() } #endif + /// + /// When the profiler's ADO.NET CallTarget integration already traces the command, its span is the current span while the + /// command executes. The diagnostic listener must not add a nested span for the very same command. + /// + [Theory] + [InlineData((short)InstrumentationFlag.SqlClient)] + [InlineData((short)InstrumentationFlag.AdoNet)] + [InlineData((short)InstrumentationFlag.EfCore)] + [InlineData((short)InstrumentationFlag.EfClassic)] + public void CommandBefore_UnderCompetingSpanForTheSameCommand_IsSkipped(short instrumentationFlag) + { + using var listener = new SqlClientDiagnosticListener(_apmAgent); + var operationId = Guid.NewGuid(); + using var command = CreateCommand(); + + var transaction = (Transaction)_apmAgent.Tracer.StartTransaction("transaction", "type"); + var competingSpan = transaction.StartSpanInternal(DbSpanCommon.GetDbSpanName(command), ApiConstants.TypeDb, + ApiConstants.SubtypeMssql, instrumentationFlag: (InstrumentationFlag)instrumentationFlag, isExitSpan: true); + + listener.OnNext(new KeyValuePair("Microsoft.Data.SqlClient.WriteCommandBefore", + new { OperationId = operationId, Command = command })); + listener.PendingSpanCount.Should().Be(0); + + listener.OnNext(new KeyValuePair("Microsoft.Data.SqlClient.WriteCommandAfter", + new { OperationId = operationId, Command = command })); + + competingSpan.End(); + transaction.End(); + + _payloadSender.Spans.Should().ContainSingle().Which.Id.Should().Be(competingSpan.Id); + } + + /// + /// A competing span only suppresses the command it describes. A command executing while an unrelated database span + /// is current must still be traced, otherwise concurrent commands on the same execution context are lost. + /// + [Fact] + public void CommandBefore_UnderCompetingSpanForAnotherCommand_CreatesSpan() + { + using var listener = new SqlClientDiagnosticListener(_apmAgent); + var operationId = Guid.NewGuid(); + using var command = CreateCommand(); + + var transaction = (Transaction)_apmAgent.Tracer.StartTransaction("transaction", "type"); + var competingSpan = transaction.StartSpanInternal("SELECT FROM SomethingElse", ApiConstants.TypeDb, + ApiConstants.SubtypeMssql, instrumentationFlag: InstrumentationFlag.AdoNet, isExitSpan: true); + + listener.OnNext(new KeyValuePair("Microsoft.Data.SqlClient.WriteCommandBefore", + new { OperationId = operationId, Command = command })); + listener.PendingSpanCount.Should().Be(1); + + listener.OnNext(new KeyValuePair("Microsoft.Data.SqlClient.WriteCommandAfter", + new { OperationId = operationId, Command = command })); + + competingSpan.End(); + transaction.End(); + + _payloadSender.Spans.Should().HaveCount(2); + _payloadSender.Spans.Should().Contain(s => s.Id == competingSpan.Id); + _payloadSender.Spans.Should().Contain(s => s.Name == DbSpanCommon.GetDbSpanName(command) && s.Id != competingSpan.Id); + } + + /// + /// Only the modules that trace the very same command compete. Any other current span, including one started by the + /// application itself, must not stop the command from being traced. + /// + [Theory] + [InlineData((short)InstrumentationFlag.None)] + [InlineData((short)InstrumentationFlag.HttpClient)] + [InlineData((short)InstrumentationFlag.AspNetCore)] + public void CommandBefore_UnderNonCompetingSpan_CreatesSpan(short instrumentationFlag) + { + using var listener = new SqlClientDiagnosticListener(_apmAgent); + var operationId = Guid.NewGuid(); + using var command = CreateCommand(); + + var transaction = (Transaction)_apmAgent.Tracer.StartTransaction("transaction", "type"); + var currentSpan = transaction.StartSpanInternal(DbSpanCommon.GetDbSpanName(command), ApiConstants.TypeExternal, + instrumentationFlag: (InstrumentationFlag)instrumentationFlag); + + listener.OnNext(new KeyValuePair("Microsoft.Data.SqlClient.WriteCommandBefore", + new { OperationId = operationId, Command = command })); + listener.PendingSpanCount.Should().Be(1); + + listener.OnNext(new KeyValuePair("Microsoft.Data.SqlClient.WriteCommandAfter", + new { OperationId = operationId, Command = command })); + + currentSpan.End(); + transaction.End(); + + _payloadSender.Spans.Should().HaveCount(2); + _payloadSender.Spans.Should().ContainSingle(s => s.Type == ApiConstants.TypeDb); + } + public void Dispose() => _apmAgent.Dispose(); /// diff --git a/test/instrumentations/Elastic.Apm.SqlClient.Tests/SqlEventListenerUnitTests.cs b/test/instrumentations/Elastic.Apm.SqlClient.Tests/SqlEventListenerUnitTests.cs new file mode 100644 index 000000000..478f70d97 --- /dev/null +++ b/test/instrumentations/Elastic.Apm.SqlClient.Tests/SqlEventListenerUnitTests.cs @@ -0,0 +1,185 @@ +// Licensed to Elasticsearch B.V under one or more agreements. +// Elasticsearch B.V licenses this file to you under the Apache 2.0 License. +// See the LICENSE file in the project root for more information + +using System; +using Elastic.Apm.Api; +using Elastic.Apm.Instrumentations.SqlClient; +using Elastic.Apm.Model; +using Elastic.Apm.Tests.Utilities; +using FluentAssertions; +using Xunit; + +namespace Elastic.Apm.SqlClient.Tests +{ + /// + /// Unit tests for which drive the SqlClient EventSource payloads directly, + /// without requiring a SQL Server instance. + /// + public class SqlEventListenerUnitTests : IDisposable + { + private const int BeginExecuteEventId = 1; + private const int EndExecuteEventId = 2; + + // composite state bits written by SqlClient: 1 = success, 2 = failure, 4 = synchronous + private const int SynchronousSuccess = 1 | 4; + private const int SynchronousFailure = 2 | 4; + + private readonly ApmAgent _apmAgent; + private readonly MockPayloadSender _payloadSender; + + public SqlEventListenerUnitTests() + { + _payloadSender = new MockPayloadSender(); + _apmAgent = new ApmAgent(new TestAgentComponents(payloadSender: _payloadSender, + configuration: new MockConfiguration(openTelemetryBridgeEnabled: "false"))); + } + + // BeginExecute payload: int objectId, string dataSource, string database, string commandText + private static object[] BeginExecute(int objectId, string commandText) => new object[] { objectId, "localhost", "mydb", commandText }; + + // EndExecute payload: int objectId, int compositeState, int sqlExceptionNumber + private static object[] EndExecute(int objectId, int compositeState = SynchronousSuccess, int sqlExceptionNumber = 0) => + new object[] { objectId, compositeState, sqlExceptionNumber }; + + [Fact] + public void BeginExecute_Then_EndExecute_ReportsSingleSpan() + { + using var listener = new SqlEventListener(_apmAgent); + + _apmAgent.Tracer.CaptureTransaction("transaction", "type", _ => + { + listener.HandleEvent(BeginExecuteEventId, BeginExecute(42, "SELECT getdate()")); + listener.HandleEvent(EndExecuteEventId, EndExecute(42)); + }); + + var span = _payloadSender.Spans.Should().ContainSingle().Which; + span.Name.Should().Be("SELECT getdate()"); + span.Type.Should().Be(ApiConstants.TypeDb); + span.Subtype.Should().Be(ApiConstants.SubtypeMssql); + span.Outcome.Should().Be(Outcome.Success); + span.Context.Db.Statement.Should().Be("SELECT getdate()"); + span.Context.Db.Instance.Should().Be("mydb"); + span.Duration.Should().BeGreaterThanOrEqualTo(0); + } + + /// + /// A SQL command is an exit span that never has legitimate children. Making it the current span would let the + /// competing-instrumentation check below mistake our own span for one created by another module. + /// + [Fact] + public void SqlSpan_IsNotMadeTheCurrentSpan() + { + using var listener = new SqlEventListener(_apmAgent); + + _apmAgent.Tracer.CaptureTransaction("transaction", "type", _ => + { + listener.HandleEvent(BeginExecuteEventId, BeginExecute(42, "SELECT getdate()")); + _apmAgent.Tracer.CurrentSpan.Should().BeNull(); + listener.HandleEvent(EndExecuteEventId, EndExecute(42)); + }); + + _payloadSender.Spans.Should().ContainSingle(); + } + + /// + /// When the command being executed is already traced by another module, the event listener must not add a nested span + /// for the same command. This is the case for Entity Framework (Core and 6) and for the profiler's ADO.NET CallTarget + /// integrations, whose span is the current span while the command executes. + /// + [Theory] + [InlineData((short)InstrumentationFlag.SqlClient)] + [InlineData((short)InstrumentationFlag.AdoNet)] + [InlineData((short)InstrumentationFlag.EfCore)] + [InlineData((short)InstrumentationFlag.EfClassic)] + public void BeginExecute_UnderCompetingDbSpan_DoesNotCreateNestedSpan(short instrumentationFlag) + { + using var listener = new SqlEventListener(_apmAgent); + + var transaction = (Transaction)_apmAgent.Tracer.StartTransaction("transaction", "type"); + var competingSpan = transaction.StartSpanInternal("SELECT getdate()", ApiConstants.TypeDb, ApiConstants.SubtypeMssql, + instrumentationFlag: (InstrumentationFlag)instrumentationFlag, isExitSpan: true); + + listener.HandleEvent(BeginExecuteEventId, BeginExecute(42, "SELECT getdate()")); + listener.HandleEvent(EndExecuteEventId, EndExecute(42)); + + competingSpan.End(); + transaction.End(); + + _payloadSender.Spans.Should().ContainSingle().Which.Id.Should().Be(competingSpan.Id); + } + + /// + /// Only the modules that trace the very same command compete. Any other current span, including one started by the + /// application itself, must not stop the command from being traced. + /// + [Theory] + [InlineData((short)InstrumentationFlag.None)] + [InlineData((short)InstrumentationFlag.HttpClient)] + [InlineData((short)InstrumentationFlag.AspNetCore)] + public void BeginExecute_UnderNonCompetingSpan_CreatesSpan(short instrumentationFlag) + { + using var listener = new SqlEventListener(_apmAgent); + + var transaction = (Transaction)_apmAgent.Tracer.StartTransaction("transaction", "type"); + var currentSpan = transaction.StartSpanInternal("SELECT getdate()", ApiConstants.TypeExternal, + instrumentationFlag: (InstrumentationFlag)instrumentationFlag); + + listener.HandleEvent(BeginExecuteEventId, BeginExecute(42, "SELECT getdate()")); + listener.HandleEvent(EndExecuteEventId, EndExecute(42)); + + currentSpan.End(); + transaction.End(); + + _payloadSender.Spans.Should().HaveCount(2); + _payloadSender.Spans.Should().ContainSingle(s => s.Type == ApiConstants.TypeDb && s.ParentId == currentSpan.Id); + } + + [Fact] + public void EventWithoutPayload_IsIgnored() + { + using var listener = new SqlEventListener(_apmAgent); + + _apmAgent.Tracer.CaptureTransaction("transaction", "type", _ => + { + var act = () => listener.HandleEvent(BeginExecuteEventId, null); + act.Should().NotThrow(); + }); + + _payloadSender.Spans.Should().BeEmpty(); + } + + [Fact] + public void EndExecute_WithoutBeginExecute_IsIgnored() + { + using var listener = new SqlEventListener(_apmAgent); + + _apmAgent.Tracer.CaptureTransaction("transaction", "type", _ => + { + var act = () => listener.HandleEvent(EndExecuteEventId, EndExecute(42)); + act.Should().NotThrow(); + }); + + _payloadSender.Spans.Should().BeEmpty(); + } + + [Fact] + public void EndExecute_WithSqlException_ReportsFailureAndError() + { + using var listener = new SqlEventListener(_apmAgent); + + _apmAgent.Tracer.CaptureTransaction("transaction", "type", _ => + { + listener.HandleEvent(BeginExecuteEventId, BeginExecute(42, "SELECT getdate()")); + listener.HandleEvent(EndExecuteEventId, EndExecute(42, SynchronousFailure, 547)); + }); + + var span = _payloadSender.Spans.Should().ContainSingle().Which; + span.Outcome.Should().Be(Outcome.Failure); + _payloadSender.WaitForErrors(); + _payloadSender.Errors.Should().ContainSingle(); + } + + public void Dispose() => _apmAgent.Dispose(); + } +}