diff --git a/src/OpenTelemetry.Instrumentation.SqlClient/CHANGELOG.md b/src/OpenTelemetry.Instrumentation.SqlClient/CHANGELOG.md index 244489dff9..8a45888983 100644 --- a/src/OpenTelemetry.Instrumentation.SqlClient/CHANGELOG.md +++ b/src/OpenTelemetry.Instrumentation.SqlClient/CHANGELOG.md @@ -53,6 +53,16 @@ * **Breaking change**: The `SetDbStatementForStoredProcedure` option has been removed. ([#TBD](https://github.com/open-telemetry/opentelemetry-dotnet-contrib/pull/TBD)) +* Add support for metric `db.client.operation.duration` + from [new database semantic conventions](https://github.com/open-telemetry/semantic-conventions/blob/v1.28.0/docs/database/database-metrics.md#metric-dbclientoperationduration) + on .NET 8+. + ([#2309](https://github.com/open-telemetry/opentelemetry-dotnet-contrib/pull/2309)) +* Add support for metric `db.client.operation.duration` + from [new database semantic conventions](https://github.com/open-telemetry/semantic-conventions/blob/v1.28.0/docs/database/database-metrics.md#metric-dbclientoperationduration) + on .NET Framework. + ([#2311](https://github.com/open-telemetry/opentelemetry-dotnet-contrib/pull/2311)) + * Only the following attributes are available when a trace is not captured: + `db.system`, `db.response.status_code`, and `error.type` * Updated OpenTelemetry core component version(s) to `1.10.0`. ([#2317](https://github.com/open-telemetry/opentelemetry-dotnet-contrib/pull/2317)) diff --git a/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlActivitySourceHelper.cs b/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlActivitySourceHelper.cs index d2e362fa63..01cde6bd66 100644 --- a/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlActivitySourceHelper.cs +++ b/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlActivitySourceHelper.cs @@ -30,6 +30,18 @@ internal sealed class SqlActivitySourceHelper "s", "Duration of database client operations."); + internal static readonly string[] SharedTagNames = + [ + SemanticConventions.AttributeDbSystem, + SemanticConventions.AttributeDbCollectionName, + SemanticConventions.AttributeDbNamespace, + SemanticConventions.AttributeDbResponseStatusCode, + SemanticConventions.AttributeDbOperationName, + SemanticConventions.AttributeErrorType, + SemanticConventions.AttributeServerPort, + SemanticConventions.AttributeServerAddress, + ]; + public static TagList GetTagListFromConnectionInfo(string? dataSource, string? databaseName, SqlClientTraceInstrumentationOptions options, out string activityName) { activityName = MicrosoftSqlServerDatabaseSystemName; @@ -97,4 +109,14 @@ public static TagList GetTagListFromConnectionInfo(string? dataSource, string? d return tags; } + + internal static double CalculateDurationFromTimestamp(long begin, long? end = null) + { + end = end ?? Stopwatch.GetTimestamp(); + var timestampToTicks = TimeSpan.TicksPerSecond / (double)Stopwatch.Frequency; + var delta = end - begin; + var ticks = (long)(timestampToTicks * delta); + var duration = new TimeSpan(ticks); + return duration.TotalSeconds; + } } diff --git a/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlClientDiagnosticListener.cs b/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlClientDiagnosticListener.cs index 1478cca3ff..3695f7424d 100644 --- a/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlClientDiagnosticListener.cs +++ b/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlClientDiagnosticListener.cs @@ -26,18 +26,6 @@ internal sealed class SqlClientDiagnosticListener : ListenerHandler public const string SqlDataWriteCommandError = "System.Data.SqlClient.WriteCommandError"; public const string SqlMicrosoftWriteCommandError = "Microsoft.Data.SqlClient.WriteCommandError"; - private static readonly string[] SharedTagNames = - [ - SemanticConventions.AttributeDbSystem, - SemanticConventions.AttributeDbCollectionName, - SemanticConventions.AttributeDbNamespace, - SemanticConventions.AttributeDbResponseStatusCode, - SemanticConventions.AttributeDbOperationName, - SemanticConventions.AttributeErrorType, - SemanticConventions.AttributeServerPort, - SemanticConventions.AttributeServerAddress, - ]; - private readonly PropertyFetcher commandFetcher = new("Command"); private readonly PropertyFetcher connectionFetcher = new("Connection"); private readonly PropertyFetcher dataSourceFetcher = new("DataSource"); @@ -257,7 +245,7 @@ private void RecordDuration(Activity? activity, object? payload, bool hasError = if (activity != null && activity.IsAllDataRequested) { - foreach (var name in SharedTagNames) + foreach (var name in SqlActivitySourceHelper.SharedTagNames) { var value = activity.GetTagItem(name); if (value != null) @@ -310,19 +298,9 @@ private void RecordDuration(Activity? activity, object? payload, bool hasError = } } - var duration = activity?.Duration.TotalSeconds ?? this.CalculateDurationFromTimestamp(); + var duration = activity?.Duration.TotalSeconds + ?? SqlActivitySourceHelper.CalculateDurationFromTimestamp(this.beginTimestamp.Value); SqlActivitySourceHelper.DbClientOperationDuration.Record(duration, tags); } - - private double CalculateDurationFromTimestamp() - { - var timestampToTicks = TimeSpan.TicksPerSecond / (double)Stopwatch.Frequency; - var begin = this.beginTimestamp.Value; - var end = Stopwatch.GetTimestamp(); - var delta = end - begin; - var ticks = (long)(timestampToTicks * delta); - var duration = new TimeSpan(ticks); - return duration.TotalSeconds; - } } #endif diff --git a/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlEventSourceListener.netfx.cs b/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlEventSourceListener.netfx.cs index 329aa8e184..f58f97cd2d 100644 --- a/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlEventSourceListener.netfx.cs +++ b/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlEventSourceListener.netfx.cs @@ -29,6 +29,7 @@ internal sealed class SqlEventSourceListener : EventListener internal const int BeginExecuteEventId = 1; internal const int EndExecuteEventId = 2; + private readonly AsyncLocal beginTimestamp = new(); private EventSource? adoNetEventSource; private EventSource? mdsEventSource; @@ -82,6 +83,29 @@ protected override void OnEventWritten(EventWrittenEventArgs eventData) } } + private static (bool HasError, string? ErrorNumber, string? ExceptionType) ExtractErrorFromEvent(EventWrittenEventArgs eventData) + { + var compositeState = (int)eventData.Payload[1]; + + if ((compositeState & 0b001) != 0b001) + { + if ((compositeState & 0b010) == 0b010) + { + var errorNumber = $"{eventData.Payload[2]}"; + var exceptionType = eventData.EventSource.Name == MdsEventSourceName + ? "Microsoft.Data.SqlClient.SqlException" + : "System.Data.SqlClient.SqlException"; + return (true, errorNumber, exceptionType); + } + else + { + return (true, null, null); + } + } + + return (false, null, null); + } + private void OnBeginExecute(EventWrittenEventArgs eventData) { /* @@ -100,7 +124,7 @@ private void OnBeginExecute(EventWrittenEventArgs eventData) (https://github.com/dotnet/SqlClient/blob/f4568ce68da21db3fe88c0e72e1287368aaa1dc8/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlCommand.cs#L6641) */ - if (SqlClientInstrumentation.TracingHandles == 0) + if (SqlClientInstrumentation.TracingHandles == 0 && SqlClientInstrumentation.MetricHandles == 0) { return; } @@ -125,6 +149,7 @@ private void OnBeginExecute(EventWrittenEventArgs eventData) if (activity == null) { // There is no listener or it decided not to sample the current request. + this.beginTimestamp.Value = Stopwatch.GetTimestamp(); return; } @@ -155,7 +180,7 @@ private void OnEndExecute(EventWrittenEventArgs eventData) [2] -> SqlExceptionNumber */ - if (SqlClientInstrumentation.TracingHandles == 0) + if (SqlClientInstrumentation.TracingHandles == 0 && SqlClientInstrumentation.MetricHandles == 0) { return; } @@ -166,6 +191,12 @@ private void OnEndExecute(EventWrittenEventArgs eventData) return; } + if (SqlClientInstrumentation.TracingHandles == 0 && SqlClientInstrumentation.MetricHandles != 0) + { + this.RecordDuration(null, eventData); + return; + } + var activity = Activity.Current; if (activity?.Source != SqlActivitySourceHelper.ActivitySource) { @@ -176,18 +207,14 @@ private void OnEndExecute(EventWrittenEventArgs eventData) { if (activity.IsAllDataRequested) { - var compositeState = (int)eventData.Payload[1]; - if ((compositeState & 0b001) != 0b001) + var (hasError, errorNumber, exceptionType) = ExtractErrorFromEvent(eventData); + + if (hasError) { - if ((compositeState & 0b010) == 0b010) + if (errorNumber != null && exceptionType != null) { - var errorNumber = $"{eventData.Payload[2]}"; activity.SetStatus(ActivityStatusCode.Error, errorNumber); activity.SetTag(SemanticConventions.AttributeDbResponseStatusCode, errorNumber); - - var exceptionType = eventData.EventSource.Name == MdsEventSourceName - ? "Microsoft.Data.SqlClient.SqlException" - : "System.Data.SqlClient.SqlException"; activity.SetTag(SemanticConventions.AttributeErrorType, exceptionType); } else @@ -200,7 +227,49 @@ private void OnEndExecute(EventWrittenEventArgs eventData) finally { activity.Stop(); + this.RecordDuration(activity, eventData); + } + } + + private void RecordDuration(Activity? activity, EventWrittenEventArgs eventData) + { + if (SqlClientInstrumentation.MetricHandles == 0) + { + return; + } + + var tags = default(TagList); + + if (activity != null && activity.IsAllDataRequested) + { + foreach (var name in SqlActivitySourceHelper.SharedTagNames) + { + var value = activity.GetTagItem(name); + if (value != null) + { + tags.Add(name, value); + } + } + } + else + { + tags.Add(SemanticConventions.AttributeDbSystem, SqlActivitySourceHelper.MicrosoftSqlServerDatabaseSystemName); + + var (hasError, errorNumber, exceptionType) = ExtractErrorFromEvent(eventData); + + if (hasError) + { + if (errorNumber != null && exceptionType != null) + { + tags.Add(SemanticConventions.AttributeDbResponseStatusCode, errorNumber); + tags.Add(SemanticConventions.AttributeErrorType, exceptionType); + } + } } + + var duration = activity?.Duration.TotalSeconds + ?? SqlActivitySourceHelper.CalculateDurationFromTimestamp(this.beginTimestamp.Value); + SqlActivitySourceHelper.DbClientOperationDuration.Record(duration, tags); } } #endif diff --git a/test/OpenTelemetry.Instrumentation.SqlClient.Tests/SqlEventSourceTests.netfx.cs b/test/OpenTelemetry.Instrumentation.SqlClient.Tests/SqlEventSourceTests.netfx.cs index d91951692a..8d0c47d002 100644 --- a/test/OpenTelemetry.Instrumentation.SqlClient.Tests/SqlEventSourceTests.netfx.cs +++ b/test/OpenTelemetry.Instrumentation.SqlClient.Tests/SqlEventSourceTests.netfx.cs @@ -7,6 +7,7 @@ using System.Diagnostics; using System.Diagnostics.Tracing; using OpenTelemetry.Instrumentation.SqlClient.Implementation; +using OpenTelemetry.Metrics; using OpenTelemetry.Tests; using OpenTelemetry.Trace; using Xunit; @@ -27,6 +28,42 @@ To use Docker... private const string SqlConnectionStringEnvVarName = "OTEL_SQLCONNECTIONSTRING"; private static readonly string? SqlConnectionString = SkipUnlessEnvVarFoundTheoryAttribute.GetEnvironmentVariable(SqlConnectionStringEnvVarName); + public static IEnumerable EventSourceFakeTestCases() + { + /* netfx driver can't capture queries, only stored procedure names */ + /* always emit some attribute */ + var bools = new[] { true, false }; + return from eventSourceType in new[] { typeof(FakeBehavingAdoNetSqlEventSource), typeof(FakeBehavingMdsSqlEventSource) } + from commandType in new[] { CommandType.StoredProcedure, CommandType.Text } + from isFailure in bools + from captureText in bools + from enableConnectionLevelAttributes in bools + from emitOldAttributes in bools + from emitNewAttributes in bools + from tracingEnabled in bools + from metricsEnabled in bools + where !(commandType == CommandType.Text && captureText == true) + where emitOldAttributes != false && emitNewAttributes != false + let commandText = commandType == CommandType.Text + ? (isFailure == false ? "select 1/1" : "select 1/0") + : "sp_who" + let sqlExceptionNumber = 0 + select new object[] + { + eventSourceType, + commandType, + commandText, + captureText, + isFailure, + sqlExceptionNumber, + enableConnectionLevelAttributes, + emitOldAttributes, + emitNewAttributes, + tracingEnabled, + metricsEnabled, + }; + } + [Trait("CategoryName", "SqlIntegrationTests")] [SkipUnlessEnvVarFoundTheory(SqlConnectionStringEnvVarName)] [InlineData(CommandType.Text, "select 1/1", false)] @@ -75,34 +112,7 @@ public async Task SuccessfulCommandTest(CommandType commandType, string commandT } [Theory] - [InlineData(typeof(FakeBehavingAdoNetSqlEventSource), CommandType.Text, "select 1/1", false)] - [InlineData(typeof(FakeBehavingAdoNetSqlEventSource), CommandType.Text, "select 1/0", false, true)] - [InlineData(typeof(FakeBehavingAdoNetSqlEventSource), CommandType.StoredProcedure, "sp_who", false)] - [InlineData(typeof(FakeBehavingAdoNetSqlEventSource), CommandType.StoredProcedure, "sp_who", true, false, 0, true)] - [InlineData(typeof(FakeBehavingMdsSqlEventSource), CommandType.Text, "select 1/1", false)] - [InlineData(typeof(FakeBehavingMdsSqlEventSource), CommandType.Text, "select 1/0", false, true)] - [InlineData(typeof(FakeBehavingMdsSqlEventSource), CommandType.StoredProcedure, "sp_who", false)] - [InlineData(typeof(FakeBehavingMdsSqlEventSource), CommandType.StoredProcedure, "sp_who", true, false, 0, true)] - - // Test cases when EmitOldAttributes = false and EmitNewAttributes = true (i.e., OTEL_SEMCONV_STABILITY_OPT_IN=database) - [InlineData(typeof(FakeBehavingAdoNetSqlEventSource), CommandType.Text, "select 1/1", false, false, 0, false, false, true)] - [InlineData(typeof(FakeBehavingAdoNetSqlEventSource), CommandType.Text, "select 1/0", false, true, 0, false, false, true)] - [InlineData(typeof(FakeBehavingAdoNetSqlEventSource), CommandType.StoredProcedure, "sp_who", false, false, 0, false, false, true)] - [InlineData(typeof(FakeBehavingAdoNetSqlEventSource), CommandType.StoredProcedure, "sp_who", true, false, 0, true, false, true)] - [InlineData(typeof(FakeBehavingMdsSqlEventSource), CommandType.Text, "select 1/1", false, false, 0, false, false, true)] - [InlineData(typeof(FakeBehavingMdsSqlEventSource), CommandType.Text, "select 1/0", false, true, 0, false, false, true)] - [InlineData(typeof(FakeBehavingMdsSqlEventSource), CommandType.StoredProcedure, "sp_who", false, false, 0, false, false, true)] - [InlineData(typeof(FakeBehavingMdsSqlEventSource), CommandType.StoredProcedure, "sp_who", true, false, 0, true, false, true)] - - // Test cases when EmitOldAttributes = true and EmitNewAttributes = true (i.e., OTEL_SEMCONV_STABILITY_OPT_IN=database/dup) - [InlineData(typeof(FakeBehavingAdoNetSqlEventSource), CommandType.Text, "select 1/1", false, false, 0, false, true, true)] - [InlineData(typeof(FakeBehavingAdoNetSqlEventSource), CommandType.Text, "select 1/0", false, true, 0, false, true, true)] - [InlineData(typeof(FakeBehavingAdoNetSqlEventSource), CommandType.StoredProcedure, "sp_who", false, false, 0, false, true, true)] - [InlineData(typeof(FakeBehavingAdoNetSqlEventSource), CommandType.StoredProcedure, "sp_who", true, false, 0, true, true, true)] - [InlineData(typeof(FakeBehavingMdsSqlEventSource), CommandType.Text, "select 1/1", false, false, 0, false, true, true)] - [InlineData(typeof(FakeBehavingMdsSqlEventSource), CommandType.Text, "select 1/0", false, true, 0, false, true, true)] - [InlineData(typeof(FakeBehavingMdsSqlEventSource), CommandType.StoredProcedure, "sp_who", false, false, 0, false, true, true)] - [InlineData(typeof(FakeBehavingMdsSqlEventSource), CommandType.StoredProcedure, "sp_who", true, false, 0, true, true, true)] + [MemberData(nameof(EventSourceFakeTestCases))] public void EventSourceFakeTests( Type eventSourceType, CommandType commandType, @@ -112,45 +122,104 @@ public void EventSourceFakeTests( int sqlExceptionNumber = 0, bool enableConnectionLevelAttributes = false, bool emitOldAttributes = true, - bool emitNewAttributes = false) + bool emitNewAttributes = false, + bool tracingEnabled = true, + bool metricsEnabled = true) { using var fakeSqlEventSource = (IFakeBehavingSqlEventSource)Activator.CreateInstance(eventSourceType); - var exportedItems = new List(); - using var shutdownSignal = Sdk.CreateTracerProviderBuilder() - .AddInMemoryExporter(exportedItems) - .AddSqlClientInstrumentation(options => - { - options.SetDbStatementForText = captureText; - options.EnableConnectionLevelAttributes = enableConnectionLevelAttributes; - options.EmitOldAttributes = emitOldAttributes; - options.EmitNewAttributes = emitNewAttributes; - }) - .Build(); + var activities = new List(); + var metrics = new List(); - var objectId = Guid.NewGuid().GetHashCode(); + var traceProviderBuilder = Sdk.CreateTracerProviderBuilder(); + if (tracingEnabled) + { + traceProviderBuilder.AddInMemoryExporter(activities) + .AddSqlClientInstrumentation(options => + { + options.SetDbStatementForText = captureText; + options.EnableConnectionLevelAttributes = enableConnectionLevelAttributes; + options.EmitOldAttributes = emitOldAttributes; + options.EmitNewAttributes = emitNewAttributes; + }); + } + + var meterProviderBuilder = Sdk.CreateMeterProviderBuilder(); + + if (metricsEnabled) + { + meterProviderBuilder.AddInMemoryExporter(metrics) + .AddSqlClientInstrumentation(); + } + + using var traceProvider = traceProviderBuilder.Build(); + using var meterProvider = meterProviderBuilder.Build(); + + var objectId = Guid.NewGuid().GetHashCode(); var dataSource = "127.0.0.1\\instanceName,port"; - fakeSqlEventSource.WriteBeginExecuteEvent(objectId, dataSource, "master", commandType == CommandType.StoredProcedure ? commandText : string.Empty); - // success is stored in the first bit in compositeState 0b001 - var successFlag = !isFailure ? 1 : 0; + try + { + fakeSqlEventSource.WriteBeginExecuteEvent(objectId, dataSource, "master", commandType == CommandType.StoredProcedure ? commandText : string.Empty); - // isSqlException is stored in the second bit in compositeState 0b010 - var isSqlExceptionFlag = sqlExceptionNumber > 0 ? 2 : 0; + // success is stored in the first bit in compositeState 0b001 + var successFlag = !isFailure ? 1 : 0; - // synchronous state is stored in the third bit in compositeState 0b100 - var synchronousFlag = false ? 4 : 0; + // isSqlException is stored in the second bit in compositeState 0b010 + var isSqlExceptionFlag = sqlExceptionNumber > 0 ? 2 : 0; - var compositeState = successFlag | isSqlExceptionFlag | synchronousFlag; + // synchronous state is stored in the third bit in compositeState 0b100 + var synchronousFlag = false ? 4 : 0; - fakeSqlEventSource.WriteEndExecuteEvent(objectId, compositeState, sqlExceptionNumber); - shutdownSignal.Dispose(); - Assert.Single(exportedItems); + var compositeState = successFlag | isSqlExceptionFlag | synchronousFlag; - var activity = exportedItems[0]; + fakeSqlEventSource.WriteEndExecuteEvent(objectId, compositeState, sqlExceptionNumber); + } + finally + { + traceProvider.Dispose(); + Assert.True(meterProvider.ForceFlush()); + } + + Activity? activity = null; + + if (tracingEnabled) + { + activity = Assert.Single(activities); + VerifyActivityData(commandText, captureText, isFailure, dataSource, activity, enableConnectionLevelAttributes, emitOldAttributes, emitNewAttributes); + } + + var dbClientOperationDurationMetrics = metrics + .Where(metric => metric.Name == "db.client.operation.duration") + .ToArray(); - VerifyActivityData(commandText, captureText, isFailure, dataSource, activity, enableConnectionLevelAttributes, emitOldAttributes, emitNewAttributes); + if (metricsEnabled) + { + var metric = Assert.Single(dbClientOperationDurationMetrics); + Assert.NotNull(metric); + Assert.Equal("s", metric.Unit); + Assert.Equal(MetricType.Histogram, metric.MetricType); + + var metricPoints = new List(); + foreach (var p in metric.GetMetricPoints()) + { + metricPoints.Add(p); + } + + var metricPoint = Assert.Single(metricPoints); + + if (activity != null) + { + var count = metricPoint.GetHistogramCount(); + var sum = metricPoint.GetHistogramSum(); + Assert.Equal(activity.Duration.TotalSeconds, sum); + } + } + else + { + Assert.Empty(dbClientOperationDurationMetrics); + } } [Theory] @@ -323,7 +392,6 @@ private static void VerifyActivityData( } #pragma warning disable SA1201 // Elements should appear in the correct order - // Helper interface to be able to have single test method for multiple EventSources, want to keep it close to the event sources themselves. private interface IFakeBehavingSqlEventSource : IDisposable #pragma warning restore SA1201 // Elements should appear in the correct order