Database query time in span is calculated incorrectly

[kbalys (Konrad Bałys)]

Hi,

when I am using APM agent with Dapper I think the execution time for sql query is calculated incorrectly.

APM Server version: 7.13.3

APM Agent language and version: dotnet core 1.7.1

Description of the problem including expected versus actual behavior. Please include screenshots (if relevant): Executing sql query does not contain time when reading from stream.

Steps to reproduce:

1. Execute query which contains multiple results sets.
2. Query is executed on dapper which db connection is based on standards .net core libraries
3. SQL execution query time does not include time when reading the stream. It only takes into account parsing and submitting the query (I think).

Sample SQL Query placed in apm-agent-dotnet/ValuesController.cs at master · elastic/apm-agent-dotnet · GitHub

                [HttpGet("poc")]
		public async Task<ActionResult<string>> Poc()
		{
			using var dbConnection = new SqlConnection("<connection_string>");
			using var multi = await dbConnection.QueryMultipleAsync(@"
				WAITFOR DELAY '00:00:05'
				SELECT 1

				WAITFOR DELAY '00:00:05'

				SELECT 2

				WAITFOR DELAY '00:00:05'

				SELECT 3");

			var one = await multi.ReadFirstAsync<int>();
			var two = await multi.ReadFirstAsync<int>();
			var three = await multi.ReadFirstAsync<int>();

			return $"POC Hello World! {one}, {two}, {three}";
		}

Please see below span.

Project references:

    <PackageReference Include="Dapper" Version="2.0.35" />
    <PackageReference Include="Microsoft.Data.SqlClient" Version="3.0.0" />

[forloop (Russ Cam)]

Hi @kbalys,

The instrumentation for SqlClient uses SQL diagnostic events on .NET Core and .NET 5, and SQL event sources on .NET Framework.

In both cases, a DB span is started when the before SQL Command executed event is raised, and ended when the after SQL Command executed event is raised. So the captured DB span won't include read time. It'd be possible however to capture the reads in a span with something like the following

namespace WebApiSample.Controllers
{
	[Route("api/[controller]")]
	[ApiController]
	public class ValuesController : ControllerBase
	{
		private ITracer _tracer;

		// inject APM agent tracer via DI
		public ValuesController(ITracer tracer) => _tracer;               

        [HttpGet("poc")]
		public async Task<ActionResult<string>> Poc()
		{
			using var dbConnection = new SqlConnection("<connection_string>");
			using var multi = await dbConnection.QueryMultipleAsync(@"
				WAITFOR DELAY '00:00:05'
				SELECT 1

				WAITFOR DELAY '00:00:05'

				SELECT 2

				WAITFOR DELAY '00:00:05'

				SELECT 3");

			return await _tracer.CurrentTransaction.CaptureSpan("DB read", ApiConstants.TypeDb, async () => {
			    var one = await multi.ReadFirstAsync<int>();
			    var two = await multi.ReadFirstAsync<int>();
			    var three = await multi.ReadFirstAsync<int>();

			    return $"POC Hello World! {one}, {two}, {three}";
			}, "read");                       

		}
	}
}