Measure the durations for /search/diag queries (#589)

Add telemetry for these measurements.
Align "latest commit" to "last commit". "last" is already used in a response body and document field so that is preferred.

src/NuGet.Services.AzureSearch/AzureSearchTelemetryService.cs

@@ -250,5 +250,40 @@ public IDisposable TrackCatalogLeafDownloadBatch(int count)
                     { "Count", count.ToString() },
                 });
         }
+
+        public void TrackDocumentCountQuery(string indexName, long count, TimeSpan elapsed)
+        {
+            _telemetryClient.TrackMetric(
+                Prefix + "DocumentCountQueryMs",
+                elapsed.TotalMilliseconds,
+                new Dictionary<string, string>
+                {
+                    { "IndexName", indexName },
+                    { "Count", count.ToString() },
+                });
+        }
+
+        public void TrackWarmQuery(string indexName, TimeSpan elapsed)
+        {
+            _telemetryClient.TrackMetric(
+                Prefix + "WarmQueryMs",
+                elapsed.TotalMilliseconds,
+                new Dictionary<string, string>
+                {
+                    { "IndexName", indexName },
+                });
+        }
+
+        public void TrackLastCommitTimestampQuery(string indexName, DateTimeOffset? lastCommitTimestamp, TimeSpan elapsed)
+        {
+            _telemetryClient.TrackMetric(
+                Prefix + "LastCommitTimestampQueryMs",
+                elapsed.TotalMilliseconds,
+                new Dictionary<string, string>
+                {
+                    { "IndexName", indexName },
+                    { "LastCommitTimestamp", lastCommitTimestamp?.ToString("O") },
+                });
+        }
     }
 }

src/NuGet.Services.AzureSearch/Catalog2AzureSearch/CatalogIndexActionBuilder.cs

@@ -258,8 +258,8 @@ private IndexAction<KeyedDocument> GetSearchIndexAction(
                     indexAction = IndexAction.Merge<KeyedDocument>(_search.UpdateVersionListAndOwnersFromCatalog(
                        context.PackageId,
                        searchFilters,
-                       lastCommitTimestamp: context.LatestCommitTimestamp,
-                       lastCommitId: context.LatestCommitId,
+                       lastCommitTimestamp: context.LastCommitTimestamp,
+                       lastCommitId: context.LastCommitId,
                        versions: latestFlags.LatestVersionInfo.ListedFullVersions,
                        isLatestStable: latestFlags.IsLatestStable,
                        isLatest: latestFlags.IsLatest,
@@ -270,8 +270,8 @@ private IndexAction<KeyedDocument> GetSearchIndexAction(
                     indexAction = IndexAction.Merge<KeyedDocument>(_search.UpdateVersionListFromCatalog(
                        context.PackageId,
                        searchFilters,
-                       lastCommitTimestamp: context.LatestCommitTimestamp,
-                       lastCommitId: context.LatestCommitId,
+                       lastCommitTimestamp: context.LastCommitTimestamp,
+                       lastCommitId: context.LastCommitId,
                        versions: latestFlags.LatestVersionInfo.ListedFullVersions,
                        isLatestStable: latestFlags.IsLatestStable,
                        isLatest: latestFlags.IsLatest));
@@ -342,8 +342,8 @@ private IndexAction<KeyedDocument> GetHijackIndexAction(
                 indexAction = IndexAction.Merge<KeyedDocument>(_hijack.LatestFromCatalog(
                     context.PackageId,
                     version.ToNormalizedString(),
-                    lastCommitTimestamp: context.LatestCommitTimestamp,
-                    lastCommitId: context.LatestCommitId,
+                    lastCommitTimestamp: context.LastCommitTimestamp,
+                    lastCommitId: context.LastCommitId,
                     changes: changes));
             }
             else
@@ -458,24 +458,24 @@ public Context(
                     x => x.Value,
                     ReferenceEqualityComparer<CatalogCommitItem>.Default);
 
-                var latestCommit = latestEntries
+                var lastCommit = latestEntries
                     .GroupBy(x => new { x.CommitTimeStamp, x.CommitId })
                     .Select(x => x.Key)
                     .OrderByDescending(x => x.CommitTimeStamp)
                     .First();
 
                 // Assume UTC on the commit timestamp.
-                LatestCommitTimestamp = new DateTimeOffset(latestCommit.CommitTimeStamp.Ticks, TimeSpan.Zero);
-                LatestCommitId = latestCommit.CommitId;
+                LastCommitTimestamp = new DateTimeOffset(lastCommit.CommitTimeStamp.Ticks, TimeSpan.Zero);
+                LastCommitId = lastCommit.CommitId;
             }
 
             public string PackageId { get; }
             public ResultAndAccessCondition<VersionListData> VersionListDataResult { get; }
             public Dictionary<NuGetVersion, CatalogCommitItem> VersionToEntry { get; }
             public Dictionary<CatalogCommitItem, PackageDetailsCatalogLeaf> EntryToLeaf { get; }
             public VersionLists VersionLists { get; set; }
-            public DateTimeOffset LatestCommitTimestamp { get; }
-            public string LatestCommitId { get; }
+            public DateTimeOffset LastCommitTimestamp { get; }
+            public string LastCommitId { get; }
 
             public PackageDetailsCatalogLeaf GetLeaf(NuGetVersion version)
             {

src/NuGet.Services.AzureSearch/IAzureSearchTelemetryService.cs

@@ -25,11 +25,14 @@ public interface IAzureSearchTelemetryService
         IDisposable TrackUploadOwnerChangeHistory(int packageIdCount);
         IDisposable TrackVersionListsUpdated(int versionListCount, int workerCount);
         IDisposable TrackCatalog2AzureSearchProcessBatch(int catalogLeafCount, int latestCatalogLeafCount, int packageIdCount);
-        void TrackV2SearchQueryWithSearchIndex(TimeSpan duration);
-        void TrackV2SearchQueryWithHijackIndex(TimeSpan duration);
-        void TrackAutocompleteQuery(TimeSpan duration);
-        void TrackV3SearchQuery(TimeSpan duration);
-        void TrackGetSearchServiceStatus(SearchStatusOptions options, bool success, TimeSpan duration);
+        void TrackV2SearchQueryWithSearchIndex(TimeSpan elapsed);
+        void TrackV2SearchQueryWithHijackIndex(TimeSpan elapsed);
+        void TrackAutocompleteQuery(TimeSpan elapsed);
+        void TrackV3SearchQuery(TimeSpan elapsed);
+        void TrackGetSearchServiceStatus(SearchStatusOptions options, bool success, TimeSpan elapsed);
+        void TrackDocumentCountQuery(string indexName, long count, TimeSpan elapsed);
+        void TrackWarmQuery(string indexName, TimeSpan elapsed);
+        void TrackLastCommitTimestampQuery(string indexName, DateTimeOffset? lastCommitTimestamp, TimeSpan elapsed);
         IDisposable TrackCatalogLeafDownloadBatch(int count);
     }
 }

src/NuGet.Services.AzureSearch/SearchService/ISearchParametersBuilder.cs

@@ -7,7 +7,7 @@ namespace NuGet.Services.AzureSearch.SearchService
 {
     public interface ISearchParametersBuilder
     {
-        SearchParameters LatestCommitTimestamp();
+        SearchParameters LastCommitTimestamp();
         SearchParameters V2Search(V2SearchRequest request);
         SearchParameters V3Search(V3SearchRequest request);
         SearchParameters Autocomplete(AutocompleteRequest request);

src/NuGet.Services.AzureSearch/SearchService/Models/IndexStatus.cs

@@ -9,7 +9,9 @@ public class IndexStatus
     {
         public string Name { get; set; }
         public long DocumentCount { get; set; }
+        public TimeSpan DocumentCountDuration { get; set; }
         public TimeSpan WarmQueryDuration { get; set; }
         public DateTimeOffset? LastCommitTimestamp { get; set; }
+        public TimeSpan LastCommitTimestampDuration { get; set; }
     }
 }

src/NuGet.Services.AzureSearch/SearchService/SearchParametersBuilder.cs

@@ -25,7 +25,7 @@ public class SearchParametersBuilder : ISearchParametersBuilder
         private static readonly List<string> SortableTitleAscending = new List<string> { IndexFields.SortableTitle + Ascending };
         private static readonly List<string> SortableTitleDescending = new List<string> { IndexFields.SortableTitle + Descending };
 
-        public SearchParameters LatestCommitTimestamp()
+        public SearchParameters LastCommitTimestamp()
         {
             return new SearchParameters
             {

src/NuGet.Services.AzureSearch/SearchService/SearchStatusService.cs

@@ -168,23 +168,29 @@ private static string GetAssemblyMetadataOrNull(Assembly assembly, string name)
 
         private async Task<IndexStatus> GetIndexStatusAsync(ISearchIndexClientWrapper index)
         {
-            var documentCount = await index.Documents.CountAsync();
+            var documentCountResult = await Measure.DurationWithValueAsync(() => index.Documents.CountAsync());
+            _telemetryService.TrackDocumentCountQuery(index.IndexName, documentCountResult.Value, documentCountResult.Duration);
 
-            var lastCommitTimestampParameters = _parametersBuilder.LatestCommitTimestamp();
-            var lastCommitTimestampResult = await index.Documents.SearchAsync("*", lastCommitTimestampParameters);
-            var lastCommitTimestamp = lastCommitTimestampResult?
+            var lastCommitTimestampParameters = _parametersBuilder.LastCommitTimestamp();
+            var lastCommitTimestampResult = await Measure.DurationWithValueAsync(() => index.Documents.SearchAsync("*", lastCommitTimestampParameters));
+            var lastCommitTimestamp = lastCommitTimestampResult
+                .Value?
                 .Results?
                 .FirstOrDefault()?
                 .Document[IndexFields.LastCommitTimestamp] as DateTimeOffset?;
+            _telemetryService.TrackLastCommitTimestampQuery(index.IndexName, lastCommitTimestamp, lastCommitTimestampResult.Duration);
 
             var warmQueryDuration = await Measure.DurationAsync(() => index.Documents.SearchAsync("*", new SearchParameters()));
+            _telemetryService.TrackWarmQuery(index.IndexName, warmQueryDuration);
 
             return new IndexStatus
             {
-                DocumentCount = documentCount,
+                DocumentCount = documentCountResult.Value,
+                DocumentCountDuration = documentCountResult.Duration,
                 Name = index.IndexName,
                 WarmQueryDuration = warmQueryDuration,
                 LastCommitTimestamp = lastCommitTimestamp,
+                LastCommitTimestampDuration = lastCommitTimestampResult.Duration,
             };
         }
     }

tests/CatalogTests/CatalogCommitUtilitiesTests.cs

@@ -166,7 +166,7 @@ public void CreateCommitItemBatches_WhenPackageIdsVaryInCasing_GroupsUsingProvid
         }
 
         [Fact]
-        public void CreateCommitItemBatches_WhenCommitItemsContainMultipleCommitsForSamePackageIdentity_ReturnsOnlyLatestCommitForEachPackageIdentity()
+        public void CreateCommitItemBatches_WhenCommitItemsContainMultipleCommitsForSamePackageIdentity_ReturnsOnlyLastCommitForEachPackageIdentity()
         {
             var now = DateTime.UtcNow;
             var commitItem0 = TestUtility.CreateCatalogCommitItem(now, _packageIdentitya);

tests/NuGet.Services.AzureSearch.Tests/SearchService/SearchParametersBuilderFacts.cs

@@ -11,12 +11,12 @@ namespace NuGet.Services.AzureSearch.SearchService
 {
     public class SearchParametersBuilderFacts
     {
-        public class LatestCommitTimestamp : BaseFacts
+        public class LastCommitTimestamp : BaseFacts
         {
             [Fact]
             public void Defaults()
             {
-                var output = _target.LatestCommitTimestamp();
+                var output = _target.LastCommitTimestamp();
 
                 Assert.Equal(QueryType.Full, output.QueryType);
                 Assert.False(output.IncludeTotalResultCount);

tests/NuGet.Services.AzureSearch.Tests/SearchService/SearchStatusServiceFacts.cs

@@ -86,7 +86,7 @@ public async Task ReturnsNullCommitTimestampWhenTheLastCommitTimestampIsNull()
             {
                 _searchDocuments
                     .Setup(x => x.SearchAsync(It.IsAny<string>(), It.IsAny<SearchParameters>()))
-                    .ReturnsAsync(GetLatestCommitTimestampResult(timestamp: null));
+                    .ReturnsAsync(GetLastCommitTimestampResult(timestamp: null));
 
                 var status = await _target.GetStatusAsync(SearchStatusOptions.All, _assembly);
 
@@ -117,12 +117,12 @@ public async Task ReturnsFullStatus()
                 Assert.Equal(23, status.SearchIndex.DocumentCount);
                 Assert.Equal("search-index", status.SearchIndex.Name);
                 Assert.InRange(status.SearchIndex.WarmQueryDuration, TimeSpan.FromMilliseconds(1), TimeSpan.MaxValue);
-                Assert.Equal(_searchLatestCommitTimestamp, status.SearchIndex.LastCommitTimestamp);
+                Assert.Equal(_searchLastCommitTimestamp, status.SearchIndex.LastCommitTimestamp);
 
                 Assert.Equal(42, status.HijackIndex.DocumentCount);
                 Assert.Equal("hijack-index", status.HijackIndex.Name);
                 Assert.InRange(status.HijackIndex.WarmQueryDuration, TimeSpan.FromMilliseconds(1), TimeSpan.MaxValue);
-                Assert.Equal(_hijackLatestCommitTimestamp, status.HijackIndex.LastCommitTimestamp);
+                Assert.Equal(_hijackLastCommitTimestamp, status.HijackIndex.LastCommitTimestamp);
 
                 Assert.Same(_auxiliaryFilesMetadata, status.AuxiliaryFiles);
 
@@ -215,9 +215,9 @@ public abstract class BaseFacts
             protected readonly AuxiliaryFilesMetadata _auxiliaryFilesMetadata;
             protected readonly Assembly _assembly;
             protected readonly SearchStatusService _target;
-            protected readonly SearchParameters _latestCommitTimestampParameters;
-            protected readonly DateTimeOffset _searchLatestCommitTimestamp;
-            protected readonly DateTimeOffset _hijackLatestCommitTimestamp;
+            protected readonly SearchParameters _lastCommitTimestampParameters;
+            protected readonly DateTimeOffset _searchLastCommitTimestamp;
+            protected readonly DateTimeOffset _hijackLastCommitTimestamp;
 
             public BaseFacts(ITestOutputHelper output)
             {
@@ -248,9 +248,9 @@ public BaseFacts(ITestOutputHelper output)
                 _assembly = typeof(BaseFacts).Assembly;
                 _config = new SearchServiceConfiguration();
                 _config.DeploymentLabel = "Fake deployment label.";
-                _latestCommitTimestampParameters = new SearchParameters();
-                _searchLatestCommitTimestamp = new DateTimeOffset(2019, 7, 1, 0, 0, 0, TimeSpan.Zero);
-                _hijackLatestCommitTimestamp = new DateTimeOffset(2019, 7, 2, 0, 0, 0, TimeSpan.Zero);
+                _lastCommitTimestampParameters = new SearchParameters();
+                _searchLastCommitTimestamp = new DateTimeOffset(2019, 7, 1, 0, 0, 0, TimeSpan.Zero);
+                _hijackLastCommitTimestamp = new DateTimeOffset(2019, 7, 2, 0, 0, 0, TimeSpan.Zero);
                 Environment.SetEnvironmentVariable("WEBSITE_INSTANCE_ID", "Fake website instance ID.");
 
                 _searchIndex.Setup(x => x.IndexName).Returns("search-index");
@@ -259,22 +259,22 @@ public BaseFacts(ITestOutputHelper output)
                 _hijackIndex.Setup(x => x.Documents).Returns(() => _hijackDocuments.Object);
                 _searchDocuments.Setup(x => x.CountAsync()).ReturnsAsync(23);
                 _hijackDocuments.Setup(x => x.CountAsync()).ReturnsAsync(42);
-                _parametersBuilder.Setup(x => x.LatestCommitTimestamp()).Returns(() => _latestCommitTimestampParameters);
+                _parametersBuilder.Setup(x => x.LastCommitTimestamp()).Returns(() => _lastCommitTimestampParameters);
 
                 _searchDocuments
-                    .Setup(x => x.SearchAsync(It.IsAny<string>(), It.Is<SearchParameters>(p => !IsLatestCommitTimestamp(p))))
+                    .Setup(x => x.SearchAsync(It.IsAny<string>(), It.Is<SearchParameters>(p => !IsLastCommitTimestamp(p))))
                     .ReturnsAsync(new DocumentSearchResult())
                     .Callback(() => Thread.Sleep(TimeSpan.FromMilliseconds(1)));
                 _searchDocuments
-                    .Setup(x => x.SearchAsync(It.IsAny<string>(), It.Is<SearchParameters>(p => IsLatestCommitTimestamp(p))))
-                    .ReturnsAsync(GetLatestCommitTimestampResult(_searchLatestCommitTimestamp));
+                    .Setup(x => x.SearchAsync(It.IsAny<string>(), It.Is<SearchParameters>(p => IsLastCommitTimestamp(p))))
+                    .ReturnsAsync(GetLastCommitTimestampResult(_searchLastCommitTimestamp));
                 _hijackDocuments
-                    .Setup(x => x.SearchAsync(It.IsAny<string>(), It.Is<SearchParameters>(p => !IsLatestCommitTimestamp(p))))
+                    .Setup(x => x.SearchAsync(It.IsAny<string>(), It.Is<SearchParameters>(p => !IsLastCommitTimestamp(p))))
                     .ReturnsAsync(new DocumentSearchResult())
                     .Callback(() => Thread.Sleep(TimeSpan.FromMilliseconds(1)));
                 _hijackDocuments
-                    .Setup(x => x.SearchAsync(It.IsAny<string>(), It.Is<SearchParameters>(p => IsLatestCommitTimestamp(p))))
-                    .ReturnsAsync(GetLatestCommitTimestampResult(_hijackLatestCommitTimestamp));
+                    .Setup(x => x.SearchAsync(It.IsAny<string>(), It.Is<SearchParameters>(p => IsLastCommitTimestamp(p))))
+                    .ReturnsAsync(GetLastCommitTimestampResult(_hijackLastCommitTimestamp));
                 _options.Setup(x => x.Value).Returns(() => _config);
                 _auxiliaryDataCache.Setup(x => x.Get()).Returns(() => _auxiliaryData.Object);
                 _auxiliaryData.Setup(x => x.Metadata).Returns(() => _auxiliaryFilesMetadata);
@@ -289,7 +289,7 @@ public BaseFacts(ITestOutputHelper output)
                     _logger);
             }
 
-            protected static DocumentSearchResult GetLatestCommitTimestampResult(DateTimeOffset? timestamp)
+            protected static DocumentSearchResult GetLastCommitTimestampResult(DateTimeOffset? timestamp)
             {
                 return new DocumentSearchResult
                 {
@@ -306,9 +306,9 @@ protected static DocumentSearchResult GetLatestCommitTimestampResult(DateTimeOff
                 };
             }
 
-            private bool IsLatestCommitTimestamp(SearchParameters parameters)
+            private bool IsLastCommitTimestamp(SearchParameters parameters)
             {
-                return parameters == _latestCommitTimestampParameters;
+                return parameters == _lastCommitTimestampParameters;
             }
         }
     }