Fix SQL duplicate spans on .NET Framework with the profiler

src/Elastic.Apm/Api/SpanCount.cs

@@ -29,6 +29,17 @@ public class SpanCount
 
 		internal void IncrementDropped() => Interlocked.Increment(ref _dropped);
 
+		/// <summary>
+		/// Moves <paramref name="count" /> spans that were started but then discarded instead of being reported
+		/// (see <c>exit_span_min_duration</c>) from <see cref="Started" /> to <see cref="Dropped" />, so that
+		/// <see cref="Started" /> keeps reflecting the number of spans that are actually recorded.
+		/// </summary>
+		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() =>

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<string, object> 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));

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);
+		}
+
+		/// <summary>
+		/// Handles a SqlClient EventSource event. Separated from <see cref="OnEventWritten" /> so that it can be exercised
+		/// without an <see cref="EventSource" />.
+		/// </summary>
+		internal void HandleEvent(int eventId, IReadOnlyList<object> 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<object> 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<object> 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;
 			}
 

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
+{
+	/// <summary>
+	/// 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.
+	/// </summary>
+	internal static class CompetingInstrumentation
+	{
+		/// <summary>
+		/// Entity Framework Core and Entity Framework 6, which trace the command they hand to ADO.NET.
+		/// </summary>
+		private const InstrumentationFlag EntityFramework = InstrumentationFlag.EfCore | InstrumentationFlag.EfClassic;
+
+		/// <summary>
+		/// The profiler's ADO.NET CallTarget integrations, which flag their spans as
+		/// <see cref="InstrumentationFlag.SqlClient" /> (SqlCommand) or <see cref="InstrumentationFlag.AdoNet" /> (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.
+		/// </summary>
+		private const InstrumentationFlag AdoNetProfiler = InstrumentationFlag.SqlClient | InstrumentationFlag.AdoNet;
+
+		/// <summary>
+		/// For the SqlClient listeners: both Entity Framework and the profiler trace the very same command.
+		/// </summary>
+		internal static bool IsCommandTracedByOtherModule(IApmAgent agent, IDbCommand command = null) =>
+			IsCommandTracedBy(agent, EntityFramework | AdoNetProfiler, command);
+
+		/// <summary>
+		/// For the Entity Framework modules: the profiler's ADO.NET integrations trace the very same command.
+		/// </summary>
+		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);
+		}
+	}
+}

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