From 2c79274f79f24db21ad65abf439d2ce790b2b93c Mon Sep 17 00:00:00 2001 From: Joel Verhagen Date: Thu, 11 Jul 2019 09:17:51 -0700 Subject: [PATCH] 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. --- .../AzureSearchTelemetryService.cs | 35 +++++++++++++++++ .../CatalogIndexActionBuilder.cs | 22 +++++------ .../IAzureSearchTelemetryService.cs | 13 ++++--- .../SearchService/ISearchParametersBuilder.cs | 2 +- .../SearchService/Models/IndexStatus.cs | 2 + .../SearchService/SearchParametersBuilder.cs | 2 +- .../SearchService/SearchStatusService.cs | 16 +++++--- .../CatalogCommitUtilitiesTests.cs | 2 +- .../SearchParametersBuilderFacts.cs | 4 +- .../SearchService/SearchStatusServiceFacts.cs | 38 +++++++++---------- 10 files changed, 91 insertions(+), 45 deletions(-) diff --git a/src/NuGet.Services.AzureSearch/AzureSearchTelemetryService.cs b/src/NuGet.Services.AzureSearch/AzureSearchTelemetryService.cs index fb939a2af..f247de00b 100644 --- a/src/NuGet.Services.AzureSearch/AzureSearchTelemetryService.cs +++ b/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 + { + { "IndexName", indexName }, + { "Count", count.ToString() }, + }); + } + + public void TrackWarmQuery(string indexName, TimeSpan elapsed) + { + _telemetryClient.TrackMetric( + Prefix + "WarmQueryMs", + elapsed.TotalMilliseconds, + new Dictionary + { + { "IndexName", indexName }, + }); + } + + public void TrackLastCommitTimestampQuery(string indexName, DateTimeOffset? lastCommitTimestamp, TimeSpan elapsed) + { + _telemetryClient.TrackMetric( + Prefix + "LastCommitTimestampQueryMs", + elapsed.TotalMilliseconds, + new Dictionary + { + { "IndexName", indexName }, + { "LastCommitTimestamp", lastCommitTimestamp?.ToString("O") }, + }); + } } } diff --git a/src/NuGet.Services.AzureSearch/Catalog2AzureSearch/CatalogIndexActionBuilder.cs b/src/NuGet.Services.AzureSearch/Catalog2AzureSearch/CatalogIndexActionBuilder.cs index 3e61a2166..98563a210 100644 --- a/src/NuGet.Services.AzureSearch/Catalog2AzureSearch/CatalogIndexActionBuilder.cs +++ b/src/NuGet.Services.AzureSearch/Catalog2AzureSearch/CatalogIndexActionBuilder.cs @@ -258,8 +258,8 @@ private IndexAction GetSearchIndexAction( indexAction = IndexAction.Merge(_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 GetSearchIndexAction( indexAction = IndexAction.Merge(_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 GetHijackIndexAction( indexAction = IndexAction.Merge(_hijack.LatestFromCatalog( context.PackageId, version.ToNormalizedString(), - lastCommitTimestamp: context.LatestCommitTimestamp, - lastCommitId: context.LatestCommitId, + lastCommitTimestamp: context.LastCommitTimestamp, + lastCommitId: context.LastCommitId, changes: changes)); } else @@ -458,15 +458,15 @@ public Context( x => x.Value, ReferenceEqualityComparer.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; } @@ -474,8 +474,8 @@ public Context( public Dictionary VersionToEntry { get; } public Dictionary 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) { diff --git a/src/NuGet.Services.AzureSearch/IAzureSearchTelemetryService.cs b/src/NuGet.Services.AzureSearch/IAzureSearchTelemetryService.cs index 223a2243d..730f65ded 100644 --- a/src/NuGet.Services.AzureSearch/IAzureSearchTelemetryService.cs +++ b/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); } } \ No newline at end of file diff --git a/src/NuGet.Services.AzureSearch/SearchService/ISearchParametersBuilder.cs b/src/NuGet.Services.AzureSearch/SearchService/ISearchParametersBuilder.cs index 79dac7c39..62e464088 100644 --- a/src/NuGet.Services.AzureSearch/SearchService/ISearchParametersBuilder.cs +++ b/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); diff --git a/src/NuGet.Services.AzureSearch/SearchService/Models/IndexStatus.cs b/src/NuGet.Services.AzureSearch/SearchService/Models/IndexStatus.cs index cb59094bd..0aa96ac83 100644 --- a/src/NuGet.Services.AzureSearch/SearchService/Models/IndexStatus.cs +++ b/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; } } } diff --git a/src/NuGet.Services.AzureSearch/SearchService/SearchParametersBuilder.cs b/src/NuGet.Services.AzureSearch/SearchService/SearchParametersBuilder.cs index 10bed632f..7e0aeb872 100644 --- a/src/NuGet.Services.AzureSearch/SearchService/SearchParametersBuilder.cs +++ b/src/NuGet.Services.AzureSearch/SearchService/SearchParametersBuilder.cs @@ -25,7 +25,7 @@ public class SearchParametersBuilder : ISearchParametersBuilder private static readonly List SortableTitleAscending = new List { IndexFields.SortableTitle + Ascending }; private static readonly List SortableTitleDescending = new List { IndexFields.SortableTitle + Descending }; - public SearchParameters LatestCommitTimestamp() + public SearchParameters LastCommitTimestamp() { return new SearchParameters { diff --git a/src/NuGet.Services.AzureSearch/SearchService/SearchStatusService.cs b/src/NuGet.Services.AzureSearch/SearchService/SearchStatusService.cs index 64b3ea021..147736b50 100644 --- a/src/NuGet.Services.AzureSearch/SearchService/SearchStatusService.cs +++ b/src/NuGet.Services.AzureSearch/SearchService/SearchStatusService.cs @@ -168,23 +168,29 @@ private static string GetAssemblyMetadataOrNull(Assembly assembly, string name) private async Task 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, }; } } diff --git a/tests/CatalogTests/CatalogCommitUtilitiesTests.cs b/tests/CatalogTests/CatalogCommitUtilitiesTests.cs index 81330631f..41a75efe4 100644 --- a/tests/CatalogTests/CatalogCommitUtilitiesTests.cs +++ b/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); diff --git a/tests/NuGet.Services.AzureSearch.Tests/SearchService/SearchParametersBuilderFacts.cs b/tests/NuGet.Services.AzureSearch.Tests/SearchService/SearchParametersBuilderFacts.cs index 06532ce2d..8caec1293 100644 --- a/tests/NuGet.Services.AzureSearch.Tests/SearchService/SearchParametersBuilderFacts.cs +++ b/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); diff --git a/tests/NuGet.Services.AzureSearch.Tests/SearchService/SearchStatusServiceFacts.cs b/tests/NuGet.Services.AzureSearch.Tests/SearchService/SearchStatusServiceFacts.cs index 257e35dde..9e71c0262 100644 --- a/tests/NuGet.Services.AzureSearch.Tests/SearchService/SearchStatusServiceFacts.cs +++ b/tests/NuGet.Services.AzureSearch.Tests/SearchService/SearchStatusServiceFacts.cs @@ -86,7 +86,7 @@ public async Task ReturnsNullCommitTimestampWhenTheLastCommitTimestampIsNull() { _searchDocuments .Setup(x => x.SearchAsync(It.IsAny(), It.IsAny())) - .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(), It.Is(p => !IsLatestCommitTimestamp(p)))) + .Setup(x => x.SearchAsync(It.IsAny(), It.Is(p => !IsLastCommitTimestamp(p)))) .ReturnsAsync(new DocumentSearchResult()) .Callback(() => Thread.Sleep(TimeSpan.FromMilliseconds(1))); _searchDocuments - .Setup(x => x.SearchAsync(It.IsAny(), It.Is(p => IsLatestCommitTimestamp(p)))) - .ReturnsAsync(GetLatestCommitTimestampResult(_searchLatestCommitTimestamp)); + .Setup(x => x.SearchAsync(It.IsAny(), It.Is(p => IsLastCommitTimestamp(p)))) + .ReturnsAsync(GetLastCommitTimestampResult(_searchLastCommitTimestamp)); _hijackDocuments - .Setup(x => x.SearchAsync(It.IsAny(), It.Is(p => !IsLatestCommitTimestamp(p)))) + .Setup(x => x.SearchAsync(It.IsAny(), It.Is(p => !IsLastCommitTimestamp(p)))) .ReturnsAsync(new DocumentSearchResult()) .Callback(() => Thread.Sleep(TimeSpan.FromMilliseconds(1))); _hijackDocuments - .Setup(x => x.SearchAsync(It.IsAny(), It.Is(p => IsLatestCommitTimestamp(p)))) - .ReturnsAsync(GetLatestCommitTimestampResult(_hijackLatestCommitTimestamp)); + .Setup(x => x.SearchAsync(It.IsAny(), It.Is(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; } } }