From 1972097140cf2de1260b8377247e51c42538b8f9 Mon Sep 17 00:00:00 2001 From: David Barbet Date: Fri, 4 Oct 2024 16:04:23 -0700 Subject: [PATCH 1/7] Allow more specific LSP services to override Any LSP services --- .../Telemetry/VSCodeRequestTelemetryLogger.cs | 62 +++++++++ .../{ => Telemetry}/RequestTelemetryLogger.cs | 40 +++--- .../RequestTelemetryLoggerFactory.cs | 0 .../Protocol/LspServices/LspServices.cs | 59 +++++---- .../ProtocolUnitTests/LspServicesTests.cs | 120 ++++++++++++++++++ .../Compiler/Core/Log/FunctionId.cs | 5 +- 6 files changed, 247 insertions(+), 39 deletions(-) create mode 100644 src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Telemetry/VSCodeRequestTelemetryLogger.cs rename src/LanguageServer/Protocol/Handler/{ => Telemetry}/RequestTelemetryLogger.cs (93%) rename src/LanguageServer/Protocol/Handler/{ => Telemetry}/RequestTelemetryLoggerFactory.cs (100%) create mode 100644 src/LanguageServer/ProtocolUnitTests/LspServicesTests.cs diff --git a/src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Telemetry/VSCodeRequestTelemetryLogger.cs b/src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Telemetry/VSCodeRequestTelemetryLogger.cs new file mode 100644 index 0000000000000..85bcdc2bcd7ff --- /dev/null +++ b/src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Telemetry/VSCodeRequestTelemetryLogger.cs @@ -0,0 +1,62 @@ +// 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 System.Collections.Concurrent; +using System.Collections.Generic; +using System.Composition; +using System.Linq; +using System.Text; +using System.Threading.Tasks; +using Microsoft.CodeAnalysis.Internal.Log; +using Microsoft.CodeAnalysis.LanguageServer.Handler; +using Microsoft.CodeAnalysis.Telemetry; + +//namespace Microsoft.CodeAnalysis.LanguageServer.Telemetry; + +//internal class VSCodeRequestTelemetryLogger : RequestTelemetryLogger +//{ +// /// +// /// Tracks whether or not the initial project load has completed so we can see +// /// how often we get misc file requests after we've loaded. +// /// +// private static bool _initialProjectLoadCompleted = false; + +// private readonly ConcurrentDictionary> _findDocumentCounters; + +// public VSCodeRequestTelemetryLogger(string serverTypeName) : base(serverTypeName) +// { +// } + +// public static void ReportProjectInitializationComplete() +// { +// _initialProjectLoadCompleted = true; +// Logger.Log(FunctionId.VSCode_Projects_Load_Completed, logLevel: LogLevel.Information); +// } + +// public static void ReportProjectLoadStarted() +// { +// Logger.Log(FunctionId.VSCode_Project_Load_Started, logLevel: LogLevel.Information); +// } + +// protected override void IncreaseFindDocumentCount(string workspaceInfo) +// { +// TelemetryLogging.LogAggregated(FunctionId.LSP_FindDocumentInWorkspace, KeyValueLogMessage.Create(m => +// { +// m[TelemetryLogging.KeyName] = _serverTypeName; +// m[TelemetryLogging.KeyValue] = (int)queuedDuration.TotalMilliseconds; +// m[TelemetryLogging.KeyMetricName] = "Count"; +// m["server"] = _serverTypeName; +// m["method"] = methodName; +// m["language"] = language; +// })); + +// base.IncreaseFindDocumentCount(workspaceInfo); +// } + +// protected override void ReportFindDocumentCounter() +// { +// base.ReportFindDocumentCounter(); +// } +//} diff --git a/src/LanguageServer/Protocol/Handler/RequestTelemetryLogger.cs b/src/LanguageServer/Protocol/Handler/Telemetry/RequestTelemetryLogger.cs similarity index 93% rename from src/LanguageServer/Protocol/Handler/RequestTelemetryLogger.cs rename to src/LanguageServer/Protocol/Handler/Telemetry/RequestTelemetryLogger.cs index 68e6ed6b8cd5d..2a3980888581a 100644 --- a/src/LanguageServer/Protocol/Handler/RequestTelemetryLogger.cs +++ b/src/LanguageServer/Protocol/Handler/Telemetry/RequestTelemetryLogger.cs @@ -14,7 +14,7 @@ namespace Microsoft.CodeAnalysis.LanguageServer.Handler; /// Logs metadata on LSP requests (duration, success / failure metrics) /// for this particular LSP server instance. /// -internal sealed class RequestTelemetryLogger : IDisposable, ILspService +internal class RequestTelemetryLogger : IDisposable, ILspService { private readonly string _serverTypeName; @@ -46,10 +46,15 @@ public void UpdateFindDocumentTelemetryData(bool success, string? workspaceKind) if (workspaceKindTelemetryProperty != null) { - _findDocumentResults.IncreaseCount(workspaceKindTelemetryProperty); + IncreaseFindDocumentCount(workspaceKindTelemetryProperty); } } + protected virtual void IncreaseFindDocumentCount(string workspaceInfo) + { + _findDocumentResults.IncreaseCount(workspaceInfo); + } + public void UpdateUsedForkedSolutionCounter(bool usedForkedSolution) { _usedForkedSolutionCounter.IncreaseCount(usedForkedSolution); @@ -103,6 +108,22 @@ public void Dispose() TelemetryLogging.Flushed -= OnFlushed; } + protected virtual void ReportFindDocumentCounter() + { + if (!_findDocumentResults.IsEmpty) + { + 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(); + } + })); + } + } + private void OnFlushed(object? sender, EventArgs e) { foreach (var kvp in _requestCounters) @@ -118,18 +139,7 @@ private void OnFlushed(object? sender, EventArgs e) })); } - if (!_findDocumentResults.IsEmpty) - { - 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(); - } - })); - } + ReportFindDocumentCounter(); if (!_usedForkedSolutionCounter.IsEmpty) { @@ -149,7 +159,7 @@ private void OnFlushed(object? sender, EventArgs e) _usedForkedSolutionCounter.Clear(); } - private class Counter + protected class Counter { private int _succeededCount; private int _failedCount; diff --git a/src/LanguageServer/Protocol/Handler/RequestTelemetryLoggerFactory.cs b/src/LanguageServer/Protocol/Handler/Telemetry/RequestTelemetryLoggerFactory.cs similarity index 100% rename from src/LanguageServer/Protocol/Handler/RequestTelemetryLoggerFactory.cs rename to src/LanguageServer/Protocol/Handler/Telemetry/RequestTelemetryLoggerFactory.cs diff --git a/src/LanguageServer/Protocol/LspServices/LspServices.cs b/src/LanguageServer/Protocol/LspServices/LspServices.cs index e104066755c89..b2417c69b7d6b 100644 --- a/src/LanguageServer/Protocol/LspServices/LspServices.cs +++ b/src/LanguageServer/Protocol/LspServices/LspServices.cs @@ -7,6 +7,7 @@ using System.Collections.Generic; using System.Collections.Immutable; using System.Diagnostics.CodeAnalysis; +using System.Linq; using Microsoft.CodeAnalysis.ErrorReporting; using Microsoft.CodeAnalysis.PooledObjects; using Microsoft.CommonLanguageServerProtocol.Framework; @@ -40,36 +41,48 @@ public LspServices( { var serviceMap = new Dictionary>(); - // Convert MEF exported service factories to the lazy LSP services that they create. - foreach (var lazyServiceFactory in mefLspServiceFactories) - { - var metadata = lazyServiceFactory.Metadata; + // Add services from factories exported for this server kind. + foreach (var lazyServiceFactory in mefLspServiceFactories.Where(f => f.Metadata.ServerKind == serverKind)) + AddSpecificService(new(() => lazyServiceFactory.Value.CreateILspService(this, serverKind), lazyServiceFactory.Metadata)); - // Make sure that we only include services exported for the specified server kind (or NotSpecified). - if (metadata.ServerKind == serverKind || - metadata.ServerKind == WellKnownLspServerKinds.Any) - { - serviceMap.Add( - metadata.TypeRef.TypeName, - new(() => lazyServiceFactory.Value.CreateILspService(this, serverKind), metadata)); - } - } + // Add services exported for this server kind. + foreach (var lazyService in mefLspServices.Where(s => s.Metadata.ServerKind == serverKind)) + AddSpecificService(lazyService); - foreach (var lazyService in mefLspServices) - { - var metadata = lazyService.Metadata; + // Add services from factories exported for any (if there is not already an existing service for the specific server kind). + foreach (var lazyServiceFactory in mefLspServiceFactories.Where(f => f.Metadata.ServerKind == WellKnownLspServerKinds.Any)) + TryAddAnyService(new(() => lazyServiceFactory.Value.CreateILspService(this, serverKind), lazyServiceFactory.Metadata)); - // Make sure that we only include services exported for the specified server kind (or NotSpecified). - if (metadata.ServerKind == serverKind || - metadata.ServerKind == WellKnownLspServerKinds.Any) - { - serviceMap.Add(metadata.TypeRef.TypeName, lazyService); - } - } + // Add services exported for any (if there is not already an existing service for the specific server kind). + foreach (var lazyService in mefLspServices.Where(s => s.Metadata.ServerKind == WellKnownLspServerKinds.Any)) + TryAddAnyService(lazyService); _lazyMefLspServices = serviceMap.ToFrozenDictionary(); _baseServices = baseServices; + + void AddSpecificService(Lazy serviceGetter) + { + var metadata = serviceGetter.Metadata; + Contract.ThrowIfFalse(metadata.ServerKind == serverKind); + serviceMap.Add(metadata.TypeRef.TypeName, serviceGetter); + } + + void TryAddAnyService(Lazy serviceGetter) + { + var metadata = serviceGetter.Metadata; + Contract.ThrowIfFalse(metadata.ServerKind == WellKnownLspServerKinds.Any); + if (!serviceMap.TryGetValue(metadata.TypeRef.TypeName, out var existing)) + { + serviceMap.Add(metadata.TypeRef.TypeName, serviceGetter); + } + else + { + // Make sure we're not trying to add a duplicate Any service, but otherwise we should skip adding + // this service as we already have a more specific service available. + Contract.ThrowIfTrue(existing.Metadata.ServerKind == WellKnownLspServerKinds.Any); + } + } } public T GetRequiredService() where T : notnull diff --git a/src/LanguageServer/ProtocolUnitTests/LspServicesTests.cs b/src/LanguageServer/ProtocolUnitTests/LspServicesTests.cs new file mode 100644 index 0000000000000..0e565059b8d5e --- /dev/null +++ b/src/LanguageServer/ProtocolUnitTests/LspServicesTests.cs @@ -0,0 +1,120 @@ +// 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 System.Composition; +using System.Threading.Tasks; +using Microsoft.CodeAnalysis.Host.Mef; +using Microsoft.CodeAnalysis.Test.Utilities; +using Roslyn.Test.Utilities; +using Xunit; +using Xunit.Abstractions; + +namespace Microsoft.CodeAnalysis.LanguageServer.UnitTests; + +[UseExportProvider] +public class LspServicesTests(ITestOutputHelper testOutputHelper) : AbstractLanguageServerProtocolTests(testOutputHelper) +{ + [Theory, CombinatorialData] + public async Task ReturnsSpecificLspService(bool mutatingLspWorkspace) + { + var composition = base.Composition.AddParts(typeof(CSharpLspService), typeof(CSharpLspServiceFactory)); + await using var server = await CreateTestLspServerAsync("", mutatingLspWorkspace, initializationOptions: new() { ServerKind = WellKnownLspServerKinds.CSharpVisualBasicLspServer }, composition); + + var lspService = server.GetRequiredLspService(); + Assert.True(lspService is CSharpLspService); + + var lspServiceFromFactory = server.GetRequiredLspService(); + Assert.Equal(typeof(CSharpLspServiceFactory).Name, lspServiceFromFactory.FactoryName); + } + + [Theory, CombinatorialData] + public async Task SpecificLspServiceOverridesAny(bool mutatingLspWorkspace) + { + var composition = base.Composition.AddParts(typeof(CSharpLspService), typeof(AnyLspService), typeof(CSharpLspServiceFactory), typeof(AnyLspServiceFactory)); + await using var server = await CreateTestLspServerAsync("", mutatingLspWorkspace, initializationOptions: new() { ServerKind = WellKnownLspServerKinds.CSharpVisualBasicLspServer }, composition); + + var lspService = server.GetRequiredLspService(); + Assert.True(lspService is CSharpLspService); + + var lspServiceFromFactory = server.GetRequiredLspService(); + Assert.Equal(typeof(CSharpLspServiceFactory).Name, lspServiceFromFactory.FactoryName); + } + + [Theory, CombinatorialData] + public async Task ReturnsAnyLspService(bool mutatingLspWorkspace) + { + var composition = base.Composition.AddParts(typeof(AnyLspService), typeof(AnyLspServiceFactory)); + await using var server = await CreateTestLspServerAsync("", mutatingLspWorkspace, initializationOptions: new() { ServerKind = WellKnownLspServerKinds.CSharpVisualBasicLspServer }, composition); + + var lspService = server.GetRequiredLspService(); + Assert.True(lspService is AnyLspService); + + var lspServiceFromFactory = server.GetRequiredLspService(); + Assert.Equal(typeof(AnyLspServiceFactory).Name, lspServiceFromFactory.FactoryName); + } + + [Theory, CombinatorialData] + public async Task DuplicateSpecificServicesThrow(bool mutatingLspWorkspace) + { + var composition = base.Composition.AddParts(typeof(CSharpLspService), typeof(CSharpLspServiceFactory), typeof(DuplicateCSharpLspService), typeof(DuplicateCSharpLspServiceFactory)); + await Assert.ThrowsAnyAsync(async () => await CreateTestLspServerAsync("", mutatingLspWorkspace, initializationOptions: new() { ServerKind = WellKnownLspServerKinds.CSharpVisualBasicLspServer }, composition)); + } + + [Theory, CombinatorialData] + public async Task DuplicateAnyServicesThrow(bool mutatingLspWorkspace) + { + var composition = base.Composition.AddParts(typeof(AnyLspService), typeof(AnyLspServiceFactory), typeof(DuplicateAnyLspService), typeof(DuplicateAnyLspServiceFactory)); + await Assert.ThrowsAnyAsync(async () => await CreateTestLspServerAsync("", mutatingLspWorkspace, initializationOptions: new() { ServerKind = WellKnownLspServerKinds.CSharpVisualBasicLspServer }, composition)); + } + + internal class TestLspService : ILspService { } + + internal record class TestLspServiceFromFactory(string FactoryName) : ILspService { } + + internal class TestLspServiceFactory : ILspServiceFactory + { + public ILspService CreateILspService(LspServices lspServices, WellKnownLspServerKinds serverKind) => new TestLspServiceFromFactory(this.GetType().Name); + } + + [ExportStatelessLspService(typeof(TestLspService), ProtocolConstants.RoslynLspLanguagesContract, WellKnownLspServerKinds.CSharpVisualBasicLspServer), Shared] + [method: ImportingConstructor] + [method: Obsolete(MefConstruction.ImportingConstructorMessage, error: true)] + internal class CSharpLspService() : TestLspService { } + + [ExportLspServiceFactory(typeof(TestLspServiceFromFactory), ProtocolConstants.RoslynLspLanguagesContract, WellKnownLspServerKinds.CSharpVisualBasicLspServer), Shared] + [method: ImportingConstructor] + [method: Obsolete(MefConstruction.ImportingConstructorMessage, error: true)] + internal class CSharpLspServiceFactory() : TestLspServiceFactory { } + + [ExportStatelessLspService(typeof(TestLspService), ProtocolConstants.RoslynLspLanguagesContract, WellKnownLspServerKinds.Any), Shared] + [method: ImportingConstructor] + [method: Obsolete(MefConstruction.ImportingConstructorMessage, error: true)] + internal class AnyLspService() : TestLspService { } + + [ExportLspServiceFactory(typeof(TestLspServiceFromFactory), ProtocolConstants.RoslynLspLanguagesContract, WellKnownLspServerKinds.Any), Shared] + [method: ImportingConstructor] + [method: Obsolete(MefConstruction.ImportingConstructorMessage, error: true)] + internal class AnyLspServiceFactory() : TestLspServiceFactory { } + + [ExportStatelessLspService(typeof(TestLspService), ProtocolConstants.RoslynLspLanguagesContract, WellKnownLspServerKinds.CSharpVisualBasicLspServer), Shared] + [method: ImportingConstructor] + [method: Obsolete(MefConstruction.ImportingConstructorMessage, error: true)] + internal class DuplicateCSharpLspService() : TestLspService { } + + [ExportLspServiceFactory(typeof(TestLspServiceFromFactory), ProtocolConstants.RoslynLspLanguagesContract, WellKnownLspServerKinds.CSharpVisualBasicLspServer), Shared] + [method: ImportingConstructor] + [method: Obsolete(MefConstruction.ImportingConstructorMessage, error: true)] + internal class DuplicateCSharpLspServiceFactory() : CSharpLspServiceFactory { } + + [ExportStatelessLspService(typeof(TestLspService), ProtocolConstants.RoslynLspLanguagesContract, WellKnownLspServerKinds.Any), Shared] + [method: ImportingConstructor] + [method: Obsolete(MefConstruction.ImportingConstructorMessage, error: true)] + internal class DuplicateAnyLspService() : TestLspService { } + + [ExportLspServiceFactory(typeof(TestLspServiceFromFactory), ProtocolConstants.RoslynLspLanguagesContract, WellKnownLspServerKinds.Any), Shared] + [method: ImportingConstructor] + [method: Obsolete(MefConstruction.ImportingConstructorMessage, error: true)] + internal class DuplicateAnyLspServiceFactory() : CSharpLspServiceFactory { } +} diff --git a/src/Workspaces/SharedUtilitiesAndExtensions/Compiler/Core/Log/FunctionId.cs b/src/Workspaces/SharedUtilitiesAndExtensions/Compiler/Core/Log/FunctionId.cs index 77c0c94bde897..0575f570a170c 100644 --- a/src/Workspaces/SharedUtilitiesAndExtensions/Compiler/Core/Log/FunctionId.cs +++ b/src/Workspaces/SharedUtilitiesAndExtensions/Compiler/Core/Log/FunctionId.cs @@ -634,5 +634,8 @@ internal enum FunctionId Copilot_On_The_Fly_Docs_Results_Canceled = 814, Copilot_On_The_Fly_Docs_Get_Counts = 815, Copilot_On_The_Fly_Docs_Content_Excluded = 816, - Copilot_Rename = 851 + Copilot_Rename = 851, + + VSCode_Project_Load_Started = 860, + VSCode_Projects_Load_Completed = 861, } From 23bd767c17cca2b5f10faa839ab19acc7178494d Mon Sep 17 00:00:00 2001 From: David Barbet Date: Fri, 4 Oct 2024 16:38:04 -0700 Subject: [PATCH 2/7] Add LSP funnel telemetry to help indicate when drop offs occur --- .../ProjectInitializationHandler.cs | 2 + .../WorkspaceProjectFactoryService.cs | 3 +- .../Program.cs | 2 + .../Telemetry/VSCodeRequestTelemetryLogger.cs | 115 ++++++++++-------- .../VSCodeRequestTelemetryLoggerFactory.cs | 24 ++++ .../Telemetry/RequestTelemetryLogger.cs | 20 +-- .../Compiler/Core/Log/FunctionId.cs | 5 +- 7 files changed, 106 insertions(+), 65 deletions(-) create mode 100644 src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Telemetry/VSCodeRequestTelemetryLoggerFactory.cs diff --git a/src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/HostWorkspace/ProjectInitializationHandler.cs b/src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/HostWorkspace/ProjectInitializationHandler.cs index 58dffd88d6900..79194cbe099ad 100644 --- a/src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/HostWorkspace/ProjectInitializationHandler.cs +++ b/src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/HostWorkspace/ProjectInitializationHandler.cs @@ -8,6 +8,7 @@ using Microsoft.CodeAnalysis.LanguageServer.BrokeredServices.Services; using Microsoft.CodeAnalysis.LanguageServer.BrokeredServices.Services.Definitions; using Microsoft.CodeAnalysis.LanguageServer.LanguageServer; +using Microsoft.CodeAnalysis.LanguageServer.Telemetry; using Microsoft.Extensions.Logging; using Microsoft.ServiceHub.Framework; using Roslyn.Utilities; @@ -111,6 +112,7 @@ public void OnError(Exception error) public void OnNext(ProjectInitializationCompletionState value) { _logger.LogDebug("Devkit project initialization completed"); + VSCodeRequestTelemetryLogger.ReportProjectInitializationComplete(); _ = SendProjectInitializationCompleteNotificationAsync().ReportNonFatalErrorAsync(); } } diff --git a/src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/HostWorkspace/WorkspaceProjectFactoryService.cs b/src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/HostWorkspace/WorkspaceProjectFactoryService.cs index 4bcbf018e089e..1debf920753bd 100644 --- a/src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/HostWorkspace/WorkspaceProjectFactoryService.cs +++ b/src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/HostWorkspace/WorkspaceProjectFactoryService.cs @@ -5,6 +5,7 @@ using System.Collections.Immutable; using System.ComponentModel.Composition; using Microsoft.CodeAnalysis.Host.Mef; +using Microsoft.CodeAnalysis.LanguageServer.Telemetry; using Microsoft.CodeAnalysis.Remote.ProjectSystem; using Microsoft.Extensions.Logging; using Microsoft.ServiceHub.Framework; @@ -44,7 +45,7 @@ async Task IExportedBrokeredService.InitializeAsync(CancellationToken cancellati public async Task CreateAndAddProjectAsync(WorkspaceProjectCreationInfo creationInfo, CancellationToken _) { _logger.LogInformation(string.Format(LanguageServerResources.Project_0_loaded_by_CSharp_Dev_Kit, creationInfo.FilePath)); - + VSCodeRequestTelemetryLogger.ReportProjectLoadStarted(); try { if (creationInfo.BuildSystemProperties.TryGetValue("SolutionPath", out var solutionPath)) diff --git a/src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Program.cs b/src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Program.cs index 3da05d5ed850a..295f23ce072f0 100644 --- a/src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Program.cs +++ b/src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Program.cs @@ -21,6 +21,7 @@ using Microsoft.Extensions.Logging; using Microsoft.Extensions.Logging.Console; using Roslyn.Utilities; +using RoslynLog = Microsoft.CodeAnalysis.Internal.Log; // Setting the title can fail if the process is run without a window, such // as when launched detached from nodejs @@ -137,6 +138,7 @@ static async Task RunAsync(ServerConfiguration serverConfiguration, Cancellation server.Start(); logger.LogInformation("Language server initialized"); + RoslynLog.Logger.Log(RoslynLog.FunctionId.VSCode_LanguageServer_Started, logLevel: RoslynLog.LogLevel.Information); try { diff --git a/src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Telemetry/VSCodeRequestTelemetryLogger.cs b/src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Telemetry/VSCodeRequestTelemetryLogger.cs index 85bcdc2bcd7ff..12d0a32f558fa 100644 --- a/src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Telemetry/VSCodeRequestTelemetryLogger.cs +++ b/src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Telemetry/VSCodeRequestTelemetryLogger.cs @@ -2,61 +2,72 @@ // 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.Concurrent; -using System.Collections.Generic; using System.Composition; -using System.Linq; -using System.Text; -using System.Threading.Tasks; +using Microsoft.CodeAnalysis.Host.Mef; using Microsoft.CodeAnalysis.Internal.Log; using Microsoft.CodeAnalysis.LanguageServer.Handler; using Microsoft.CodeAnalysis.Telemetry; -//namespace Microsoft.CodeAnalysis.LanguageServer.Telemetry; - -//internal class VSCodeRequestTelemetryLogger : RequestTelemetryLogger -//{ -// /// -// /// Tracks whether or not the initial project load has completed so we can see -// /// how often we get misc file requests after we've loaded. -// /// -// private static bool _initialProjectLoadCompleted = false; - -// private readonly ConcurrentDictionary> _findDocumentCounters; - -// public VSCodeRequestTelemetryLogger(string serverTypeName) : base(serverTypeName) -// { -// } - -// public static void ReportProjectInitializationComplete() -// { -// _initialProjectLoadCompleted = true; -// Logger.Log(FunctionId.VSCode_Projects_Load_Completed, logLevel: LogLevel.Information); -// } - -// public static void ReportProjectLoadStarted() -// { -// Logger.Log(FunctionId.VSCode_Project_Load_Started, logLevel: LogLevel.Information); -// } - -// protected override void IncreaseFindDocumentCount(string workspaceInfo) -// { -// TelemetryLogging.LogAggregated(FunctionId.LSP_FindDocumentInWorkspace, KeyValueLogMessage.Create(m => -// { -// m[TelemetryLogging.KeyName] = _serverTypeName; -// m[TelemetryLogging.KeyValue] = (int)queuedDuration.TotalMilliseconds; -// m[TelemetryLogging.KeyMetricName] = "Count"; -// m["server"] = _serverTypeName; -// m["method"] = methodName; -// m["language"] = language; -// })); - -// base.IncreaseFindDocumentCount(workspaceInfo); -// } - -// protected override void ReportFindDocumentCounter() -// { -// base.ReportFindDocumentCounter(); -// } -//} +namespace Microsoft.CodeAnalysis.LanguageServer.Telemetry; + +[ExportCSharpVisualBasicStatelessLspService(typeof(RequestTelemetryLogger), serverKind: WellKnownLspServerKinds.CSharpVisualBasicLspServer), Shared] +[method: ImportingConstructor] +[method: Obsolete(MefConstruction.ImportingConstructorMessage, error: true)] +internal class VSCodeRequestTelemetryLogger() : RequestTelemetryLogger(WellKnownLspServerKinds.CSharpVisualBasicLspServer.ToTelemetryString()) +{ + /// + /// Tracks whether or not the initial project load has completed. + /// + 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() + { + [true] = new(), + [false] = new(), + }; + + public static void ReportProjectInitializationComplete() + { + s_initialProjectLoadCompleted = true; + Logger.Log(FunctionId.VSCode_Projects_Load_Completed, logLevel: LogLevel.Information); + } + + public static void ReportProjectLoadStarted() + { + Logger.Log(FunctionId.VSCode_Project_Load_Started, logLevel: LogLevel.Information); + } + + protected override void IncreaseFindDocumentCount(string workspaceInfo) + { + _findDocumentCounters.GetOrAdd(s_initialProjectLoadCompleted, (_) => new CountLogAggregator()).IncreaseCount(workspaceInfo); + } + + protected override void ReportFindDocumentCounter() + { + foreach (var (isInitialLoadComplete, counter) in _findDocumentCounters) + { + 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(); + } + +} diff --git a/src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Telemetry/VSCodeRequestTelemetryLoggerFactory.cs b/src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Telemetry/VSCodeRequestTelemetryLoggerFactory.cs new file mode 100644 index 0000000000000..eb5f57144a0f6 --- /dev/null +++ b/src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Telemetry/VSCodeRequestTelemetryLoggerFactory.cs @@ -0,0 +1,24 @@ +// 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 System.Composition; +using Microsoft.CodeAnalysis.Host.Mef; + +namespace Microsoft.CodeAnalysis.LanguageServer.Handler; + +[ExportCSharpVisualBasicLspServiceFactory(typeof(RequestTelemetryLogger)), Shared] +internal sealed class RequestTelemetryLoggerFactory : ILspServiceFactory +{ + [ImportingConstructor] + [Obsolete(MefConstruction.ImportingConstructorMessage, error: true)] + public RequestTelemetryLoggerFactory() + { + } + + public ILspService CreateILspService(LspServices lspServices, WellKnownLspServerKinds serverKind) + { + return new RequestTelemetryLogger(serverKind.ToTelemetryString()); + } +} diff --git a/src/LanguageServer/Protocol/Handler/Telemetry/RequestTelemetryLogger.cs b/src/LanguageServer/Protocol/Handler/Telemetry/RequestTelemetryLogger.cs index 2a3980888581a..95c3d2c6e5c45 100644 --- a/src/LanguageServer/Protocol/Handler/Telemetry/RequestTelemetryLogger.cs +++ b/src/LanguageServer/Protocol/Handler/Telemetry/RequestTelemetryLogger.cs @@ -16,7 +16,7 @@ namespace Microsoft.CodeAnalysis.LanguageServer.Handler; /// internal class RequestTelemetryLogger : IDisposable, ILspService { - private readonly string _serverTypeName; + protected readonly string ServerTypeName; /// /// Store request counters in a concurrent dictionary as non-mutating LSP requests can @@ -32,7 +32,7 @@ internal class RequestTelemetryLogger : IDisposable, ILspService public RequestTelemetryLogger(string serverTypeName) { - _serverTypeName = serverTypeName; + ServerTypeName = serverTypeName; _requestCounters = new(); _findDocumentResults = new(); _usedForkedSolutionCounter = new(); @@ -70,20 +70,20 @@ public void UpdateTelemetryData( // Store the request time metrics per LSP method. TelemetryLogging.LogAggregated(FunctionId.LSP_TimeInQueue, KeyValueLogMessage.Create(m => { - m[TelemetryLogging.KeyName] = _serverTypeName; + m[TelemetryLogging.KeyName] = ServerTypeName; m[TelemetryLogging.KeyValue] = (int)queuedDuration.TotalMilliseconds; m[TelemetryLogging.KeyMetricName] = "TimeInQueue"; - m["server"] = _serverTypeName; + m["server"] = ServerTypeName; m["method"] = methodName; m["language"] = language; })); TelemetryLogging.LogAggregated(FunctionId.LSP_RequestDuration, KeyValueLogMessage.Create(m => { - m[TelemetryLogging.KeyName] = _serverTypeName + "." + methodName; + m[TelemetryLogging.KeyName] = ServerTypeName + "." + methodName; m[TelemetryLogging.KeyValue] = (int)requestDuration.TotalMilliseconds; m[TelemetryLogging.KeyMetricName] = "RequestDuration"; - m["server"] = _serverTypeName; + m["server"] = ServerTypeName; m["method"] = methodName; m["language"] = language; })); @@ -114,7 +114,7 @@ protected virtual void ReportFindDocumentCounter() { TelemetryLogging.Log(FunctionId.LSP_FindDocumentInWorkspace, KeyValueLogMessage.Create(LogType.Trace, m => { - m["server"] = _serverTypeName; + m["server"] = ServerTypeName; foreach (var kvp in _findDocumentResults) { var info = kvp.Key.ToString()!; @@ -130,7 +130,7 @@ private void OnFlushed(object? sender, EventArgs e) { TelemetryLogging.Log(FunctionId.LSP_RequestCounter, KeyValueLogMessage.Create(LogType.Trace, m => { - m["server"] = _serverTypeName; + m["server"] = ServerTypeName; m["method"] = kvp.Key.Method; m["language"] = kvp.Key.Language; m["successful"] = kvp.Value.SucceededCount; @@ -145,7 +145,7 @@ private void OnFlushed(object? sender, EventArgs e) { TelemetryLogging.Log(FunctionId.LSP_UsedForkedSolution, KeyValueLogMessage.Create(LogType.Trace, m => { - m["server"] = _serverTypeName; + m["server"] = ServerTypeName; foreach (var kvp in _usedForkedSolutionCounter) { var info = kvp.Key.ToString()!; @@ -159,7 +159,7 @@ private void OnFlushed(object? sender, EventArgs e) _usedForkedSolutionCounter.Clear(); } - protected class Counter + private class Counter { private int _succeededCount; private int _failedCount; diff --git a/src/Workspaces/SharedUtilitiesAndExtensions/Compiler/Core/Log/FunctionId.cs b/src/Workspaces/SharedUtilitiesAndExtensions/Compiler/Core/Log/FunctionId.cs index 0575f570a170c..4f123aa508e83 100644 --- a/src/Workspaces/SharedUtilitiesAndExtensions/Compiler/Core/Log/FunctionId.cs +++ b/src/Workspaces/SharedUtilitiesAndExtensions/Compiler/Core/Log/FunctionId.cs @@ -636,6 +636,7 @@ internal enum FunctionId Copilot_On_The_Fly_Docs_Content_Excluded = 816, Copilot_Rename = 851, - VSCode_Project_Load_Started = 860, - VSCode_Projects_Load_Completed = 861, + VSCode_LanguageServer_Started = 860, + VSCode_Project_Load_Started = 861, + VSCode_Projects_Load_Completed = 862, } From cbcfb4a70020603f2ca5e59a4295fe7eafa07b06 Mon Sep 17 00:00:00 2001 From: David Barbet Date: Tue, 8 Oct 2024 14:18:58 -0700 Subject: [PATCH 3/7] Cleanup --- .../Telemetry/VSCodeRequestTelemetryLogger.cs | 6 +---- .../VSCodeRequestTelemetryLoggerFactory.cs | 24 ------------------- .../Telemetry/RequestTelemetryLogger.cs | 2 +- 3 files changed, 2 insertions(+), 30 deletions(-) delete mode 100644 src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Telemetry/VSCodeRequestTelemetryLoggerFactory.cs diff --git a/src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Telemetry/VSCodeRequestTelemetryLogger.cs b/src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Telemetry/VSCodeRequestTelemetryLogger.cs index 12d0a32f558fa..ee7da49df6442 100644 --- a/src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Telemetry/VSCodeRequestTelemetryLogger.cs +++ b/src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Telemetry/VSCodeRequestTelemetryLogger.cs @@ -27,11 +27,7 @@ internal class VSCodeRequestTelemetryLogger() : RequestTelemetryLogger(WellKnown /// 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() - { - [true] = new(), - [false] = new(), - }; + private readonly ConcurrentDictionary> _findDocumentCounters = new(); public static void ReportProjectInitializationComplete() { diff --git a/src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Telemetry/VSCodeRequestTelemetryLoggerFactory.cs b/src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Telemetry/VSCodeRequestTelemetryLoggerFactory.cs deleted file mode 100644 index eb5f57144a0f6..0000000000000 --- a/src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Telemetry/VSCodeRequestTelemetryLoggerFactory.cs +++ /dev/null @@ -1,24 +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; -using System.Composition; -using Microsoft.CodeAnalysis.Host.Mef; - -namespace Microsoft.CodeAnalysis.LanguageServer.Handler; - -[ExportCSharpVisualBasicLspServiceFactory(typeof(RequestTelemetryLogger)), Shared] -internal sealed class RequestTelemetryLoggerFactory : ILspServiceFactory -{ - [ImportingConstructor] - [Obsolete(MefConstruction.ImportingConstructorMessage, error: true)] - public RequestTelemetryLoggerFactory() - { - } - - public ILspService CreateILspService(LspServices lspServices, WellKnownLspServerKinds serverKind) - { - return new RequestTelemetryLogger(serverKind.ToTelemetryString()); - } -} diff --git a/src/LanguageServer/Protocol/Handler/Telemetry/RequestTelemetryLogger.cs b/src/LanguageServer/Protocol/Handler/Telemetry/RequestTelemetryLogger.cs index 95c3d2c6e5c45..955514d5ce933 100644 --- a/src/LanguageServer/Protocol/Handler/Telemetry/RequestTelemetryLogger.cs +++ b/src/LanguageServer/Protocol/Handler/Telemetry/RequestTelemetryLogger.cs @@ -122,6 +122,7 @@ protected virtual void ReportFindDocumentCounter() } })); } + _findDocumentResults.Clear(); } private void OnFlushed(object? sender, EventArgs e) @@ -155,7 +156,6 @@ private void OnFlushed(object? sender, EventArgs e) } _requestCounters.Clear(); - _findDocumentResults.Clear(); _usedForkedSolutionCounter.Clear(); } From 47eac670e9aabb89f302c4e61b50b2564c52b68a Mon Sep 17 00:00:00 2001 From: David Barbet Date: Wed, 9 Oct 2024 18:31:56 -0700 Subject: [PATCH 4/7] 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( From 0d5ec5378187bccd357221beccedee83037900c2 Mon Sep 17 00:00:00 2001 From: David Barbet Date: Mon, 14 Oct 2024 09:05:30 -0700 Subject: [PATCH 5/7] Add test to ensure services apply to the correct server kind --- .../ProtocolUnitTests/LspServicesTests.cs | 20 +++++++++++++++++++ 1 file changed, 20 insertions(+) diff --git a/src/LanguageServer/ProtocolUnitTests/LspServicesTests.cs b/src/LanguageServer/ProtocolUnitTests/LspServicesTests.cs index 0e565059b8d5e..5ccdfd4ae3949 100644 --- a/src/LanguageServer/ProtocolUnitTests/LspServicesTests.cs +++ b/src/LanguageServer/ProtocolUnitTests/LspServicesTests.cs @@ -69,6 +69,21 @@ public async Task DuplicateAnyServicesThrow(bool mutatingLspWorkspace) await Assert.ThrowsAnyAsync(async () => await CreateTestLspServerAsync("", mutatingLspWorkspace, initializationOptions: new() { ServerKind = WellKnownLspServerKinds.CSharpVisualBasicLspServer }, composition)); } + [Theory, CombinatorialData] + public async Task ReturnsLspServiceForMatchingServer(bool mutatingLspWorkspace) + { + var composition = base.Composition.AddParts(typeof(CSharpLspService), typeof(AlwaysActiveCSharpLspService)); + await using var server = await CreateTestLspServerAsync("", mutatingLspWorkspace, initializationOptions: new() { ServerKind = WellKnownLspServerKinds.CSharpVisualBasicLspServer }, composition); + + var lspService = server.GetRequiredLspService(); + Assert.True(lspService is CSharpLspService); + + await using var server2 = await CreateTestLspServerAsync("", mutatingLspWorkspace, initializationOptions: new() { ServerKind = WellKnownLspServerKinds.AlwaysActiveVSLspServer }, composition); + + var lspService2 = server2.GetRequiredLspService(); + Assert.True(lspService2 is AlwaysActiveCSharpLspService); + } + internal class TestLspService : ILspService { } internal record class TestLspServiceFromFactory(string FactoryName) : ILspService { } @@ -117,4 +132,9 @@ internal class DuplicateAnyLspService() : TestLspService { } [method: ImportingConstructor] [method: Obsolete(MefConstruction.ImportingConstructorMessage, error: true)] internal class DuplicateAnyLspServiceFactory() : CSharpLspServiceFactory { } + + [ExportStatelessLspService(typeof(TestLspService), ProtocolConstants.RoslynLspLanguagesContract, WellKnownLspServerKinds.AlwaysActiveVSLspServer), Shared] + [method: ImportingConstructor] + [method: Obsolete(MefConstruction.ImportingConstructorMessage, error: true)] + internal class AlwaysActiveCSharpLspService() : TestLspService { } } From 6bd644e3078f86885957312909d4bcb41ff30853 Mon Sep 17 00:00:00 2001 From: David Barbet Date: Mon, 14 Oct 2024 09:11:07 -0700 Subject: [PATCH 6/7] Update comments --- .../Core/Def/Telemetry/Shared/AbstractAggregatingLog.cs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/VisualStudio/Core/Def/Telemetry/Shared/AbstractAggregatingLog.cs b/src/VisualStudio/Core/Def/Telemetry/Shared/AbstractAggregatingLog.cs index 915dbcdfa7db5..6799cc82d180a 100644 --- a/src/VisualStudio/Core/Def/Telemetry/Shared/AbstractAggregatingLog.cs +++ b/src/VisualStudio/Core/Def/Telemetry/Shared/AbstractAggregatingLog.cs @@ -57,7 +57,7 @@ public void Log(KeyValueLogMessage logMessage) if (!IsEnabled) return; - // Name is the key for this message in our histogram dictionary. It is also used as the metric name + // Name is the key for this message in our aggregation dictionary. It is also used as the metric name // if the MetricName property isn't specified. if (!logMessage.Properties.TryGetValue(TelemetryLogging.KeyName, out var nameValue) || nameValue is not string name) throw ExceptionUtilities.Unreachable(); @@ -112,7 +112,7 @@ public void Flush() { foreach (var (aggregator, telemetryEvent, aggregatorLock) in _aggregations.Values) { - // This fine-grained lock ensures that the histogram isn't modified (via a Record call) + // This fine-grained lock ensures that the aggregation isn't modified (via a Record call) // during the creation of the TelemetryMetricEvent or the PostMetricEvent // call that operates on it. lock (aggregatorLock) From e53963b915be47c480a8e11dd061e0f6c95ddfc4 Mon Sep 17 00:00:00 2001 From: David Barbet Date: Mon, 14 Oct 2024 09:13:05 -0700 Subject: [PATCH 7/7] Remove unnecessary properties on event --- .../Protocol/Handler/Telemetry/RequestTelemetryLogger.cs | 2 -- 1 file changed, 2 deletions(-) diff --git a/src/LanguageServer/Protocol/Handler/Telemetry/RequestTelemetryLogger.cs b/src/LanguageServer/Protocol/Handler/Telemetry/RequestTelemetryLogger.cs index 369e09f9cc556..7adef6d4cd998 100644 --- a/src/LanguageServer/Protocol/Handler/Telemetry/RequestTelemetryLogger.cs +++ b/src/LanguageServer/Protocol/Handler/Telemetry/RequestTelemetryLogger.cs @@ -73,8 +73,6 @@ public void UpdateTelemetryData( m[TelemetryLogging.KeyValue] = (long)queuedDuration.TotalMilliseconds; m[TelemetryLogging.KeyMetricName] = "TimeInQueue"; m["server"] = ServerTypeName; - m["method"] = methodName; - m["language"] = language; })); TelemetryLogging.LogAggregatedHistogram(FunctionId.LSP_RequestDuration, KeyValueLogMessage.Create(m =>