SQL connection creation duration tracking (#9086)

agr · web-flow · commit cef94bf0b88f · 2022-04-08T15:56:45.000-07:00
* Methods for tracking Sql connection creation duration.

* Reporting new metric

* Reporting milliseconds for create sql connection duration.

* Better check for all event names.
Testing both sync and async SQL creation duration metric
diff --git a/src/GitHubVulnerabilities2Db/Gallery/ThrowingTelemetryService.cs b/src/GitHubVulnerabilities2Db/Gallery/ThrowingTelemetryService.cs
@@ -390,5 +390,15 @@ public void TrackVulnerabilitiesCacheRefreshDuration(TimeSpan duration)
         {
             throw new NotImplementedException();
         }
+
+        public IDisposable TrackSyncSqlConnectionCreationDuration()
+        {
+            throw new NotImplementedException();
+        }
+
+        public IDisposable TrackAsyncSqlConnectionCreationDuration()
+        {
+            throw new NotImplementedException();
+        }
     }
 }
diff --git a/src/NuGetGallery.Services/NuGetGallery.Services.csproj b/src/NuGetGallery.Services/NuGetGallery.Services.csproj
@@ -242,6 +242,7 @@
     <Compile Include="SupportRequest\Models\ISupportRequestDbContext.cs" />
     <Compile Include="SupportRequest\Models\SupportRequestDbContext.cs" />
     <Compile Include="SupportRequest\SupportRequestService.cs" />
+    <Compile Include="Telemetry\DurationMetric.cs" />
     <Compile Include="Telemetry\ITelemetryClient.cs" />
     <Compile Include="Telemetry\ITelemetryService.cs" />
     <Compile Include="Telemetry\Obfuscator.cs" />
diff --git a/src/NuGetGallery.Services/Telemetry/DurationMetric.cs b/src/NuGetGallery.Services/Telemetry/DurationMetric.cs
@@ -0,0 +1,24 @@
+﻿// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
+
+using System;
+using System.Diagnostics;
+
+namespace NuGetGallery
+{
+    public class DurationTracker : IDisposable
+    {
+        private readonly Stopwatch _timer;
+
+        private Action<TimeSpan> _trackAction;
+
+        public DurationTracker(
+            Action<TimeSpan> trackAction)
+        {
+            _trackAction = trackAction ?? throw new ArgumentNullException(nameof(trackAction));
+            _timer = Stopwatch.StartNew();
+        }
+
+        public void Dispose() => _trackAction(_timer.Elapsed);
+    }
+}
diff --git a/src/NuGetGallery.Services/Telemetry/ITelemetryService.cs b/src/NuGetGallery.Services/Telemetry/ITelemetryService.cs
@@ -424,5 +424,8 @@ void TrackABTestEvaluated(
         /// </summary>
         /// <param name="endpoint"></param>
         void TrackApiRequest(string endpoint);
+
+        IDisposable TrackSyncSqlConnectionCreationDuration();
+        IDisposable TrackAsyncSqlConnectionCreationDuration();
     }
 }
diff --git a/src/NuGetGallery.Services/Telemetry/TelemetryService.cs b/src/NuGetGallery.Services/Telemetry/TelemetryService.cs
@@ -19,7 +19,7 @@ namespace NuGetGallery
 {
     public class TelemetryService : ITelemetryService, IFeatureFlagTelemetryService
     {
-        public class Events
+        public static class Events
         {
             public const string ODataQueryFilter = "ODataQueryFilter";
             public const string ODataCustomQuery = "ODataCustomQuery";
@@ -95,6 +95,7 @@ public class Events
             public const string VulnerabilitiesCacheRefreshDurationMs = "VulnerabilitiesCacheRefreshDurationMs";
             public const string InstanceUptime = "InstanceUptimeInDays";
             public const string ApiRequest = "ApiRequest";
+            public const string CreateSqlConnectionDurationMs = "CreateSqlConnectionDurationMs";
         }
 
         private readonly IDiagnosticsSource _diagnosticsSource;
@@ -236,6 +237,10 @@ public class Events
 
         public const string Endpoint = "Endpoint";
 
+        public const string Kind = "Kind";
+        public const string Sync = "Sync";
+        public const string Async = "Async";
+
         public TelemetryService(IDiagnosticsSource diagnosticsSource, ITelemetryClient telemetryClient)
         {
             _telemetryClient = telemetryClient ?? throw new ArgumentNullException(nameof(telemetryClient));
@@ -1138,6 +1143,18 @@ public void TrackApiRequest(string endpoint)
             _telemetryClient.TrackAggregatedMetric(Events.ApiRequest, 1, Endpoint, endpoint);
         }
 
+        public IDisposable TrackSyncSqlConnectionCreationDuration()
+            => TrackSqlConnectionCreationDuration(Sync);
+
+        public IDisposable TrackAsyncSqlConnectionCreationDuration()
+            => TrackSqlConnectionCreationDuration(Async);
+
+        private IDisposable TrackSqlConnectionCreationDuration(string kind)
+        {
+            return new DurationTracker(duration => 
+                _telemetryClient.TrackAggregatedMetric(Events.CreateSqlConnectionDurationMs, duration.TotalMilliseconds, Kind, kind));
+        }
+
         /// <summary>
         /// We use <see cref="ITelemetryClient.TrackMetric(string, double, IDictionary{string, string})"/> instead of
         /// <see cref="ITelemetryClient.TrackEvent(string, IDictionary{string, string}, IDictionary{string, double})"/>
diff --git a/src/NuGetGallery/App_Start/DefaultDependenciesModule.cs b/src/NuGetGallery/App_Start/DefaultDependenciesModule.cs
@@ -192,7 +192,7 @@ protected override void Load(ContainerBuilder builder)
                 .As<ISqlConnectionFactory>()
                 .SingleInstance();
 
-            builder.Register(c => new EntitiesContext(CreateDbConnection(galleryDbConnectionFactory), configuration.Current.ReadOnlyMode))
+            builder.Register(c => new EntitiesContext(CreateDbConnection(galleryDbConnectionFactory, telemetryService), configuration.Current.ReadOnlyMode))
                 .AsSelf()
                 .As<IEntitiesContext>()
                 .As<DbContext>()
@@ -278,15 +278,15 @@ protected override void Load(ContainerBuilder builder)
                 .As<IEntityRepository<PackageRename>>()
                 .InstancePerLifetimeScope();
 
-            ConfigureGalleryReadOnlyReplicaEntitiesContext(builder, loggerFactory, configuration, secretInjector);
+            ConfigureGalleryReadOnlyReplicaEntitiesContext(builder, loggerFactory, configuration, secretInjector, telemetryService);
 
             var supportDbConnectionFactory = CreateDbConnectionFactory(
                 loggerFactory,
                 nameof(SupportRequestDbContext),
                 configuration.Current.SqlConnectionStringSupportRequest,
                 secretInjector);
 
-            builder.Register(c => new SupportRequestDbContext(CreateDbConnection(supportDbConnectionFactory)))
+            builder.Register(c => new SupportRequestDbContext(CreateDbConnection(supportDbConnectionFactory, telemetryService)))
                 .AsSelf()
                 .As<ISupportRequestDbContext>()
                 .InstancePerLifetimeScope();
@@ -503,7 +503,7 @@ protected override void Load(ContainerBuilder builder)
                     break;
             }
 
-            RegisterAsynchronousValidation(builder, loggerFactory, configuration, secretInjector);
+            RegisterAsynchronousValidation(builder, loggerFactory, configuration, secretInjector, telemetryService);
 
             RegisterAuditingServices(builder, configuration.Current.StorageType);
 
@@ -963,28 +963,35 @@ private static ISqlConnectionFactory CreateDbConnectionFactory(
             return new AzureSqlConnectionFactory(connectionString, secretInjector, logger);
         }
 
-        public static DbConnection CreateDbConnection(ISqlConnectionFactory connectionFactory)
+        public static DbConnection CreateDbConnection(ISqlConnectionFactory connectionFactory, ITelemetryService telemetryService)
         {
-            if (connectionFactory.TryCreate(out var connection))
+            using (telemetryService.TrackSyncSqlConnectionCreationDuration())
             {
-                return connection;
+                if (connectionFactory.TryCreate(out var connection))
+                {
+                    return connection;
+                }
+            }
+            using (telemetryService.TrackAsyncSqlConnectionCreationDuration())
+            {
+                return Task.Run(() => connectionFactory.CreateAsync()).Result;
             }
-            return Task.Run(() => connectionFactory.CreateAsync()).Result;
         }
 
         private static void ConfigureGalleryReadOnlyReplicaEntitiesContext(
             ContainerBuilder builder,
             ILoggerFactory loggerFactory,
             ConfigurationService configuration,
-            ICachingSecretInjector secretInjector)
+            ICachingSecretInjector secretInjector,
+            ITelemetryService telemetryService)
         {
             var galleryDbReadOnlyReplicaConnectionFactory = CreateDbConnectionFactory(
                 loggerFactory,
                 nameof(ReadOnlyEntitiesContext),
                 configuration.Current.SqlReadOnlyReplicaConnectionString ?? configuration.Current.SqlConnectionString,
                 secretInjector);
 
-            builder.Register(c => new ReadOnlyEntitiesContext(CreateDbConnection(galleryDbReadOnlyReplicaConnectionFactory)))
+            builder.Register(c => new ReadOnlyEntitiesContext(CreateDbConnection(galleryDbReadOnlyReplicaConnectionFactory, telemetryService)))
                 .As<IReadOnlyEntitiesContext>()
                 .InstancePerLifetimeScope();
 
@@ -997,15 +1004,16 @@ private static void ConfigureValidationEntitiesContext(
             ContainerBuilder builder,
             ILoggerFactory loggerFactory,
             ConfigurationService configuration,
-            ICachingSecretInjector secretInjector)
+            ICachingSecretInjector secretInjector,
+            ITelemetryService telemetryService)
         {
             var validationDbConnectionFactory = CreateDbConnectionFactory(
                 loggerFactory,
                 nameof(ValidationEntitiesContext),
                 configuration.Current.SqlConnectionStringValidation,
                 secretInjector);
 
-            builder.Register(c => new ValidationEntitiesContext(CreateDbConnection(validationDbConnectionFactory)))
+            builder.Register(c => new ValidationEntitiesContext(CreateDbConnection(validationDbConnectionFactory, telemetryService)))
                 .AsSelf()
                 .InstancePerLifetimeScope();
 
@@ -1026,7 +1034,8 @@ private void RegisterAsynchronousValidation(
             ContainerBuilder builder,
             ILoggerFactory loggerFactory,
             ConfigurationService configuration,
-            ICachingSecretInjector secretInjector)
+            ICachingSecretInjector secretInjector,
+            ITelemetryService telemetryService)
         {
             builder
                 .RegisterType<NuGet.Services.Validation.ServiceBusMessageSerializer>()
@@ -1052,7 +1061,7 @@ private void RegisterAsynchronousValidation(
 
             if (configuration.Current.AsynchronousPackageValidationEnabled)
             {
-                ConfigureValidationEntitiesContext(builder, loggerFactory, configuration, secretInjector);
+                ConfigureValidationEntitiesContext(builder, loggerFactory, configuration, secretInjector, telemetryService);
 
                 builder
                     .Register(c =>
diff --git a/src/VerifyMicrosoftPackage/Fakes/FakeTelemetryService.cs b/src/VerifyMicrosoftPackage/Fakes/FakeTelemetryService.cs
@@ -392,5 +392,15 @@ public void TrackVulnerabilitiesCacheRefreshDuration(TimeSpan duration)
         {
             throw new NotImplementedException();
         }
+
+        public IDisposable TrackSyncSqlConnectionCreationDuration()
+        {
+            throw new NotImplementedException();
+        }
+
+        public IDisposable TrackAsyncSqlConnectionCreationDuration()
+        {
+            throw new NotImplementedException();
+        }
     }
 }
diff --git a/tests/NuGetGallery.Facts/App_Start/DefaultDependenciesModuleFacts.cs b/tests/NuGetGallery.Facts/App_Start/DefaultDependenciesModuleFacts.cs
@@ -204,7 +204,7 @@ public void TriesSyncBeforeAsync()
                     .Setup(cf => cf.TryCreate(out It.Ref<SqlConnection>.IsAny))
                     .Returns(true);
 
-                DefaultDependenciesModule.CreateDbConnection(connectionFactoryMock.Object);
+                DefaultDependenciesModule.CreateDbConnection(connectionFactoryMock.Object, Mock.Of<ITelemetryService>());
                 connectionFactoryMock
                     .Verify(cf => cf.TryCreate(out It.Ref<SqlConnection>.IsAny), Times.Once);
                 connectionFactoryMock
@@ -222,7 +222,7 @@ public void FallsBackToAsyncIfSyncFails()
                     .Setup(cf => cf.CreateAsync())
                     .ReturnsAsync((SqlConnection)null);
 
-                DefaultDependenciesModule.CreateDbConnection(connectionFactoryMock.Object);
+                DefaultDependenciesModule.CreateDbConnection(connectionFactoryMock.Object, Mock.Of<ITelemetryService>());
                 connectionFactoryMock
                     .Verify(cf => cf.TryCreate(out It.Ref<SqlConnection>.IsAny), Times.Once);
                 connectionFactoryMock
diff --git a/tests/NuGetGallery.Facts/Services/TelemetryServiceFacts.cs b/tests/NuGetGallery.Facts/Services/TelemetryServiceFacts.cs
@@ -360,16 +360,31 @@ public static IEnumerable<object[]> TrackMetricNames_Data
                         (TrackAction)(s => s.TrackApiRequest("SomeEndpoint")),
                         true
                     };
+
+                    yield return new object[] { "CreateSqlConnectionDurationMs",
+                        (TrackAction)(s => s.TrackSyncSqlConnectionCreationDuration().Dispose()),
+                        true
+                    };
+
+                    yield return new object[] { "CreateSqlConnectionDurationMs",
+                        (TrackAction)(s => s.TrackAsyncSqlConnectionCreationDuration().Dispose()),
+                        true
+                    };
                 }
             }
 
             [Fact]
             public void TrackEventNamesIncludesAllEvents()
             {
-                var expectedCount = typeof(TelemetryService.Events).GetFields().Length;
-                var actualCount = TrackMetricNames_Data.Count();
+                var eventNames = typeof(TelemetryService.Events)
+                    .GetFields()
+                    .Where(f => f.IsLiteral && !f.IsInitOnly && f.FieldType == typeof(string))
+                    .Select(f => (string)f.GetValue(null))
+                    .ToList();
+
+                var testedNames = new HashSet<string>(TrackMetricNames_Data.Select(element => (string)element[0]));
 
-                Assert.Equal(expectedCount, actualCount);
+                Assert.All(eventNames, name => testedNames.Contains(name));
             }
 
             [Theory]

Original file line number	Diff line number	Diff line change
`@@ -390,5 +390,15 @@ public void TrackVulnerabilitiesCacheRefreshDuration(TimeSpan duration)`
`390`	`390`	`{`
`391`	`391`	`throw new NotImplementedException();`
`392`	`392`	`}`
	`393`	`+`
	`394`	`+ public IDisposable TrackSyncSqlConnectionCreationDuration()`
	`395`	`+ {`
	`396`	`+ throw new NotImplementedException();`
	`397`	`+ }`
	`398`	`+`
	`399`	`+ public IDisposable TrackAsyncSqlConnectionCreationDuration()`
	`400`	`+ {`
	`401`	`+ throw new NotImplementedException();`
	`402`	`+ }`
`393`	`403`	`}`
`394`	`404`	`}`
Original file line number	Diff line number	Diff line change
`@@ -424,5 +424,8 @@ void TrackABTestEvaluated(`
`424`	`424`	`/// </summary>`
`425`	`425`	`/// <param name="endpoint"></param>`
`426`	`426`	`void TrackApiRequest(string endpoint);`
	`427`	`+`
	`428`	`+ IDisposable TrackSyncSqlConnectionCreationDuration();`
	`429`	`+ IDisposable TrackAsyncSqlConnectionCreationDuration();`
`427`	`430`	`}`
`428`	`431`	`}`
Original file line number	Diff line number	Diff line change
`@@ -392,5 +392,15 @@ public void TrackVulnerabilitiesCacheRefreshDuration(TimeSpan duration)`
`392`	`392`	`{`
`393`	`393`	`throw new NotImplementedException();`
`394`	`394`	`}`
	`395`	`+`
	`396`	`+ public IDisposable TrackSyncSqlConnectionCreationDuration()`
	`397`	`+ {`
	`398`	`+ throw new NotImplementedException();`
	`399`	`+ }`
	`400`	`+`
	`401`	`+ public IDisposable TrackAsyncSqlConnectionCreationDuration()`
	`402`	`+ {`
	`403`	`+ throw new NotImplementedException();`
	`404`	`+ }`
`395`	`405`	`}`
`396`	`406`	`}`