From fa7d05ba1d5748cdce88e6146e5c847068d6229d Mon Sep 17 00:00:00 2001 From: Matthew Hensley Date: Fri, 8 Nov 2024 21:14:13 -0500 Subject: [PATCH 01/13] port duration meter, adjust main test --- .../SqlEventSourceListener.netfx.cs | 36 +++- .../SqlEventSourceTests.netfx.cs | 176 ++++++++++++------ 2 files changed, 156 insertions(+), 56 deletions(-) diff --git a/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlEventSourceListener.netfx.cs b/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlEventSourceListener.netfx.cs index 329aa8e184..e583254daf 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; @@ -100,7 +101,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 +126,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 +157,7 @@ private void OnEndExecute(EventWrittenEventArgs eventData) [2] -> SqlExceptionNumber */ - if (SqlClientInstrumentation.TracingHandles == 0) + if (SqlClientInstrumentation.TracingHandles == 0 && SqlClientInstrumentation.MetricHandles == 0) { return; } @@ -166,6 +168,12 @@ private void OnEndExecute(EventWrittenEventArgs eventData) return; } + if (SqlClientInstrumentation.TracingHandles == 0 && SqlClientInstrumentation.MetricHandles != 0) + { + this.RecordDuration(null, eventData.Payload); + return; + } + var activity = Activity.Current; if (activity?.Source != SqlActivitySourceHelper.ActivitySource) { @@ -200,7 +208,31 @@ private void OnEndExecute(EventWrittenEventArgs eventData) finally { activity.Stop(); + this.RecordDuration(activity, eventData.Payload); + } + } + + private void RecordDuration(Activity? activity, object? payload, bool hasError = false) + { + if (SqlClientInstrumentation.MetricHandles == 0) + { + return; } + + TagList tags = default; + var duration = activity?.Duration.TotalSeconds ?? this.CalculateDurationFromTimestamp(); + SqlActivitySourceHelper.DbClientOperationDuration.Record(duration); + } + + 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/test/OpenTelemetry.Instrumentation.SqlClient.Tests/SqlEventSourceTests.netfx.cs b/test/OpenTelemetry.Instrumentation.SqlClient.Tests/SqlEventSourceTests.netfx.cs index d91951692a..8cfa9d4a39 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; @@ -75,34 +76,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 +86,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(); + + if (metricsEnabled) + { + var metric = Assert.Single(dbClientOperationDurationMetrics); + Assert.NotNull(metric); + Assert.Equal("s", metric.Unit); + Assert.Equal(MetricType.Histogram, metric.MetricType); - VerifyActivityData(commandText, captureText, isFailure, dataSource, activity, enableConnectionLevelAttributes, emitOldAttributes, emitNewAttributes); + 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,6 +356,41 @@ private static void VerifyActivityData( } #pragma warning disable SA1201 // Elements should appear in the correct order + 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, + }; + } // 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 From 5076cc65b5dd1ade1904738f7180a338df2f5bf6 Mon Sep 17 00:00:00 2001 From: Matthew Hensley Date: Fri, 8 Nov 2024 21:44:55 -0500 Subject: [PATCH 02/13] copy tags from activity --- .../SqlEventSourceListener.netfx.cs | 29 +++++++++++++++++-- 1 file changed, 27 insertions(+), 2 deletions(-) diff --git a/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlEventSourceListener.netfx.cs b/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlEventSourceListener.netfx.cs index e583254daf..357b36cdcd 100644 --- a/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlEventSourceListener.netfx.cs +++ b/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlEventSourceListener.netfx.cs @@ -29,6 +29,18 @@ internal sealed class SqlEventSourceListener : EventListener internal const int BeginExecuteEventId = 1; internal const int EndExecuteEventId = 2; + private static readonly string[] SharedTagNames = + [ + SemanticConventions.AttributeDbSystem, + SemanticConventions.AttributeDbCollectionName, + SemanticConventions.AttributeDbNamespace, + SemanticConventions.AttributeDbResponseStatusCode, + SemanticConventions.AttributeDbOperationName, + SemanticConventions.AttributeErrorType, + SemanticConventions.AttributeServerPort, + SemanticConventions.AttributeServerAddress, + ]; + private readonly AsyncLocal beginTimestamp = new(); private EventSource? adoNetEventSource; private EventSource? mdsEventSource; @@ -219,9 +231,22 @@ private void RecordDuration(Activity? activity, object? payload, bool hasError = return; } - TagList tags = default; + var tags = default(TagList); + + if (activity != null && activity.IsAllDataRequested) + { + foreach (var name in SharedTagNames) + { + var value = activity.GetTagItem(name); + if (value != null) + { + tags.Add(name, value); + } + } + } + var duration = activity?.Duration.TotalSeconds ?? this.CalculateDurationFromTimestamp(); - SqlActivitySourceHelper.DbClientOperationDuration.Record(duration); + SqlActivitySourceHelper.DbClientOperationDuration.Record(duration, tags); } private double CalculateDurationFromTimestamp() From 54318e29b6c53e91e401c6a99d57f5a32ec8a806 Mon Sep 17 00:00:00 2001 From: Matthew Hensley Date: Fri, 8 Nov 2024 21:45:06 -0500 Subject: [PATCH 03/13] Record does not like empty TagList --- .../Implementation/SqlEventSourceListener.netfx.cs | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlEventSourceListener.netfx.cs b/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlEventSourceListener.netfx.cs index 357b36cdcd..b088c72c5c 100644 --- a/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlEventSourceListener.netfx.cs +++ b/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlEventSourceListener.netfx.cs @@ -244,6 +244,10 @@ private void RecordDuration(Activity? activity, object? payload, bool hasError = } } } + else + { + tags.Add(SemanticConventions.AttributeDbSystem, SqlActivitySourceHelper.MicrosoftSqlServerDatabaseSystemName); + } var duration = activity?.Duration.TotalSeconds ?? this.CalculateDurationFromTimestamp(); SqlActivitySourceHelper.DbClientOperationDuration.Record(duration, tags); From 130846029e5400b66cfa552fe752fdff8abf3b36 Mon Sep 17 00:00:00 2001 From: Matthew Hensley Date: Fri, 8 Nov 2024 22:17:58 -0500 Subject: [PATCH 04/13] reuse existing error extraction logic --- .../SqlEventSourceListener.netfx.cs | 52 +++++++++++++++---- 1 file changed, 41 insertions(+), 11 deletions(-) diff --git a/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlEventSourceListener.netfx.cs b/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlEventSourceListener.netfx.cs index b088c72c5c..1f2062bf7c 100644 --- a/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlEventSourceListener.netfx.cs +++ b/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlEventSourceListener.netfx.cs @@ -95,6 +95,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) { /* @@ -182,7 +205,7 @@ private void OnEndExecute(EventWrittenEventArgs eventData) if (SqlClientInstrumentation.TracingHandles == 0 && SqlClientInstrumentation.MetricHandles != 0) { - this.RecordDuration(null, eventData.Payload); + this.RecordDuration(null, eventData); return; } @@ -196,18 +219,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 @@ -220,11 +239,11 @@ private void OnEndExecute(EventWrittenEventArgs eventData) finally { activity.Stop(); - this.RecordDuration(activity, eventData.Payload); + this.RecordDuration(activity, eventData); } } - private void RecordDuration(Activity? activity, object? payload, bool hasError = false) + private void RecordDuration(Activity? activity, EventWrittenEventArgs eventData) { if (SqlClientInstrumentation.MetricHandles == 0) { @@ -247,6 +266,17 @@ private void RecordDuration(Activity? activity, object? payload, bool hasError = 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 ?? this.CalculateDurationFromTimestamp(); From db73b46f47763751695f2ebbcff8b1048f90c3e8 Mon Sep 17 00:00:00 2001 From: Matthew Hensley Date: Sun, 10 Nov 2024 21:06:00 -0500 Subject: [PATCH 05/13] CHANGELOG entry for db.client.operation.duration --- src/OpenTelemetry.Instrumentation.SqlClient/CHANGELOG.md | 3 +++ 1 file changed, 3 insertions(+) diff --git a/src/OpenTelemetry.Instrumentation.SqlClient/CHANGELOG.md b/src/OpenTelemetry.Instrumentation.SqlClient/CHANGELOG.md index d69cfbd959..0703d25342 100644 --- a/src/OpenTelemetry.Instrumentation.SqlClient/CHANGELOG.md +++ b/src/OpenTelemetry.Instrumentation.SqlClient/CHANGELOG.md @@ -47,6 +47,9 @@ ([#2277](https://github.com/open-telemetry/opentelemetry-dotnet-contrib/pull/2277)) * **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). + ([#2309](https://github.com/open-telemetry/opentelemetry-dotnet-contrib/pull/2309)) ## 1.9.0-beta.1 From 1a65afabb2ed15af60d54b2edded55aee25376be Mon Sep 17 00:00:00 2001 From: Matthew Hensley Date: Sun, 10 Nov 2024 21:08:09 -0500 Subject: [PATCH 06/13] clarify only available for .NET 8 and higher --- src/OpenTelemetry.Instrumentation.SqlClient/CHANGELOG.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/OpenTelemetry.Instrumentation.SqlClient/CHANGELOG.md b/src/OpenTelemetry.Instrumentation.SqlClient/CHANGELOG.md index 0703d25342..9abafe5e6a 100644 --- a/src/OpenTelemetry.Instrumentation.SqlClient/CHANGELOG.md +++ b/src/OpenTelemetry.Instrumentation.SqlClient/CHANGELOG.md @@ -48,7 +48,7 @@ * **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). + from [new database semantic conventions] on .NET 8+.(https://github.com/open-telemetry/semantic-conventions/blob/v1.28.0/docs/database/database-metrics.md#metric-dbclientoperationduration). ([#2309](https://github.com/open-telemetry/opentelemetry-dotnet-contrib/pull/2309)) ## 1.9.0-beta.1 From e6baad87899706a58ee086a1d5a0cfe8adcb7a75 Mon Sep 17 00:00:00 2001 From: Matthew Hensley Date: Sun, 10 Nov 2024 21:11:22 -0500 Subject: [PATCH 07/13] correct markdown --- src/OpenTelemetry.Instrumentation.SqlClient/CHANGELOG.md | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/src/OpenTelemetry.Instrumentation.SqlClient/CHANGELOG.md b/src/OpenTelemetry.Instrumentation.SqlClient/CHANGELOG.md index 9abafe5e6a..af83f617fa 100644 --- a/src/OpenTelemetry.Instrumentation.SqlClient/CHANGELOG.md +++ b/src/OpenTelemetry.Instrumentation.SqlClient/CHANGELOG.md @@ -48,7 +48,8 @@ * **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] on .NET 8+.(https://github.com/open-telemetry/semantic-conventions/blob/v1.28.0/docs/database/database-metrics.md#metric-dbclientoperationduration). + 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)) ## 1.9.0-beta.1 From 70c096fa5f73907d1ff16f3657717e0570ce9871 Mon Sep 17 00:00:00 2001 From: Matthew Hensley Date: Mon, 11 Nov 2024 19:30:27 -0500 Subject: [PATCH 08/13] netfx changelog / note --- src/OpenTelemetry.Instrumentation.SqlClient/CHANGELOG.md | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/src/OpenTelemetry.Instrumentation.SqlClient/CHANGELOG.md b/src/OpenTelemetry.Instrumentation.SqlClient/CHANGELOG.md index af83f617fa..34eb2242b6 100644 --- a/src/OpenTelemetry.Instrumentation.SqlClient/CHANGELOG.md +++ b/src/OpenTelemetry.Instrumentation.SqlClient/CHANGELOG.md @@ -51,6 +51,12 @@ 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` ## 1.9.0-beta.1 From d37bd126c339ac43d55c261ce93d452ea7afc09c Mon Sep 17 00:00:00 2001 From: Matthew Hensley Date: Mon, 11 Nov 2024 19:31:20 -0500 Subject: [PATCH 09/13] linter: trailing space --- src/OpenTelemetry.Instrumentation.SqlClient/CHANGELOG.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/OpenTelemetry.Instrumentation.SqlClient/CHANGELOG.md b/src/OpenTelemetry.Instrumentation.SqlClient/CHANGELOG.md index 34eb2242b6..f0725e7c15 100644 --- a/src/OpenTelemetry.Instrumentation.SqlClient/CHANGELOG.md +++ b/src/OpenTelemetry.Instrumentation.SqlClient/CHANGELOG.md @@ -53,7 +53,7 @@ ([#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. + 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` From bdffec5b2c2eb6a676b3a1dc35e11a94ae47fd14 Mon Sep 17 00:00:00 2001 From: Matthew Hensley Date: Tue, 12 Nov 2024 19:31:16 -0500 Subject: [PATCH 10/13] extract shared tag list --- .../Implementation/SqlActivitySourceHelper.cs | 12 ++++++++++++ .../Implementation/SqlClientDiagnosticListener.cs | 14 +------------- .../Implementation/SqlEventSourceListener.netfx.cs | 14 +------------- 3 files changed, 14 insertions(+), 26 deletions(-) diff --git a/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlActivitySourceHelper.cs b/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlActivitySourceHelper.cs index d2e362fa63..0a14da68c5 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; diff --git a/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlClientDiagnosticListener.cs b/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlClientDiagnosticListener.cs index c5d234550e..ec20b2e037 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) diff --git a/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlEventSourceListener.netfx.cs b/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlEventSourceListener.netfx.cs index 1f2062bf7c..9e4dfe821a 100644 --- a/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlEventSourceListener.netfx.cs +++ b/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlEventSourceListener.netfx.cs @@ -29,18 +29,6 @@ internal sealed class SqlEventSourceListener : EventListener internal const int BeginExecuteEventId = 1; internal const int EndExecuteEventId = 2; - private static readonly string[] SharedTagNames = - [ - SemanticConventions.AttributeDbSystem, - SemanticConventions.AttributeDbCollectionName, - SemanticConventions.AttributeDbNamespace, - SemanticConventions.AttributeDbResponseStatusCode, - SemanticConventions.AttributeDbOperationName, - SemanticConventions.AttributeErrorType, - SemanticConventions.AttributeServerPort, - SemanticConventions.AttributeServerAddress, - ]; - private readonly AsyncLocal beginTimestamp = new(); private EventSource? adoNetEventSource; private EventSource? mdsEventSource; @@ -254,7 +242,7 @@ private void RecordDuration(Activity? activity, EventWrittenEventArgs eventData) if (activity != null && activity.IsAllDataRequested) { - foreach (var name in SharedTagNames) + foreach (var name in SqlActivitySourceHelper.SharedTagNames) { var value = activity.GetTagItem(name); if (value != null) From ecb134e36ae86a900bdba943319778c423600a58 Mon Sep 17 00:00:00 2001 From: Matthew Hensley Date: Tue, 12 Nov 2024 19:47:00 -0500 Subject: [PATCH 11/13] extract CalculateDurationFromTimestamp, quick unit test --- .../Implementation/SqlActivitySourceHelper.cs | 10 ++++++++ .../SqlClientDiagnosticListener.cs | 14 ++--------- .../SqlEventSourceListener.netfx.cs | 14 ++--------- .../SqlActivitySourceHelperTests.cs | 24 +++++++++++++++++++ 4 files changed, 38 insertions(+), 24 deletions(-) create mode 100644 test/OpenTelemetry.Instrumentation.SqlClient.Tests/SqlActivitySourceHelperTests.cs diff --git a/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlActivitySourceHelper.cs b/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlActivitySourceHelper.cs index 0a14da68c5..01cde6bd66 100644 --- a/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlActivitySourceHelper.cs +++ b/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlActivitySourceHelper.cs @@ -109,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 ec20b2e037..af3189fbc8 100644 --- a/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlClientDiagnosticListener.cs +++ b/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlClientDiagnosticListener.cs @@ -298,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 9e4dfe821a..f58f97cd2d 100644 --- a/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlEventSourceListener.netfx.cs +++ b/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlEventSourceListener.netfx.cs @@ -267,19 +267,9 @@ private void RecordDuration(Activity? activity, EventWrittenEventArgs eventData) } } - 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/test/OpenTelemetry.Instrumentation.SqlClient.Tests/SqlActivitySourceHelperTests.cs b/test/OpenTelemetry.Instrumentation.SqlClient.Tests/SqlActivitySourceHelperTests.cs new file mode 100644 index 0000000000..9bf96b578c --- /dev/null +++ b/test/OpenTelemetry.Instrumentation.SqlClient.Tests/SqlActivitySourceHelperTests.cs @@ -0,0 +1,24 @@ +// Copyright The OpenTelemetry Authors +// SPDX-License-Identifier: Apache-2.0 + +using OpenTelemetry.Instrumentation.SqlClient.Implementation; +using Xunit; + +namespace OpenTelemetry.Instrumentation.SqlClient.Tests; + +public class SqlActivitySourceHelperTests +{ + [Fact] + public void ShouldCalculateDuration() + { + var epochStart = DateTimeOffset.FromUnixTimeSeconds(0); + var duration1 = SqlActivitySourceHelper.CalculateDurationFromTimestamp(epochStart.Ticks, epochStart.AddSeconds(10).Ticks); + Assert.Equal(10.0, duration1); + + var duration2 = SqlActivitySourceHelper.CalculateDurationFromTimestamp(epochStart.Ticks, epochStart.Ticks); + Assert.Equal(0.0, duration2); + + var duration3 = SqlActivitySourceHelper.CalculateDurationFromTimestamp(epochStart.Ticks, epochStart.AddMilliseconds(10).Ticks); + Assert.Equal(0.01, duration3); + } +} From 173da0aa76e540c22b8e83c7b233bbe023c945c5 Mon Sep 17 00:00:00 2001 From: Matthew Hensley Date: Tue, 12 Nov 2024 19:49:18 -0500 Subject: [PATCH 12/13] appease the linter --- .../SqlEventSourceTests.netfx.cs | 72 +++++++++---------- 1 file changed, 36 insertions(+), 36 deletions(-) diff --git a/test/OpenTelemetry.Instrumentation.SqlClient.Tests/SqlEventSourceTests.netfx.cs b/test/OpenTelemetry.Instrumentation.SqlClient.Tests/SqlEventSourceTests.netfx.cs index 8cfa9d4a39..8d0c47d002 100644 --- a/test/OpenTelemetry.Instrumentation.SqlClient.Tests/SqlEventSourceTests.netfx.cs +++ b/test/OpenTelemetry.Instrumentation.SqlClient.Tests/SqlEventSourceTests.netfx.cs @@ -28,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)] @@ -356,42 +392,6 @@ private static void VerifyActivityData( } #pragma warning disable SA1201 // Elements should appear in the correct order - 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, - }; - } - // 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 From f61fbecbfce27dee0e0dc0178a72653f2eddc995 Mon Sep 17 00:00:00 2001 From: Matthew Hensley Date: Wed, 13 Nov 2024 15:33:20 -0500 Subject: [PATCH 13/13] drop test for now --- .../SqlActivitySourceHelperTests.cs | 24 ------------------- 1 file changed, 24 deletions(-) delete mode 100644 test/OpenTelemetry.Instrumentation.SqlClient.Tests/SqlActivitySourceHelperTests.cs diff --git a/test/OpenTelemetry.Instrumentation.SqlClient.Tests/SqlActivitySourceHelperTests.cs b/test/OpenTelemetry.Instrumentation.SqlClient.Tests/SqlActivitySourceHelperTests.cs deleted file mode 100644 index 9bf96b578c..0000000000 --- a/test/OpenTelemetry.Instrumentation.SqlClient.Tests/SqlActivitySourceHelperTests.cs +++ /dev/null @@ -1,24 +0,0 @@ -// Copyright The OpenTelemetry Authors -// SPDX-License-Identifier: Apache-2.0 - -using OpenTelemetry.Instrumentation.SqlClient.Implementation; -using Xunit; - -namespace OpenTelemetry.Instrumentation.SqlClient.Tests; - -public class SqlActivitySourceHelperTests -{ - [Fact] - public void ShouldCalculateDuration() - { - var epochStart = DateTimeOffset.FromUnixTimeSeconds(0); - var duration1 = SqlActivitySourceHelper.CalculateDurationFromTimestamp(epochStart.Ticks, epochStart.AddSeconds(10).Ticks); - Assert.Equal(10.0, duration1); - - var duration2 = SqlActivitySourceHelper.CalculateDurationFromTimestamp(epochStart.Ticks, epochStart.Ticks); - Assert.Equal(0.0, duration2); - - var duration3 = SqlActivitySourceHelper.CalculateDurationFromTimestamp(epochStart.Ticks, epochStart.AddMilliseconds(10).Ticks); - Assert.Equal(0.01, duration3); - } -}