From 47eac670e9aabb89f302c4e61b50b2564c52b68a Mon Sep 17 00:00:00 2001 From: David Barbet Date: Wed, 9 Oct 2024 18:31:56 -0700 Subject: [PATCH] Add counter telemetry log aggregator and cleanup implemention to ensure it always gets posted --- .../SuggestedActions/SuggestedAction.cs | 2 +- .../SuggestedActionsSource_Async.cs | 8 +- .../CodeRefactoringService.cs | 2 +- .../Telemetry/VSCodeRequestTelemetryLogger.cs | 41 ++--- .../Features/CodeFixes/CodeFixService.cs | 12 +- .../Diagnostics/DocumentAnalysisExecutor.cs | 4 +- ...crementalAnalyzer_GetDiagnosticsForSpan.cs | 6 +- .../Telemetry/RequestTelemetryLogger.cs | 159 +++++------------- .../AbstractWorkspaceTelemetryService.cs | 10 +- ...emetryLog.cs => AbstractAggregatingLog.cs} | 59 +++---- .../Telemetry/Shared/AggregatingCounterLog.cs | 37 ++++ .../Shared/AggregatingHistogramLog.cs | 63 +++++++ .../Shared/AggregatingTelemetryLogManager.cs | 47 ------ .../Telemetry/Shared/TelemetryLogProvider.cs | 67 +++++++- .../Shared/TimedTelemetryLogBlock.cs | 2 +- .../Shared/VisualStudioTelemetryLog.cs | 2 +- .../Shared/VisualStudioTelemetryLogManager.cs | 32 ---- .../Impl/Logging/VSCodeTelemetryLogger.cs | 2 + .../Core/Portable/CodeActions/CodeAction.cs | 2 +- .../Portable/Telemetry/ITelemetryBlockLog.cs | 19 +++ .../Core/Portable/Telemetry/ITelemetryLog.cs | 8 - .../Telemetry/ITelemetryLogProvider.cs | 12 +- .../Portable/Telemetry/TelemetryLogging.cs | 36 ++-- .../PerformanceTrackerService.cs | 4 +- .../RemoteDiagnosticAnalyzerService.cs | 2 +- 25 files changed, 318 insertions(+), 320 deletions(-) rename src/VisualStudio/Core/Def/Telemetry/Shared/{AggregatingTelemetryLog.cs => AbstractAggregatingLog.cs} (62%) create mode 100644 src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingCounterLog.cs create mode 100644 src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingHistogramLog.cs delete mode 100644 src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingTelemetryLogManager.cs delete mode 100644 src/VisualStudio/Core/Def/Telemetry/Shared/VisualStudioTelemetryLogManager.cs create mode 100644 src/Workspaces/Core/Portable/Telemetry/ITelemetryBlockLog.cs diff --git a/src/EditorFeatures/Core.Wpf/Suggestions/SuggestedActions/SuggestedAction.cs b/src/EditorFeatures/Core.Wpf/Suggestions/SuggestedActions/SuggestedAction.cs index 328f3d74e0a02..81de54979ae38 100644 --- a/src/EditorFeatures/Core.Wpf/Suggestions/SuggestedActions/SuggestedAction.cs +++ b/src/EditorFeatures/Core.Wpf/Suggestions/SuggestedActions/SuggestedAction.cs @@ -116,7 +116,7 @@ private async Task InvokeAsync() { try { - using var _ = TelemetryLogging.LogBlockTimeAggregated(FunctionId.SuggestedAction_Application_Summary, $"Total"); + using var _ = TelemetryLogging.LogBlockTimeAggregatedHistogram(FunctionId.SuggestedAction_Application_Summary, $"Total"); using var token = SourceProvider.OperationListener.BeginAsyncOperation($"{nameof(SuggestedAction)}.{nameof(Invoke)}"); using var context = SourceProvider.UIThreadOperationExecutor.BeginExecute( diff --git a/src/EditorFeatures/Core.Wpf/Suggestions/SuggestedActionsSource_Async.cs b/src/EditorFeatures/Core.Wpf/Suggestions/SuggestedActionsSource_Async.cs index 7f4c8382432b9..135caef587b35 100644 --- a/src/EditorFeatures/Core.Wpf/Suggestions/SuggestedActionsSource_Async.cs +++ b/src/EditorFeatures/Core.Wpf/Suggestions/SuggestedActionsSource_Async.cs @@ -113,14 +113,14 @@ private async Task GetSuggestedActionsWorkerAsync( // then pass it continuously from one priority group to the next. var lowPriorityAnalyzerData = new SuggestedActionPriorityProvider.LowPriorityAnalyzersAndDiagnosticIds(); - using var _2 = TelemetryLogging.LogBlockTimeAggregated(FunctionId.SuggestedAction_Summary, $"Total"); + using var _2 = TelemetryLogging.LogBlockTimeAggregatedHistogram(FunctionId.SuggestedAction_Summary, $"Total"); // Collectors are in priority order. So just walk them from highest to lowest. foreach (var collector in collectors) { if (TryGetPriority(collector.Priority) is CodeActionRequestPriority priority) { - using var _3 = TelemetryLogging.LogBlockTimeAggregated(FunctionId.SuggestedAction_Summary, $"Total.Pri{(int)priority}"); + using var _3 = TelemetryLogging.LogBlockTimeAggregatedHistogram(FunctionId.SuggestedAction_Summary, $"Total.Pri{(int)priority}"); var allSets = GetCodeFixesAndRefactoringsAsync( state, requestedActionCategories, document, @@ -229,7 +229,7 @@ private async IAsyncEnumerable GetCodeFixesAndRefactoringsAs async Task> GetCodeFixesAsync() { - using var _ = TelemetryLogging.LogBlockTimeAggregated(FunctionId.SuggestedAction_Summary, $"Total.Pri{priorityProvider.Priority.GetPriorityInt()}.{nameof(GetCodeFixesAsync)}"); + using var _ = TelemetryLogging.LogBlockTimeAggregatedHistogram(FunctionId.SuggestedAction_Summary, $"Total.Pri{priorityProvider.Priority.GetPriorityInt()}.{nameof(GetCodeFixesAsync)}"); if (owner._codeFixService == null || !supportsFeatureService.SupportsCodeFixes(target.SubjectBuffer) || @@ -245,7 +245,7 @@ async Task> GetCodeFixesAsync() async Task> GetRefactoringsAsync() { - using var _ = TelemetryLogging.LogBlockTimeAggregated(FunctionId.SuggestedAction_Summary, $"Total.Pri{priorityProvider.Priority.GetPriorityInt()}.{nameof(GetRefactoringsAsync)}"); + using var _ = TelemetryLogging.LogBlockTimeAggregatedHistogram(FunctionId.SuggestedAction_Summary, $"Total.Pri{priorityProvider.Priority.GetPriorityInt()}.{nameof(GetRefactoringsAsync)}"); if (!selection.HasValue) { diff --git a/src/Features/Core/Portable/CodeRefactorings/CodeRefactoringService.cs b/src/Features/Core/Portable/CodeRefactorings/CodeRefactoringService.cs index 7955a0e2c53ac..78cff4cd8a3fe 100644 --- a/src/Features/Core/Portable/CodeRefactorings/CodeRefactoringService.cs +++ b/src/Features/Core/Portable/CodeRefactorings/CodeRefactoringService.cs @@ -152,7 +152,7 @@ public async Task> GetRefactoringsAsync( CodeActionRequestPriority? priority, CancellationToken cancellationToken) { - using (TelemetryLogging.LogBlockTimeAggregated(FunctionId.CodeRefactoring_Summary, $"Pri{priority.GetPriorityInt()}")) + using (TelemetryLogging.LogBlockTimeAggregatedHistogram(FunctionId.CodeRefactoring_Summary, $"Pri{priority.GetPriorityInt()}")) using (Logger.LogBlock(FunctionId.Refactoring_CodeRefactoringService_GetRefactoringsAsync, cancellationToken)) { using var _ = PooledDictionary.GetInstance(out var providerToIndex); diff --git a/src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Telemetry/VSCodeRequestTelemetryLogger.cs b/src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Telemetry/VSCodeRequestTelemetryLogger.cs index ee7da49df6442..b16907c53cdb9 100644 --- a/src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Telemetry/VSCodeRequestTelemetryLogger.cs +++ b/src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Telemetry/VSCodeRequestTelemetryLogger.cs @@ -21,14 +21,6 @@ internal class VSCodeRequestTelemetryLogger() : RequestTelemetryLogger(WellKnown /// private static bool s_initialProjectLoadCompleted = false; - /// - /// Store which workspace a document came from for each request. This is tracked separately before and after initial project load: - /// 1. Before initial load, almost all requests should resolve to the misc files workspace. - /// 2. After initial load, almost all requests should resolve to the host workspace. - /// A large amount of misc files requests in 2 could indicate either a bug or feature improvements in order to load what the user is expecting. - /// - private readonly ConcurrentDictionary> _findDocumentCounters = new(); - public static void ReportProjectInitializationComplete() { s_initialProjectLoadCompleted = true; @@ -40,30 +32,17 @@ public static void ReportProjectLoadStarted() Logger.Log(FunctionId.VSCode_Project_Load_Started, logLevel: LogLevel.Information); } - protected override void IncreaseFindDocumentCount(string workspaceInfo) + protected override void IncreaseFindDocumentCount(string workspaceCountMetricName) { - _findDocumentCounters.GetOrAdd(s_initialProjectLoadCompleted, (_) => new CountLogAggregator()).IncreaseCount(workspaceInfo); - } - - protected override void ReportFindDocumentCounter() - { - foreach (var (isInitialLoadComplete, counter) in _findDocumentCounters) + TelemetryLogging.LogAggregatedCounter(FunctionId.LSP_FindDocumentInWorkspace, KeyValueLogMessage.Create(m => { - if (!counter.IsEmpty) - { - TelemetryLogging.Log(FunctionId.LSP_FindDocumentInWorkspace, KeyValueLogMessage.Create(LogType.Trace, m => - { - m["server"] = ServerTypeName; - m["projectsLoaded"] = isInitialLoadComplete; - foreach (var kvp in counter) - { - var info = kvp.Key.ToString()!; - m[info] = kvp.Value.GetCount(); - } - })); - } - } - _findDocumentCounters.Clear(); + var projectsLoaded = s_initialProjectLoadCompleted; + m[TelemetryLogging.KeyName] = ServerTypeName + "." + workspaceCountMetricName + "." + projectsLoaded; + m[TelemetryLogging.KeyValue] = 1L; + m[TelemetryLogging.KeyMetricName] = workspaceCountMetricName; + m["server"] = ServerTypeName; + m["workspace"] = workspaceCountMetricName; + m["projectsLoaded"] = projectsLoaded; + })); } - } diff --git a/src/LanguageServer/Protocol/Features/CodeFixes/CodeFixService.cs b/src/LanguageServer/Protocol/Features/CodeFixes/CodeFixService.cs index b76abcf95ec86..0a2112d3e8db3 100644 --- a/src/LanguageServer/Protocol/Features/CodeFixes/CodeFixService.cs +++ b/src/LanguageServer/Protocol/Features/CodeFixes/CodeFixService.cs @@ -101,11 +101,11 @@ public CodeFixService( public async Task GetMostSevereFixAsync( TextDocument document, TextSpan range, ICodeActionRequestPriorityProvider priorityProvider, CancellationToken cancellationToken) { - using var _ = TelemetryLogging.LogBlockTimeAggregated(FunctionId.CodeFix_Summary, $"Pri{priorityProvider.Priority.GetPriorityInt()}.{nameof(GetMostSevereFixAsync)}"); + using var _ = TelemetryLogging.LogBlockTimeAggregatedHistogram(FunctionId.CodeFix_Summary, $"Pri{priorityProvider.Priority.GetPriorityInt()}.{nameof(GetMostSevereFixAsync)}"); ImmutableArray allDiagnostics; - using (TelemetryLogging.LogBlockTimeAggregated(FunctionId.CodeFix_Summary, $"Pri{priorityProvider.Priority.GetPriorityInt()}.{nameof(GetMostSevereFixAsync)}.{nameof(_diagnosticService.GetDiagnosticsForSpanAsync)}")) + using (TelemetryLogging.LogBlockTimeAggregatedHistogram(FunctionId.CodeFix_Summary, $"Pri{priorityProvider.Priority.GetPriorityInt()}.{nameof(GetMostSevereFixAsync)}.{nameof(_diagnosticService.GetDiagnosticsForSpanAsync)}")) { allDiagnostics = await _diagnosticService.GetDiagnosticsForSpanAsync( document, range, GetShouldIncludeDiagnosticPredicate(document, priorityProvider), @@ -172,7 +172,7 @@ public async IAsyncEnumerable StreamFixesAsync( ICodeActionRequestPriorityProvider priorityProvider, [EnumeratorCancellation] CancellationToken cancellationToken) { - using var _ = TelemetryLogging.LogBlockTimeAggregated(FunctionId.CodeFix_Summary, $"Pri{priorityProvider.Priority.GetPriorityInt()}"); + using var _ = TelemetryLogging.LogBlockTimeAggregatedHistogram(FunctionId.CodeFix_Summary, $"Pri{priorityProvider.Priority.GetPriorityInt()}"); // We only need to compute suppression/configuration fixes when request priority is // 'CodeActionPriorityRequest.Lowest' or no priority was provided at all (so all providers should run). @@ -190,7 +190,7 @@ public async IAsyncEnumerable StreamFixesAsync( // user-invoked diagnostic requests, for example, user invoked Ctrl + Dot operation for lightbulb. ImmutableArray diagnostics; - using (TelemetryLogging.LogBlockTimeAggregated(FunctionId.CodeFix_Summary, $"Pri{priorityProvider.Priority.GetPriorityInt()}.{nameof(_diagnosticService.GetDiagnosticsForSpanAsync)}")) + using (TelemetryLogging.LogBlockTimeAggregatedHistogram(FunctionId.CodeFix_Summary, $"Pri{priorityProvider.Priority.GetPriorityInt()}.{nameof(_diagnosticService.GetDiagnosticsForSpanAsync)}")) { diagnostics = await _diagnosticService.GetDiagnosticsForSpanAsync( document, range, GetShouldIncludeDiagnosticPredicate(document, priorityProvider), @@ -286,10 +286,10 @@ private static SortedDictionary> ConvertToMap( { cancellationToken.ThrowIfCancellationRequested(); - using var _ = TelemetryLogging.LogBlockTimeAggregated(FunctionId.CodeFix_Summary, $"{nameof(GetDocumentFixAllForIdInSpanAsync)}"); + using var _ = TelemetryLogging.LogBlockTimeAggregatedHistogram(FunctionId.CodeFix_Summary, $"{nameof(GetDocumentFixAllForIdInSpanAsync)}"); ImmutableArray diagnostics; - using (TelemetryLogging.LogBlockTimeAggregated(FunctionId.CodeFix_Summary, $"{nameof(GetDocumentFixAllForIdInSpanAsync)}.{nameof(_diagnosticService.GetDiagnosticsForSpanAsync)}")) + using (TelemetryLogging.LogBlockTimeAggregatedHistogram(FunctionId.CodeFix_Summary, $"{nameof(GetDocumentFixAllForIdInSpanAsync)}.{nameof(_diagnosticService.GetDiagnosticsForSpanAsync)}")) { diagnostics = await _diagnosticService.GetDiagnosticsForSpanAsync( document, range, diagnosticId, includeSuppressedDiagnostics: false, priorityProvider: new DefaultCodeActionRequestPriorityProvider(), diff --git a/src/LanguageServer/Protocol/Features/Diagnostics/DocumentAnalysisExecutor.cs b/src/LanguageServer/Protocol/Features/Diagnostics/DocumentAnalysisExecutor.cs index d5de93548ef16..521dac2950c56 100644 --- a/src/LanguageServer/Protocol/Features/Diagnostics/DocumentAnalysisExecutor.cs +++ b/src/LanguageServer/Protocol/Features/Diagnostics/DocumentAnalysisExecutor.cs @@ -240,7 +240,7 @@ private async Task> GetSyntaxDiagnosticsAsync(Dia if (_lazySyntaxDiagnostics == null) { - using var _ = TelemetryLogging.LogBlockTimeAggregated(FunctionId.RequestDiagnostics_Summary, $"{nameof(GetSyntaxDiagnosticsAsync)}.{nameof(GetAnalysisResultAsync)}"); + using var _ = TelemetryLogging.LogBlockTimeAggregatedHistogram(FunctionId.RequestDiagnostics_Summary, $"{nameof(GetSyntaxDiagnosticsAsync)}.{nameof(GetAnalysisResultAsync)}"); var analysisScope = AnalysisScope.WithAnalyzers(_compilationBasedAnalyzersInAnalysisScope); var syntaxDiagnostics = await GetAnalysisResultAsync(analysisScope, cancellationToken).ConfigureAwait(false); @@ -276,7 +276,7 @@ private async Task> GetSemanticDiagnosticsAsync(D if (_lazySemanticDiagnostics == null) { - using var _ = TelemetryLogging.LogBlockTimeAggregated(FunctionId.RequestDiagnostics_Summary, $"{nameof(GetSemanticDiagnosticsAsync)}.{nameof(GetAnalysisResultAsync)}"); + using var _ = TelemetryLogging.LogBlockTimeAggregatedHistogram(FunctionId.RequestDiagnostics_Summary, $"{nameof(GetSemanticDiagnosticsAsync)}.{nameof(GetAnalysisResultAsync)}"); var analysisScope = AnalysisScope.WithAnalyzers(_compilationBasedAnalyzersInAnalysisScope); var semanticDiagnostics = await GetAnalysisResultAsync(analysisScope, cancellationToken).ConfigureAwait(false); diff --git a/src/LanguageServer/Protocol/Features/Diagnostics/EngineV2/DiagnosticIncrementalAnalyzer_GetDiagnosticsForSpan.cs b/src/LanguageServer/Protocol/Features/Diagnostics/EngineV2/DiagnosticIncrementalAnalyzer_GetDiagnosticsForSpan.cs index 11e74419a40a6..6eb5c073d1c49 100644 --- a/src/LanguageServer/Protocol/Features/Diagnostics/EngineV2/DiagnosticIncrementalAnalyzer_GetDiagnosticsForSpan.cs +++ b/src/LanguageServer/Protocol/Features/Diagnostics/EngineV2/DiagnosticIncrementalAnalyzer_GetDiagnosticsForSpan.cs @@ -196,7 +196,7 @@ public async Task GetAsync(ArrayBuilder list, CancellationToken using var _2 = ArrayBuilder.GetInstance(out var semanticSpanBasedAnalyzers); using var _3 = ArrayBuilder.GetInstance(out var semanticDocumentBasedAnalyzers); - using var _4 = TelemetryLogging.LogBlockTimeAggregated(FunctionId.RequestDiagnostics_Summary, $"Pri{_priorityProvider.Priority.GetPriorityInt()}"); + using var _4 = TelemetryLogging.LogBlockTimeAggregatedHistogram(FunctionId.RequestDiagnostics_Summary, $"Pri{_priorityProvider.Priority.GetPriorityInt()}"); foreach (var stateSet in _stateSets) { @@ -383,7 +383,7 @@ private async Task ComputeDocumentDiagnosticsAsync( ImmutableDictionary> diagnosticsMap; if (incrementalAnalysis) { - using var _2 = TelemetryLogging.LogBlockTimeAggregated(FunctionId.RequestDiagnostics_Summary, $"Pri{_priorityProvider.Priority.GetPriorityInt()}.Incremental"); + using var _2 = TelemetryLogging.LogBlockTimeAggregatedHistogram(FunctionId.RequestDiagnostics_Summary, $"Pri{_priorityProvider.Priority.GetPriorityInt()}.Incremental"); diagnosticsMap = await _owner._incrementalMemberEditAnalyzer.ComputeDiagnosticsAsync( executor, @@ -395,7 +395,7 @@ private async Task ComputeDocumentDiagnosticsAsync( } else { - using var _2 = TelemetryLogging.LogBlockTimeAggregated(FunctionId.RequestDiagnostics_Summary, $"Pri{_priorityProvider.Priority.GetPriorityInt()}.Document"); + using var _2 = TelemetryLogging.LogBlockTimeAggregatedHistogram(FunctionId.RequestDiagnostics_Summary, $"Pri{_priorityProvider.Priority.GetPriorityInt()}.Document"); diagnosticsMap = await ComputeDocumentDiagnosticsCoreAsync(executor, cancellationToken).ConfigureAwait(false); } diff --git a/src/LanguageServer/Protocol/Handler/Telemetry/RequestTelemetryLogger.cs b/src/LanguageServer/Protocol/Handler/Telemetry/RequestTelemetryLogger.cs index 955514d5ce933..369e09f9cc556 100644 --- a/src/LanguageServer/Protocol/Handler/Telemetry/RequestTelemetryLogger.cs +++ b/src/LanguageServer/Protocol/Handler/Telemetry/RequestTelemetryLogger.cs @@ -4,9 +4,11 @@ using System; using System.Collections.Concurrent; +using System.Reflection; using System.Threading; using Microsoft.CodeAnalysis.Internal.Log; using Microsoft.CodeAnalysis.Telemetry; +using Roslyn.Utilities; namespace Microsoft.CodeAnalysis.LanguageServer.Handler; @@ -18,46 +20,43 @@ internal class RequestTelemetryLogger : IDisposable, ILspService { protected readonly string ServerTypeName; - /// - /// Store request counters in a concurrent dictionary as non-mutating LSP requests can - /// run alongside other non-mutating requests. - /// - private readonly ConcurrentDictionary<(string Method, string? Language), Counter> _requestCounters; - - private readonly CountLogAggregator _findDocumentResults; - - private readonly CountLogAggregator _usedForkedSolutionCounter; - - private int _disposed; - public RequestTelemetryLogger(string serverTypeName) { ServerTypeName = serverTypeName; - _requestCounters = new(); - _findDocumentResults = new(); - _usedForkedSolutionCounter = new(); - - TelemetryLogging.Flushed += OnFlushed; } public void UpdateFindDocumentTelemetryData(bool success, string? workspaceKind) { var workspaceKindTelemetryProperty = success ? workspaceKind : "Failed"; - if (workspaceKindTelemetryProperty != null) { IncreaseFindDocumentCount(workspaceKindTelemetryProperty); } } - protected virtual void IncreaseFindDocumentCount(string workspaceInfo) + protected virtual void IncreaseFindDocumentCount(string workspaceCounterMetricName) { - _findDocumentResults.IncreaseCount(workspaceInfo); + TelemetryLogging.LogAggregatedCounter(FunctionId.LSP_FindDocumentInWorkspace, KeyValueLogMessage.Create(m => + { + m[TelemetryLogging.KeyName] = ServerTypeName + "." + workspaceCounterMetricName; + m[TelemetryLogging.KeyValue] = 1L; + m[TelemetryLogging.KeyMetricName] = workspaceCounterMetricName; + m["server"] = ServerTypeName; + m["workspace"] = workspaceCounterMetricName; + })); } public void UpdateUsedForkedSolutionCounter(bool usedForkedSolution) { - _usedForkedSolutionCounter.IncreaseCount(usedForkedSolution); + var metricName = usedForkedSolution ? "ForkedCount" : "NonForkedCount"; + TelemetryLogging.LogAggregatedCounter(FunctionId.LSP_UsedForkedSolution, KeyValueLogMessage.Create(m => + { + m[TelemetryLogging.KeyName] = ServerTypeName + "." + metricName; + m[TelemetryLogging.KeyValue] = 1L; + m[TelemetryLogging.KeyMetricName] = metricName; + m["server"] = ServerTypeName; + m["usedForkedSolution"] = usedForkedSolution; + })); } public void UpdateTelemetryData( @@ -68,122 +67,50 @@ public void UpdateTelemetryData( Result result) { // Store the request time metrics per LSP method. - TelemetryLogging.LogAggregated(FunctionId.LSP_TimeInQueue, KeyValueLogMessage.Create(m => + TelemetryLogging.LogAggregatedHistogram(FunctionId.LSP_TimeInQueue, KeyValueLogMessage.Create(m => { m[TelemetryLogging.KeyName] = ServerTypeName; - m[TelemetryLogging.KeyValue] = (int)queuedDuration.TotalMilliseconds; + m[TelemetryLogging.KeyValue] = (long)queuedDuration.TotalMilliseconds; m[TelemetryLogging.KeyMetricName] = "TimeInQueue"; m["server"] = ServerTypeName; m["method"] = methodName; m["language"] = language; })); - TelemetryLogging.LogAggregated(FunctionId.LSP_RequestDuration, KeyValueLogMessage.Create(m => + TelemetryLogging.LogAggregatedHistogram(FunctionId.LSP_RequestDuration, KeyValueLogMessage.Create(m => { - m[TelemetryLogging.KeyName] = ServerTypeName + "." + methodName; - m[TelemetryLogging.KeyValue] = (int)requestDuration.TotalMilliseconds; + m[TelemetryLogging.KeyName] = ServerTypeName + "." + methodName + "." + language; + m[TelemetryLogging.KeyValue] = (long)requestDuration.TotalMilliseconds; m[TelemetryLogging.KeyMetricName] = "RequestDuration"; m["server"] = ServerTypeName; m["method"] = methodName; m["language"] = language; })); - _requestCounters.GetOrAdd((methodName, language), (_) => new Counter()).IncrementCount(result); - } - - /// - /// Only output aggregate telemetry to the vs logger when the server instance is disposed - /// to avoid spamming the telemetry output with thousands of events - /// - public void Dispose() - { - if (Interlocked.Exchange(ref _disposed, 1) != 0) + var metricName = result switch { - return; - } + Result.Succeeded => "SucceededCount", + Result.Failed => "FailedCount", + Result.Cancelled => "CancelledCount", + _ => throw ExceptionUtilities.UnexpectedValue(result) + }; - // Flush all telemetry logged through TelemetryLogging - TelemetryLogging.Flush(); - - TelemetryLogging.Flushed -= OnFlushed; - } - - protected virtual void ReportFindDocumentCounter() - { - if (!_findDocumentResults.IsEmpty) + TelemetryLogging.LogAggregatedCounter(FunctionId.LSP_RequestCounter, KeyValueLogMessage.Create(m => { - TelemetryLogging.Log(FunctionId.LSP_FindDocumentInWorkspace, KeyValueLogMessage.Create(LogType.Trace, m => - { - m["server"] = ServerTypeName; - foreach (var kvp in _findDocumentResults) - { - var info = kvp.Key.ToString()!; - m[info] = kvp.Value.GetCount(); - } - })); - } - _findDocumentResults.Clear(); - } - - private void OnFlushed(object? sender, EventArgs e) - { - foreach (var kvp in _requestCounters) - { - TelemetryLogging.Log(FunctionId.LSP_RequestCounter, KeyValueLogMessage.Create(LogType.Trace, m => - { - m["server"] = ServerTypeName; - m["method"] = kvp.Key.Method; - m["language"] = kvp.Key.Language; - m["successful"] = kvp.Value.SucceededCount; - m["failed"] = kvp.Value.FailedCount; - m["cancelled"] = kvp.Value.CancelledCount; - })); - } - - ReportFindDocumentCounter(); - - if (!_usedForkedSolutionCounter.IsEmpty) - { - TelemetryLogging.Log(FunctionId.LSP_UsedForkedSolution, KeyValueLogMessage.Create(LogType.Trace, m => - { - m["server"] = ServerTypeName; - foreach (var kvp in _usedForkedSolutionCounter) - { - var info = kvp.Key.ToString()!; - m[info] = kvp.Value.GetCount(); - } - })); - } - - _requestCounters.Clear(); - _usedForkedSolutionCounter.Clear(); + m[TelemetryLogging.KeyName] = ServerTypeName + "." + methodName + "." + language + "." + metricName; + m[TelemetryLogging.KeyValue] = 1L; + m[TelemetryLogging.KeyMetricName] = metricName; + m["server"] = ServerTypeName; + m["method"] = methodName; + m["language"] = language; + })); } - private class Counter + public void Dispose() { - private int _succeededCount; - private int _failedCount; - private int _cancelledCount; - - public int SucceededCount => _succeededCount; - public int FailedCount => _failedCount; - public int CancelledCount => _cancelledCount; - - public void IncrementCount(Result result) - { - switch (result) - { - case Result.Succeeded: - Interlocked.Increment(ref _succeededCount); - break; - case Result.Failed: - Interlocked.Increment(ref _failedCount); - break; - case Result.Cancelled: - Interlocked.Increment(ref _cancelledCount); - break; - } - } + // Ensure that telemetry logged for this server instance is flushed before potentially creating a new instance. + // This is also called on disposal of the telemetry session, but will no-op if already flushed. + TelemetryLogging.Flush(); } internal enum Result diff --git a/src/VisualStudio/Core/Def/Telemetry/AbstractWorkspaceTelemetryService.cs b/src/VisualStudio/Core/Def/Telemetry/AbstractWorkspaceTelemetryService.cs index 435dca4a549b1..cb1ef8c812cbd 100644 --- a/src/VisualStudio/Core/Def/Telemetry/AbstractWorkspaceTelemetryService.cs +++ b/src/VisualStudio/Core/Def/Telemetry/AbstractWorkspaceTelemetryService.cs @@ -2,6 +2,7 @@ // The .NET Foundation licenses this file to you under the MIT license. // See the LICENSE file in the project root for more information. +using System; using System.Diagnostics; using System.Diagnostics.CodeAnalysis; using Microsoft.CodeAnalysis.ErrorReporting; @@ -12,7 +13,7 @@ namespace Microsoft.VisualStudio.LanguageServices.Telemetry; -internal abstract class AbstractWorkspaceTelemetryService : IWorkspaceTelemetryService +internal abstract class AbstractWorkspaceTelemetryService : IWorkspaceTelemetryService, IDisposable { public TelemetrySession? CurrentSession { get; private set; } @@ -49,4 +50,11 @@ public void RegisterUnexpectedExceptionLogger(TraceSource logger) public void UnregisterUnexpectedExceptionLogger(TraceSource logger) => FaultReporter.UnregisterLogger(logger); + + public void Dispose() + { + // Ensure any aggregate telemetry is flushed when the catalog is destroyed. + // It is fine for this to be called multiple times - if telemetry has already been flushed this will no-op. + TelemetryLogging.Flush(); + } } diff --git a/src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingTelemetryLog.cs b/src/VisualStudio/Core/Def/Telemetry/Shared/AbstractAggregatingLog.cs similarity index 62% rename from src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingTelemetryLog.cs rename to src/VisualStudio/Core/Def/Telemetry/Shared/AbstractAggregatingLog.cs index 711cf06437e77..915dbcdfa7db5 100644 --- a/src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingTelemetryLog.cs +++ b/src/VisualStudio/Core/Def/Telemetry/Shared/AbstractAggregatingLog.cs @@ -2,7 +2,6 @@ // The .NET Foundation licenses this file to you under the MIT license. // See the LICENSE file in the project root for more information. -using System; using System.Collections.Immutable; using Microsoft.CodeAnalysis.Internal.Log; using Microsoft.VisualStudio.Telemetry; @@ -13,11 +12,11 @@ namespace Microsoft.CodeAnalysis.Telemetry; /// -/// Provides a wrapper around the VSTelemetry histogram APIs to support aggregated telemetry. Each instance +/// Provides a wrapper around various VSTelemetry aggregating APIs to support aggregated telemetry. Each instance /// of this class corresponds to a specific FunctionId operation and can support aggregated values for each /// metric name logged. /// -internal sealed class AggregatingTelemetryLog : ITelemetryLog +internal abstract class AbstractAggregatingLog : ITelemetryLog where TAggregator : IInstrument { // Indicates version information which vs telemetry will use for our aggregated telemetry. This can be used // by Kusto queries to filter against telemetry versions which have the specified version and thus desired shape. @@ -25,21 +24,18 @@ internal sealed class AggregatingTelemetryLog : ITelemetryLog private readonly IMeter _meter; private readonly TelemetrySession _session; - private readonly HistogramConfiguration? _histogramConfiguration; private readonly string _eventName; private readonly FunctionId _functionId; private readonly object _flushLock; - private ImmutableDictionary Histogram, TelemetryEvent TelemetryEvent, object Lock)> _histograms = ImmutableDictionary, TelemetryEvent, object)>.Empty; + private ImmutableDictionary _aggregations = ImmutableDictionary.Empty; /// /// Creates a new aggregating telemetry log /// /// Telemetry session used to post events /// Used to derive meter name - /// Optional values indicating bucket boundaries in milliseconds. If not specified, - /// all histograms created will use the default histogram configuration - public AggregatingTelemetryLog(TelemetrySession session, FunctionId functionId, double[]? bucketBoundaries) + public AbstractAggregatingLog(TelemetrySession session, FunctionId functionId) { var meterName = TelemetryLogger.GetPropertyName(functionId, "meter"); var meterProvider = new VSTelemetryMeterProvider(); @@ -49,11 +45,6 @@ public AggregatingTelemetryLog(TelemetrySession session, FunctionId functionId, _eventName = TelemetryLogger.GetEventName(functionId); _functionId = functionId; _flushLock = new(); - - if (bucketBoundaries != null) - { - _histogramConfiguration = new HistogramConfiguration(bucketBoundaries); - } } /// @@ -71,10 +62,10 @@ public void Log(KeyValueLogMessage logMessage) if (!logMessage.Properties.TryGetValue(TelemetryLogging.KeyName, out var nameValue) || nameValue is not string name) throw ExceptionUtilities.Unreachable(); - if (!logMessage.Properties.TryGetValue(TelemetryLogging.KeyValue, out var valueValue) || valueValue is not int value) + if (!logMessage.Properties.TryGetValue(TelemetryLogging.KeyValue, out var valueValue) || valueValue is not TValue value) throw ExceptionUtilities.Unreachable(); - (var histogram, _, var histogramLock) = ImmutableInterlocked.GetOrAdd(ref _histograms, name, name => + (var aggregator, _, var aggregatorLock) = ImmutableInterlocked.GetOrAdd(ref _aggregations, name, name => { var telemetryEvent = new TelemetryEvent(_eventName); @@ -92,52 +83,46 @@ public void Log(KeyValueLogMessage logMessage) } } - var histogram = _meter.CreateHistogram(metricName, _histogramConfiguration); - var histogramLock = new object(); + var aggregator = CreateAggregator(_meter, metricName); + var aggregatorLock = new object(); - return (histogram, telemetryEvent, histogramLock); + return (aggregator, telemetryEvent, aggregatorLock); }); - lock (histogramLock) + lock (aggregatorLock) { - histogram.Record(value); + UpdateAggregator(aggregator, value); } } - public IDisposable? LogBlockTime(KeyValueLogMessage logMessage, int minThresholdMs) - { - if (!IsEnabled) - return null; + protected abstract TAggregator CreateAggregator(IMeter meter, string metricName); - if (!logMessage.Properties.TryGetValue(TelemetryLogging.KeyName, out var nameValue) || nameValue is not string) - throw ExceptionUtilities.Unreachable(); + protected abstract void UpdateAggregator(TAggregator aggregator, TValue value); - return new TimedTelemetryLogBlock(logMessage, minThresholdMs, telemetryLog: this); - } + protected abstract TelemetryMetricEvent CreateTelemetryEvent(TelemetryEvent telemetryEvent, TAggregator aggregator); - private bool IsEnabled => _session.IsOptedIn; + protected bool IsEnabled => _session.IsOptedIn; public void Flush() { // This lock ensures that multiple calls to Flush cannot occur simultaneously. // Without this lock, we would could potentially call PostMetricEvent multiple - // times for the same histogram. + // times for the same aggregation. lock (_flushLock) { - foreach (var (histogram, telemetryEvent, histogramLock) in _histograms.Values) + foreach (var (aggregator, telemetryEvent, aggregatorLock) in _aggregations.Values) { // This fine-grained lock ensures that the histogram isn't modified (via a Record call) - // during the creation of the TelemetryHistogramEvent or the PostMetricEvent + // during the creation of the TelemetryMetricEvent or the PostMetricEvent // call that operates on it. - lock (histogramLock) + lock (aggregatorLock) { - var histogramEvent = new TelemetryHistogramEvent(telemetryEvent, histogram); - - _session.PostMetricEvent(histogramEvent); + var aggregatorEvent = CreateTelemetryEvent(telemetryEvent, aggregator); + _session.PostMetricEvent(aggregatorEvent); } } - _histograms = ImmutableDictionary, TelemetryEvent, object)>.Empty; + _aggregations = ImmutableDictionary.Empty; } } } diff --git a/src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingCounterLog.cs b/src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingCounterLog.cs new file mode 100644 index 0000000000000..bb9ab02a21a3e --- /dev/null +++ b/src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingCounterLog.cs @@ -0,0 +1,37 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +using Microsoft.CodeAnalysis.Internal.Log; +using Microsoft.VisualStudio.Telemetry; +using Microsoft.VisualStudio.Telemetry.Metrics; +using Microsoft.VisualStudio.Telemetry.Metrics.Events; + +namespace Microsoft.CodeAnalysis.Telemetry; + +/// +/// Provides a wrapper around the VSTelemetry counter APIs to support aggregated counter telemetry. Each instance +/// of this class corresponds to a specific FunctionId operation and can support counting aggregated values for each +/// metric name logged. +/// +internal sealed class AggregatingCounterLog : AbstractAggregatingLog, long> +{ + public AggregatingCounterLog(TelemetrySession session, FunctionId functionId) : base(session, functionId) + { + } + + protected override ICounter CreateAggregator(IMeter meter, string metricName) + { + return meter.CreateCounter(metricName); + } + + protected override void UpdateAggregator(ICounter counter, long value) + { + counter.Add(value); + } + + protected override TelemetryMetricEvent CreateTelemetryEvent(TelemetryEvent telemetryEvent, ICounter counter) + { + return new TelemetryCounterEvent(telemetryEvent, counter); + } +} diff --git a/src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingHistogramLog.cs b/src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingHistogramLog.cs new file mode 100644 index 0000000000000..11e4a262cb250 --- /dev/null +++ b/src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingHistogramLog.cs @@ -0,0 +1,63 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +using System; +using Microsoft.CodeAnalysis.Internal.Log; +using Microsoft.VisualStudio.Telemetry; +using Microsoft.VisualStudio.Telemetry.Metrics; +using Microsoft.VisualStudio.Telemetry.Metrics.Events; +using Roslyn.Utilities; + +namespace Microsoft.CodeAnalysis.Telemetry; + +/// +/// Provides a wrapper around the VSTelemetry histogram APIs to support aggregated telemetry. Each instance +/// of this class corresponds to a specific FunctionId operation and can support aggregated values for each +/// metric name logged. +/// +internal sealed class AggregatingHistogramLog : AbstractAggregatingLog, long>, ITelemetryBlockLog +{ + private readonly HistogramConfiguration? _histogramConfiguration; + + /// + /// Creates a new aggregating telemetry log + /// + /// Telemetry session used to post events + /// Used to derive meter name + /// Optional values indicating bucket boundaries in milliseconds. If not specified, + /// all histograms created will use the default histogram configuration + public AggregatingHistogramLog(TelemetrySession session, FunctionId functionId, double[]? bucketBoundaries) : base(session, functionId) + { + if (bucketBoundaries != null) + { + _histogramConfiguration = new HistogramConfiguration(bucketBoundaries); + } + } + + public IDisposable? LogBlockTime(KeyValueLogMessage logMessage, int minThresholdMs) + { + if (!IsEnabled) + return null; + + if (!logMessage.Properties.TryGetValue(TelemetryLogging.KeyName, out var nameValue) || nameValue is not string) + throw ExceptionUtilities.Unreachable(); + + return new TimedTelemetryLogBlock(logMessage, minThresholdMs, telemetryLog: this); + } + + protected override IHistogram CreateAggregator(IMeter meter, string metricName) + { + return meter.CreateHistogram(metricName, _histogramConfiguration); + } + + protected override void UpdateAggregator(IHistogram histogram, long value) + { + histogram.Record(value); + } + + protected override TelemetryMetricEvent CreateTelemetryEvent(TelemetryEvent telemetryEvent, IHistogram histogram) + { + return new TelemetryHistogramEvent(telemetryEvent, histogram); + } +} diff --git a/src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingTelemetryLogManager.cs b/src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingTelemetryLogManager.cs deleted file mode 100644 index 2b3042e607592..0000000000000 --- a/src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingTelemetryLogManager.cs +++ /dev/null @@ -1,47 +0,0 @@ -// Licensed to the .NET Foundation under one or more agreements. -// The .NET Foundation licenses this file to you under the MIT license. -// See the LICENSE file in the project root for more information. - -using System.Collections.Immutable; -using Microsoft.CodeAnalysis.Internal.Log; -using Microsoft.VisualStudio.Telemetry; - -namespace Microsoft.CodeAnalysis.Telemetry; - -/// -/// Manages creation and obtaining aggregated telemetry logs. -/// -internal sealed class AggregatingTelemetryLogManager -{ - private readonly TelemetrySession _session; - - private ImmutableDictionary _aggregatingLogs = ImmutableDictionary.Empty; - - public AggregatingTelemetryLogManager(TelemetrySession session) - { - _session = session; - } - - public ITelemetryLog? GetLog(FunctionId functionId, double[]? bucketBoundaries) - { - if (!_session.IsOptedIn) - return null; - - return ImmutableInterlocked.GetOrAdd( - ref _aggregatingLogs, - functionId, - static (functionId, arg) => new AggregatingTelemetryLog(arg._session, functionId, arg.bucketBoundaries), - factoryArgument: (_session, bucketBoundaries)); - } - - public void Flush() - { - if (!_session.IsOptedIn) - return; - - foreach (var log in _aggregatingLogs.Values) - { - log.Flush(); - } - } -} diff --git a/src/VisualStudio/Core/Def/Telemetry/Shared/TelemetryLogProvider.cs b/src/VisualStudio/Core/Def/Telemetry/Shared/TelemetryLogProvider.cs index 042bf2b7f1bac..a21a3926fcf9f 100644 --- a/src/VisualStudio/Core/Def/Telemetry/Shared/TelemetryLogProvider.cs +++ b/src/VisualStudio/Core/Def/Telemetry/Shared/TelemetryLogProvider.cs @@ -2,6 +2,7 @@ // The .NET Foundation licenses this file to you under the MIT license. // See the LICENSE file in the project root for more information. +using System.Collections.Immutable; using Microsoft.CodeAnalysis.Internal.Log; using Microsoft.CodeAnalysis.Telemetry; using Microsoft.VisualStudio.Telemetry; @@ -13,13 +14,28 @@ namespace Microsoft.VisualStudio.LanguageServices.Telemetry; /// internal sealed class TelemetryLogProvider : ITelemetryLogProvider { - private readonly AggregatingTelemetryLogManager _aggregatingTelemetryLogManager; - private readonly VisualStudioTelemetryLogManager _visualStudioTelemetryLogManager; + private readonly TelemetrySession _session; + private readonly ILogger _telemetryLogger; + + /// + /// Manages instances of to provide in + /// + private ImmutableDictionary _logs = ImmutableDictionary.Empty; + + /// + /// Manages instances of to provide in + /// + private ImmutableDictionary _histogramLogs = ImmutableDictionary.Empty; + + /// + /// Manages instances of to provide in + /// + private ImmutableDictionary _counterLogs = ImmutableDictionary.Empty; private TelemetryLogProvider(TelemetrySession session, ILogger telemetryLogger) { - _aggregatingTelemetryLogManager = new AggregatingTelemetryLogManager(session); - _visualStudioTelemetryLogManager = new VisualStudioTelemetryLogManager(session, telemetryLogger); + _session = session; + _telemetryLogger = telemetryLogger; } public static TelemetryLogProvider Create(TelemetrySession session, ILogger telemetryLogger) @@ -34,17 +50,39 @@ public static TelemetryLogProvider Create(TelemetrySession session, ILogger tele /// /// Returns an for logging telemetry. /// - public ITelemetryLog? GetLog(FunctionId functionId) + public ITelemetryBlockLog? GetLog(FunctionId functionId) { - return _visualStudioTelemetryLogManager.GetLog(functionId); + if (!_session.IsOptedIn) + return null; + + return ImmutableInterlocked.GetOrAdd(ref _logs, functionId, functionId => new VisualStudioTelemetryLog(_telemetryLogger, functionId)); } /// /// Returns an aggregating for logging telemetry. /// - public ITelemetryLog? GetAggregatingLog(FunctionId functionId, double[]? bucketBoundaries) + public ITelemetryBlockLog? GetHistogramLog(FunctionId functionId, double[]? bucketBoundaries) + { + if (!_session.IsOptedIn) + return null; + + return ImmutableInterlocked.GetOrAdd( + ref _histogramLogs, + functionId, + static (functionId, arg) => new AggregatingHistogramLog(arg._session, functionId, arg.bucketBoundaries), + factoryArgument: (_session, bucketBoundaries)); + } + + public ITelemetryLog? GetCounterLog(FunctionId functionId) { - return _aggregatingTelemetryLogManager.GetLog(functionId, bucketBoundaries); + if (!_session.IsOptedIn) + return null; + + return ImmutableInterlocked.GetOrAdd( + ref _counterLogs, + functionId, + static (functionId, session) => new AggregatingCounterLog(session, functionId), + factoryArgument: _session); } /// @@ -52,6 +90,17 @@ public static TelemetryLogProvider Create(TelemetrySession session, ILogger tele /// public void Flush() { - _aggregatingTelemetryLogManager.Flush(); + if (!_session.IsOptedIn) + return; + + foreach (var log in _histogramLogs.Values) + { + log.Flush(); + } + + foreach (var log in _counterLogs.Values) + { + log.Flush(); + } } } diff --git a/src/VisualStudio/Core/Def/Telemetry/Shared/TimedTelemetryLogBlock.cs b/src/VisualStudio/Core/Def/Telemetry/Shared/TimedTelemetryLogBlock.cs index a2ffd6601757b..aab88ae4358c7 100644 --- a/src/VisualStudio/Core/Def/Telemetry/Shared/TimedTelemetryLogBlock.cs +++ b/src/VisualStudio/Core/Def/Telemetry/Shared/TimedTelemetryLogBlock.cs @@ -32,7 +32,7 @@ public TimedTelemetryLogBlock(KeyValueLogMessage logMessage, int minThresholdMs, public void Dispose() { - var elapsed = (int)_stopwatch.Elapsed.TotalMilliseconds; + var elapsed = (long)_stopwatch.Elapsed.TotalMilliseconds; if (elapsed >= _minThresholdMs) { var logMessage = KeyValueLogMessage.Create(m => diff --git a/src/VisualStudio/Core/Def/Telemetry/Shared/VisualStudioTelemetryLog.cs b/src/VisualStudio/Core/Def/Telemetry/Shared/VisualStudioTelemetryLog.cs index a6486f01825a5..6b8c429398539 100644 --- a/src/VisualStudio/Core/Def/Telemetry/Shared/VisualStudioTelemetryLog.cs +++ b/src/VisualStudio/Core/Def/Telemetry/Shared/VisualStudioTelemetryLog.cs @@ -8,7 +8,7 @@ namespace Microsoft.VisualStudio.LanguageServices.Telemetry; -internal sealed class VisualStudioTelemetryLog : ITelemetryLog +internal sealed class VisualStudioTelemetryLog : ITelemetryBlockLog { private readonly ILogger _telemetryLogger; private readonly FunctionId _functionId; diff --git a/src/VisualStudio/Core/Def/Telemetry/Shared/VisualStudioTelemetryLogManager.cs b/src/VisualStudio/Core/Def/Telemetry/Shared/VisualStudioTelemetryLogManager.cs deleted file mode 100644 index e67956dc34dac..0000000000000 --- a/src/VisualStudio/Core/Def/Telemetry/Shared/VisualStudioTelemetryLogManager.cs +++ /dev/null @@ -1,32 +0,0 @@ -// Licensed to the .NET Foundation under one or more agreements. -// The .NET Foundation licenses this file to you under the MIT license. -// See the LICENSE file in the project root for more information. - -using System.Collections.Immutable; -using Microsoft.CodeAnalysis.Internal.Log; -using Microsoft.CodeAnalysis.Telemetry; -using Microsoft.VisualStudio.Telemetry; - -namespace Microsoft.VisualStudio.LanguageServices.Telemetry; - -internal sealed class VisualStudioTelemetryLogManager -{ - private readonly TelemetrySession _session; - private readonly ILogger _telemetryLogger; - - private ImmutableDictionary _logs = ImmutableDictionary.Empty; - - public VisualStudioTelemetryLogManager(TelemetrySession session, ILogger telemetryLogger) - { - _session = session; - _telemetryLogger = telemetryLogger; - } - - public ITelemetryLog? GetLog(FunctionId functionId) - { - if (!_session.IsOptedIn) - return null; - - return ImmutableInterlocked.GetOrAdd(ref _logs, functionId, functionId => new VisualStudioTelemetryLog(_telemetryLogger, functionId)); - } -} diff --git a/src/VisualStudio/DevKit/Impl/Logging/VSCodeTelemetryLogger.cs b/src/VisualStudio/DevKit/Impl/Logging/VSCodeTelemetryLogger.cs index 410e5dac79f51..99c70e13fc181 100644 --- a/src/VisualStudio/DevKit/Impl/Logging/VSCodeTelemetryLogger.cs +++ b/src/VisualStudio/DevKit/Impl/Logging/VSCodeTelemetryLogger.cs @@ -132,6 +132,8 @@ public void ReportFault(string eventName, string description, int logLevel, bool public void Dispose() { + // Ensure that we flush any pending telemetry *before* we dispose of the telemetry session. + TelemetryLogging.Flush(); _telemetrySession?.Dispose(); _telemetrySession = null; } diff --git a/src/Workspaces/Core/Portable/CodeActions/CodeAction.cs b/src/Workspaces/Core/Portable/CodeActions/CodeAction.cs index 925eef02d7e7b..c11b685452841 100644 --- a/src/Workspaces/Core/Portable/CodeActions/CodeAction.cs +++ b/src/Workspaces/Core/Portable/CodeActions/CodeAction.cs @@ -260,7 +260,7 @@ public Task> GetPreviewOperationsAsync(Cance internal async Task> GetPreviewOperationsAsync( Solution originalSolution, CancellationToken cancellationToken) { - using var _ = TelemetryLogging.LogBlockTimeAggregated(FunctionId.SuggestedAction_Preview_Summary, $"Total"); + using var _ = TelemetryLogging.LogBlockTimeAggregatedHistogram(FunctionId.SuggestedAction_Preview_Summary, $"Total"); var operations = await this.ComputePreviewOperationsAsync(cancellationToken).ConfigureAwait(false); diff --git a/src/Workspaces/Core/Portable/Telemetry/ITelemetryBlockLog.cs b/src/Workspaces/Core/Portable/Telemetry/ITelemetryBlockLog.cs new file mode 100644 index 0000000000000..5860c56141603 --- /dev/null +++ b/src/Workspaces/Core/Portable/Telemetry/ITelemetryBlockLog.cs @@ -0,0 +1,19 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +using System; +using Microsoft.CodeAnalysis.Internal.Log; + +namespace Microsoft.CodeAnalysis.Telemetry; + +internal interface ITelemetryBlockLog : ITelemetryLog +{ + /// + /// Adds an execution time telemetry event representing + /// only if block duration meets or exceeds milliseconds. + /// + /// Event data to be sent + /// Optional parameter used to determine whether to send the telemetry event (in milliseconds) + public IDisposable? LogBlockTime(KeyValueLogMessage logMessage, int minThresholdMs = -1); +} diff --git a/src/Workspaces/Core/Portable/Telemetry/ITelemetryLog.cs b/src/Workspaces/Core/Portable/Telemetry/ITelemetryLog.cs index acbd153ca9a87..585b3ec32a858 100644 --- a/src/Workspaces/Core/Portable/Telemetry/ITelemetryLog.cs +++ b/src/Workspaces/Core/Portable/Telemetry/ITelemetryLog.cs @@ -13,12 +13,4 @@ internal interface ITelemetryLog /// Adds a telemetry event with values obtained from context message /// public void Log(KeyValueLogMessage logMessage); - - /// - /// Adds an execution time telemetry event representing - /// only if block duration meets or exceeds milliseconds. - /// - /// Event data to be sent - /// Optional parameter used to determine whether to send the telemetry event (in milliseconds) - public IDisposable? LogBlockTime(KeyValueLogMessage logMessage, int minThresholdMs = -1); } diff --git a/src/Workspaces/Core/Portable/Telemetry/ITelemetryLogProvider.cs b/src/Workspaces/Core/Portable/Telemetry/ITelemetryLogProvider.cs index 9d74257933c46..8ef0da7052293 100644 --- a/src/Workspaces/Core/Portable/Telemetry/ITelemetryLogProvider.cs +++ b/src/Workspaces/Core/Portable/Telemetry/ITelemetryLogProvider.cs @@ -12,15 +12,21 @@ internal interface ITelemetryLogProvider /// Returns an for logging telemetry. /// /// FunctionId representing the telemetry operation - public ITelemetryLog? GetLog(FunctionId functionId); + public ITelemetryBlockLog? GetLog(FunctionId functionId); /// - /// Returns an aggregating for logging telemetry. + /// Returns an aggregating for logging histogram based telemetry. /// /// FunctionId representing the telemetry operation /// Optional values indicating bucket boundaries in milliseconds. If not specified, /// all aggregating events created will use a default configuration - public ITelemetryLog? GetAggregatingLog(FunctionId functionId, double[]? bucketBoundaries = null); + public ITelemetryBlockLog? GetHistogramLog(FunctionId functionId, double[]? bucketBoundaries = null); + + /// + /// Returns an aggregating for logging counter telemetry. + /// + /// FunctionId representing the telemetry operation + public ITelemetryLog? GetCounterLog(FunctionId functionId); /// /// Flushes all telemetry logs diff --git a/src/Workspaces/Core/Portable/Telemetry/TelemetryLogging.cs b/src/Workspaces/Core/Portable/Telemetry/TelemetryLogging.cs index 07202cfab0098..28e26b51ce63b 100644 --- a/src/Workspaces/Core/Portable/Telemetry/TelemetryLogging.cs +++ b/src/Workspaces/Core/Portable/Telemetry/TelemetryLogging.cs @@ -24,8 +24,6 @@ internal static class TelemetryLogging public const string KeyLanguageName = "LanguageName"; public const string KeyMetricName = "MetricName"; - public static event EventHandler? Flushed; - public static void SetLogProvider(ITelemetryLogProvider logProvider) { s_logProvider = logProvider; @@ -59,9 +57,9 @@ public static void Log(FunctionId functionId, KeyValueLogMessage logMessage) /// Adds information to an aggregated telemetry event representing the operation /// with the specified name and value. /// - public static void LogAggregated(FunctionId functionId, TelemetryLoggingInterpolatedStringHandler name, int value) + public static void LogAggregatedHistogram(FunctionId functionId, TelemetryLoggingInterpolatedStringHandler name, long value) { - if (GetAggregatingLog(functionId) is not { } aggregatingLog) + if (GetHistogramLog(functionId) is not { } aggregatingLog) return; var logMessage = KeyValueLogMessage.Create(m => @@ -74,9 +72,9 @@ public static void LogAggregated(FunctionId functionId, TelemetryLoggingInterpol logMessage.Free(); } - public static void LogAggregated(FunctionId functionId, KeyValueLogMessage logMessage) + public static void LogAggregatedHistogram(FunctionId functionId, KeyValueLogMessage logMessage) { - if (GetAggregatingLog(functionId) is not { } aggregatingLog) + if (GetHistogramLog(functionId) is not { } aggregatingLog) return; aggregatingLog.Log(logMessage); @@ -88,9 +86,9 @@ public static void LogAggregated(FunctionId functionId, KeyValueLogMessage logMe /// with metric only if the block duration meets or exceeds milliseconds. /// /// Optional parameter used to determine whether to send the telemetry event - public static IDisposable? LogBlockTimeAggregated(FunctionId functionId, TelemetryLoggingInterpolatedStringHandler metricName, int minThresholdMs = -1) + public static IDisposable? LogBlockTimeAggregatedHistogram(FunctionId functionId, TelemetryLoggingInterpolatedStringHandler metricName, int minThresholdMs = -1) { - if (GetAggregatingLog(functionId) is not { } aggregatingLog) + if (GetHistogramLog(functionId) is not { } aggregatingLog) return null; var logMessage = KeyValueLogMessage.Create(m => @@ -101,10 +99,19 @@ public static void LogAggregated(FunctionId functionId, KeyValueLogMessage logMe return aggregatingLog.LogBlockTime(logMessage, minThresholdMs); } + public static void LogAggregatedCounter(FunctionId functionId, KeyValueLogMessage logMessage) + { + if (GetCounterLog(functionId) is not { } aggregatingLog) + return; + + aggregatingLog.Log(logMessage); + logMessage.Free(); + } + /// /// Returns non-aggregating telemetry log. /// - public static ITelemetryLog? GetLog(FunctionId functionId) + public static ITelemetryBlockLog? GetLog(FunctionId functionId) { return s_logProvider?.GetLog(functionId); } @@ -112,16 +119,19 @@ public static void LogAggregated(FunctionId functionId, KeyValueLogMessage logMe /// /// Returns aggregating telemetry log. /// - public static ITelemetryLog? GetAggregatingLog(FunctionId functionId, double[]? bucketBoundaries = null) + private static ITelemetryBlockLog? GetHistogramLog(FunctionId functionId, double[]? bucketBoundaries = null) + { + return s_logProvider?.GetHistogramLog(functionId, bucketBoundaries); + } + + private static ITelemetryLog? GetCounterLog(FunctionId functionId) { - return s_logProvider?.GetAggregatingLog(functionId, bucketBoundaries); + return s_logProvider?.GetCounterLog(functionId); } public static void Flush() { s_logProvider?.Flush(); - - Flushed?.Invoke(null, EventArgs.Empty); } private static async Task PostCollectedTelemetryAsync(CancellationToken cancellationToken) diff --git a/src/Workspaces/Remote/ServiceHub/Services/DiagnosticAnalyzer/PerformanceTrackerService.cs b/src/Workspaces/Remote/ServiceHub/Services/DiagnosticAnalyzer/PerformanceTrackerService.cs index 139d4c086e0d4..c7f1264d27979 100644 --- a/src/Workspaces/Remote/ServiceHub/Services/DiagnosticAnalyzer/PerformanceTrackerService.cs +++ b/src/Workspaces/Remote/ServiceHub/Services/DiagnosticAnalyzer/PerformanceTrackerService.cs @@ -66,9 +66,9 @@ public void AddSnapshot(IEnumerable snapshot, int unitC { const int PerformAnalysisTelemetryDelay = 250; - var delay = (int)perfInfo.TimeSpan.TotalMilliseconds; + var delay = (long)perfInfo.TimeSpan.TotalMilliseconds; - TelemetryLogging.LogAggregated(FunctionId.PerformAnalysis_Summary, $"IndividualTimes", delay); + TelemetryLogging.LogAggregatedHistogram(FunctionId.PerformAnalysis_Summary, $"IndividualTimes", delay); if (delay > PerformAnalysisTelemetryDelay) { diff --git a/src/Workspaces/Remote/ServiceHub/Services/DiagnosticAnalyzer/RemoteDiagnosticAnalyzerService.cs b/src/Workspaces/Remote/ServiceHub/Services/DiagnosticAnalyzer/RemoteDiagnosticAnalyzerService.cs index 3d2715001f177..e2fa645f5e163 100644 --- a/src/Workspaces/Remote/ServiceHub/Services/DiagnosticAnalyzer/RemoteDiagnosticAnalyzerService.cs +++ b/src/Workspaces/Remote/ServiceHub/Services/DiagnosticAnalyzer/RemoteDiagnosticAnalyzerService.cs @@ -44,7 +44,7 @@ public async ValueTask CalculateDiagnosti // Complete RPC right away so the client can start reading from the stream. // The fire-and forget task starts writing to the output stream and the client will read it until it reads all expected data. - using (TelemetryLogging.LogBlockTimeAggregated(FunctionId.PerformAnalysis_Summary, $"Total")) + using (TelemetryLogging.LogBlockTimeAggregatedHistogram(FunctionId.PerformAnalysis_Summary, $"Total")) using (RoslynLogger.LogBlock(FunctionId.CodeAnalysisService_CalculateDiagnosticsAsync, arguments.ProjectId.DebugName, cancellationToken)) { return await RunWithSolutionAsync(