Add metric to track package backup durations (#682)

Package backups exceeding the expected duration may be causing message duplication in the Orchestrator. This adds more telemetry around package backups for future investigations.

Part of NuGet/NuGetGallery#6624

Author: loic-sharma

src/NuGet.Services.Validation.Orchestrator/Telemetry/ITelemetryService.cs

@@ -17,12 +17,19 @@ public interface ITelemetryService
         /// </summary>
         void TrackDurationToValidationSetCreation(TimeSpan duration);
 
+        /// <summary>
+        /// Track how long a package's backup takes.
+        /// </summary>
+        /// <param name="validationSet">The validation set that requested the backup.</param>
+        /// <returns>Reports the duration when disposed.</returns>
+        IDisposable TrackDurationToBackupPackage(PackageValidationSet validationSet);
+
         /// <summary>
         /// A counter metric emitted when a package changes package status. This metric is not emitted if package status
         /// does not change. This metric is emitted for revalidation if the terminal state changes.
         /// </summary>
         /// <param name="fromStatus">The status that the package moved from.</param>
-        /// <param name="toStatus">The status that the package moved tp.</param>
+        /// <param name="toStatus">The status that the package moved to.</param>
         void TrackPackageStatusChange(PackageStatus fromStatus, PackageStatus toStatus);
 
         /// <summary>

src/NuGet.Services.Validation.Orchestrator/Telemetry/TelemetryService.cs

@@ -16,6 +16,7 @@ public class TelemetryService : ITelemetryService, ISubscriptionProcessorTelemet
         private const string PackageCertificatesPrefix = "PackageCertificates.";
 
         private const string DurationToValidationSetCreationSeconds = OrchestratorPrefix + "DurationToValidationSetCreationSeconds";
+        private const string DurationToBackupPackageSeconds = OrchestratorPrefix + "DurationToBackupPackageSeconds";
         private const string PackageStatusChange = OrchestratorPrefix + "PackageStatusChange";
         private const string TotalValidationDurationSeconds = OrchestratorPrefix + "TotalValidationDurationSeconds";
         private const string SentValidationTakingTooLongMessage = OrchestratorPrefix + "SentValidationTakingTooLongMessage";
@@ -86,6 +87,18 @@ public void TrackDurationToValidationSetCreation(TimeSpan duration)
                 duration.TotalSeconds);
         }
 
+        public IDisposable TrackDurationToBackupPackage(PackageValidationSet validationSet)
+        {
+            return _telemetryClient.TrackDuration(
+                DurationToBackupPackageSeconds,
+                new Dictionary<string, string>
+                {
+                    { ValidationTrackingId, validationSet.ValidationTrackingId.ToString() },
+                    { PackageId, validationSet.PackageId },
+                    { NormalizedVersion, validationSet.PackageNormalizedVersion }
+                });
+        }
+
         public void TrackPackageStatusChange(PackageStatus fromStatus, PackageStatus toStatus)
         {
             _telemetryClient.TrackMetric(

src/NuGet.Services.Validation.Orchestrator/ValidationPackageFileService.cs

@@ -118,19 +118,22 @@ public Task CopyValidationPackageForValidationSetAsync(PackageValidationSet vali
 
         public async Task BackupPackageFileFromValidationSetPackageAsync(PackageValidationSet validationSet)
         {
-            _logger.LogInformation(
-                "Backing up package for validation set {ValidationTrackingId} ({PackageId} {PackageVersion}).",
-                validationSet.ValidationTrackingId,
-                validationSet.PackageId,
-                validationSet.PackageNormalizedVersion);
+            using (_telemetryService.TrackDurationToBackupPackage(validationSet))
+            {
+                _logger.LogInformation(
+                    "Backing up package for validation set {ValidationTrackingId} ({PackageId} {PackageVersion}).",
+                    validationSet.ValidationTrackingId,
+                    validationSet.PackageId,
+                    validationSet.PackageNormalizedVersion);
 
-            var packageUri = await GetPackageForValidationSetReadUriAsync(
-                validationSet,
-                DateTimeOffset.UtcNow.Add(AccessDuration));
+                var packageUri = await GetPackageForValidationSetReadUriAsync(
+                    validationSet,
+                    DateTimeOffset.UtcNow.Add(AccessDuration));
 
-            using (var packageStream = await _fileDownloader.DownloadAsync(packageUri, CancellationToken.None))
-            {
-                await StorePackageFileInBackupLocationAsync(validationSet, packageStream);
+                using (var packageStream = await _fileDownloader.DownloadAsync(packageUri, CancellationToken.None))
+                {
+                    await StorePackageFileInBackupLocationAsync(validationSet, packageStream);
+                }
             }
         }
 

tests/NuGet.Services.Validation.Orchestrator.Tests/TelemetryServiceFacts.cs

@@ -71,5 +71,48 @@ public void TrackDurationToHashPackage_TracksDuration()
 
             _telemetryClient.VerifyAll();
         }
+
+        [Fact]
+        public void TrackDurationToBackupPackage_TracksDuration()
+        {
+            // Arrange
+            var validationTrackingId = Guid.NewGuid();
+            var packageId = "a";
+            var normalizedVersion = "b";
+            var validationSet = new PackageValidationSet
+            {
+                ValidationTrackingId = validationTrackingId,
+                PackageId = packageId,
+                PackageNormalizedVersion = normalizedVersion
+            };
+
+            var expectedReturnValue = Mock.Of<IDisposable>();
+
+            _telemetryClient.Setup(
+                    x => x.TrackMetric(
+                        It.IsNotNull<string>(),
+                        It.IsAny<double>(),
+                        It.IsNotNull<IDictionary<string, string>>()))
+                .Callback((string metricName, double value, IDictionary<string, string> properties) =>
+                {
+                    Assert.Equal("Orchestrator.DurationToBackupPackageSeconds", metricName);
+                    Assert.True(value > 0);
+                    Assert.NotEmpty(properties);
+                    Assert.Equal(new Dictionary<string, string>()
+                    {
+                        { "ValidationTrackingId", validationTrackingId.ToString() },
+                        { "PackageId", packageId },
+                        { "NormalizedVersion", normalizedVersion },
+                    }, properties);
+                });
+
+            // Act
+            using (_telemetryService.TrackDurationToBackupPackage(validationSet))
+            {
+            }
+
+            // Assert
+            _telemetryClient.VerifyAll();
+        }
     }
 }

tests/NuGet.Services.Validation.Orchestrator.Tests/ValidationPackageFileServiceFacts.cs

@@ -112,6 +112,15 @@ public async Task BackupPackageFileFromValidationSetPackageAsync()
                 .Returns(Task.CompletedTask)
                 .Verifiable();
 
+            var backupDurationMetric = new Mock<IDisposable>(MockBehavior.Strict);
+            backupDurationMetric
+                .Setup(m => m.Dispose())
+                .Verifiable();
+
+            _telemetryService
+                .Setup(t => t.TrackDurationToBackupPackage(_validationSet))
+                .Returns(backupDurationMetric.Object);
+
             var before = DateTimeOffset.UtcNow;
             await _target.BackupPackageFileFromValidationSetPackageAsync(_validationSet);
             var after = DateTimeOffset.UtcNow;