From da22131c283b366baa304e4aaa9e4a1a2a4e0a02 Mon Sep 17 00:00:00 2001 From: Todd Grunke Date: Thu, 7 Dec 2023 11:03:49 -0800 Subject: [PATCH 01/10] Initial attempt at putting back CLaSP request telemetry --- .../LanguageServer/TestOutputLspLogger.cs | 11 ++++ .../Logging/LspServiceLogger.cs | 9 ++++ .../Program.cs | 2 +- .../Mocks/NoOpLspLogger.cs | 7 ++- .../AbstractLspRequestScope.cs | 40 +++++++++++++++ .../ILspLogger.cs | 4 +- .../ILspRequestScope.cs | 16 ++++++ .../QueueItem.cs | 20 ++++---- .../Protocol/Handler/RequestTelemetryScope.cs | 37 ++++++++++++++ .../ServerLifetime/InitializeHandler.cs | 50 +++++++------------ .../LanguageServer/Protocol/NoOpLspLogger.cs | 8 ++- .../Def/LanguageClient/LogHubLspLogger.cs | 50 ++++++++++++++++++- 12 files changed, 205 insertions(+), 49 deletions(-) create mode 100644 src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractLspRequestScope.cs create mode 100644 src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/ILspRequestScope.cs create mode 100644 src/Features/LanguageServer/Protocol/Handler/RequestTelemetryScope.cs diff --git a/src/EditorFeatures/TestUtilities/LanguageServer/TestOutputLspLogger.cs b/src/EditorFeatures/TestUtilities/LanguageServer/TestOutputLspLogger.cs index 22796b723e10f..e5d21ec6f315f 100644 --- a/src/EditorFeatures/TestUtilities/LanguageServer/TestOutputLspLogger.cs +++ b/src/EditorFeatures/TestUtilities/LanguageServer/TestOutputLspLogger.cs @@ -8,6 +8,7 @@ using System.Linq; using System.Text; using System.Threading.Tasks; +using Microsoft.CommonLanguageServerProtocol.Framework; using Xunit.Abstractions; namespace Microsoft.CodeAnalysis.LanguageServer.UnitTests; @@ -19,6 +20,11 @@ public TestOutputLspLogger(ITestOutputHelper testOutputHelper) _testOutputHelper = testOutputHelper; } + public ILspRequestScope BeginScope(string message) + { + throw new NotImplementedException(); + } + public void LogEndContext(string message, params object[] @params) => Log("End", message, @params); public void LogError(string message, params object[] @params) => Log("Error", message, @params); @@ -32,6 +38,11 @@ public void LogException(Exception exception, string? message = null, params obj public void LogWarning(string message, params object[] @params) => Log("Warning", message, @params); + public ILspRequestScope TrackLspRequest(string message, ILspServices lspServices) + { + throw new NotImplementedException(); + } + private void Log(string level, string message, params object[] @params) => _testOutputHelper.WriteLine($"[{DateTime.UtcNow:hh:mm:ss.fff}][{level}]{message}", @params); } diff --git a/src/Features/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Logging/LspServiceLogger.cs b/src/Features/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Logging/LspServiceLogger.cs index 5da7012ea5e5d..460e1edb3f876 100644 --- a/src/Features/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Logging/LspServiceLogger.cs +++ b/src/Features/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Logging/LspServiceLogger.cs @@ -2,6 +2,8 @@ // 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.LanguageServer.Handler; +using Microsoft.CommonLanguageServerProtocol.Framework; using Microsoft.Extensions.Logging; namespace Microsoft.CodeAnalysis.LanguageServer.Logging; @@ -32,4 +34,11 @@ public LspServiceLogger(ILogger hostLogger) public void LogStartContext(string message, params object[] @params) => _hostLogger.LogDebug($"[{DateTime.UtcNow:hh:mm:ss.fff}][Start]{message}", @params); public void LogWarning(string message, params object[] @params) => _hostLogger.LogWarning(message, @params); + + public ILspRequestScope TrackLspRequest(string lspMethodName, ILspServices lspServices) + { + var telemetryLogger = lspServices.GetRequiredService(); + + return new RequestTelemetryScope(lspMethodName, telemetryLogger); + } } diff --git a/src/Features/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Program.cs b/src/Features/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Program.cs index 422eb6b3309c3..80d9ce55e0386 100644 --- a/src/Features/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Program.cs +++ b/src/Features/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Program.cs @@ -198,7 +198,7 @@ static CliRootCommand CreateCommandLineParser() }; rootCommand.SetAction((parseResult, cancellationToken) => { - var launchDebugger = parseResult.GetValue(debugOption); + var launchDebugger = parseResult.GetValue(debugOption) || true; var logLevel = parseResult.GetValue(logLevelOption); var starredCompletionsPath = parseResult.GetValue(starredCompletionsPathOption); var telemetryLevel = parseResult.GetValue(telemetryLevelOption); diff --git a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework.UnitTests/Mocks/NoOpLspLogger.cs b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework.UnitTests/Mocks/NoOpLspLogger.cs index 0264918f7027f..b96900cc703dc 100644 --- a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework.UnitTests/Mocks/NoOpLspLogger.cs +++ b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework.UnitTests/Mocks/NoOpLspLogger.cs @@ -3,8 +3,6 @@ // See the LICENSE file in the project root for more information. using System; -using System.Threading; -using System.Threading.Tasks; namespace Microsoft.CommonLanguageServerProtocol.Framework.UnitTests; @@ -35,4 +33,9 @@ public void LogEndContext(string context, params object[] @params) public void LogWarning(string message, params object[] @params) { } + + public ILspRequestScope TrackLspRequest(string message, ILspServices lspServices) + { + throw new NotImplementedException(); + } } diff --git a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractLspRequestScope.cs b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractLspRequestScope.cs new file mode 100644 index 0000000000000..6b0379c05c40f --- /dev/null +++ b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractLspRequestScope.cs @@ -0,0 +1,40 @@ +// 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.Diagnostics; + +namespace Microsoft.CommonLanguageServerProtocol.Framework; + +public abstract class AbstractLspRequestScope : ILspRequestScope +{ + private readonly Stopwatch _stopwatch; + + protected string Name { get; } + + protected TimeSpan QueuedDuration { get; private set; } + protected TimeSpan RequestDuration { get; private set; } + + protected AbstractLspRequestScope(string name) + { + _stopwatch = Stopwatch.StartNew(); + Name = name; + } + + public abstract void RecordCancellation(); + public abstract void RecordException(Exception exception); + public abstract void RecordWarning(string message); + + public void RecordExecutionStart() + { + QueuedDuration = _stopwatch.Elapsed; + } + + public virtual void Dispose() + { + RequestDuration = _stopwatch.Elapsed; + + _stopwatch.Stop(); + } +} diff --git a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/ILspLogger.cs b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/ILspLogger.cs index 69c1c91255734..58b8dab2a670c 100644 --- a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/ILspLogger.cs +++ b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/ILspLogger.cs @@ -3,8 +3,6 @@ // See the LICENSE file in the project root for more information. using System; -using System.Threading; -using System.Threading.Tasks; namespace Microsoft.CommonLanguageServerProtocol.Framework; @@ -16,4 +14,6 @@ public interface ILspLogger void LogWarning(string message, params object[] @params); void LogError(string message, params object[] @params); void LogException(Exception exception, string? message = null, params object[] @params); + + ILspRequestScope TrackLspRequest(string message, ILspServices lspServices); } diff --git a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/ILspRequestScope.cs b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/ILspRequestScope.cs new file mode 100644 index 0000000000000..66368358c0b46 --- /dev/null +++ b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/ILspRequestScope.cs @@ -0,0 +1,16 @@ +// 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; + +namespace Microsoft.CommonLanguageServerProtocol.Framework; + +public interface ILspRequestScope : IDisposable +{ + void RecordExecutionStart(); + + void RecordCancellation(); + void RecordException(Exception exception); + void RecordWarning(string message); +} diff --git a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/QueueItem.cs b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/QueueItem.cs index 6874d32e77673..b3c672d6bb1e3 100644 --- a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/QueueItem.cs +++ b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/QueueItem.cs @@ -3,7 +3,6 @@ // See the LICENSE file in the project root for more information. using System; -using System.Diagnostics; using System.Threading; using System.Threading.Tasks; using Microsoft.VisualStudio.Threading; @@ -20,8 +19,6 @@ internal sealed class NoValue internal class QueueItem : IQueueItem { - private readonly ILspLogger _logger; - private readonly TRequest _request; private readonly IMethodHandler _handler; @@ -39,6 +36,8 @@ internal class QueueItem : IQueueItem _completionSource.TrySetCanceled(cancellationToken)); _handler = handler; - _logger = logger; _request = request; LspServices = lspServices; MethodHandler = methodHandler; MutatesServerState = mutatesSolutionState; MethodName = methodName; + + _requestScope = logger.TrackLspRequest(methodName, LspServices); } public static (IQueueItem, Task) Create( @@ -88,6 +88,9 @@ public static (IQueueItem, Task) Create( public async Task CreateRequestContextAsync(CancellationToken cancellationToken) { cancellationToken.ThrowIfCancellationRequested(); + + _requestScope.RecordExecutionStart(); + var requestContextFactory = LspServices.GetRequiredService>(); var context = await requestContextFactory.CreateRequestContextAsync(this, _request, cancellationToken).ConfigureAwait(false); return context; @@ -102,7 +105,6 @@ public static (IQueueItem, Task) Create( /// The result of the request. public async Task StartRequestAsync(TRequestContext? context, CancellationToken cancellationToken) { - _logger.LogStartContext($"{MethodName}"); try { cancellationToken.ThrowIfCancellationRequested(); @@ -116,7 +118,7 @@ public async Task StartRequestAsync(TRequestContext? context, CancellationToken // the requests this could happen for. However, this assumption may not hold in the future. // If that turns out to be the case, we could defer to the individual handler to decide // what to do. - _logger.LogWarning($"Could not get request context for {MethodName}"); + _requestScope.RecordWarning($"Could not get request context for {MethodName}"); _completionSource.TrySetException(new InvalidOperationException($"Unable to create request context for {MethodName}")); } else if (_handler is IRequestHandler requestHandler) @@ -153,7 +155,7 @@ public async Task StartRequestAsync(TRequestContext? context, CancellationToken catch (OperationCanceledException ex) { // Record logs + metrics on cancellation. - _logger.LogInformation($"{MethodName} - Canceled"); + _requestScope.RecordCancellation(); _completionSource.TrySetCanceled(ex.CancellationToken); } @@ -161,13 +163,13 @@ public async Task StartRequestAsync(TRequestContext? context, CancellationToken { // Record logs and metrics on the exception. // It's important that this can NEVER throw, or the queue will hang. - _logger.LogException(ex); + _requestScope.RecordException(ex); _completionSource.TrySetException(ex); } finally { - _logger.LogEndContext($"{MethodName}"); + _requestScope.Dispose(); } // Return the result of this completion source to the caller diff --git a/src/Features/LanguageServer/Protocol/Handler/RequestTelemetryScope.cs b/src/Features/LanguageServer/Protocol/Handler/RequestTelemetryScope.cs new file mode 100644 index 0000000000000..9e4cd13b63cf5 --- /dev/null +++ b/src/Features/LanguageServer/Protocol/Handler/RequestTelemetryScope.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 System; +using Microsoft.CommonLanguageServerProtocol.Framework; + +namespace Microsoft.CodeAnalysis.LanguageServer.Handler; + +internal sealed class RequestTelemetryScope(string name, RequestTelemetryLogger telemetryLogger) + : AbstractLspRequestScope(name) +{ + private readonly RequestTelemetryLogger _telemetryLogger = telemetryLogger; + private RequestTelemetryLogger.Result _result = RequestTelemetryLogger.Result.Succeeded; + + public override void Dispose() + { + base.Dispose(); + + _telemetryLogger.UpdateTelemetryData(Name, QueuedDuration, RequestDuration, _result); + } + + public override void RecordCancellation() + { + _result = RequestTelemetryLogger.Result.Cancelled; + } + + public override void RecordException(Exception exception) + { + _result = RequestTelemetryLogger.Result.Failed; + } + + public override void RecordWarning(string message) + { + _result = RequestTelemetryLogger.Result.Failed; + } +} diff --git a/src/Features/LanguageServer/Protocol/Handler/ServerLifetime/InitializeHandler.cs b/src/Features/LanguageServer/Protocol/Handler/ServerLifetime/InitializeHandler.cs index 0cc14e2d1a843..788a3a20f1f8f 100644 --- a/src/Features/LanguageServer/Protocol/Handler/ServerLifetime/InitializeHandler.cs +++ b/src/Features/LanguageServer/Protocol/Handler/ServerLifetime/InitializeHandler.cs @@ -3,10 +3,8 @@ // See the LICENSE file in the project root for more information. using System; -using System.Composition; using System.Threading; using System.Threading.Tasks; -using Microsoft.CodeAnalysis.Host.Mef; using Microsoft.CodeAnalysis.Internal.Log; using Microsoft.VisualStudio.LanguageServer.Protocol; using Newtonsoft.Json; @@ -25,40 +23,30 @@ public InitializeHandler() public Task HandleRequestAsync(InitializeParams request, RequestContext context, CancellationToken cancellationToken) { - var logger = context.GetRequiredLspService(); - try + var clientCapabilitiesManager = context.GetRequiredLspService(); + var clientCapabilities = clientCapabilitiesManager.TryGetClientCapabilities(); + if (clientCapabilities != null) { - logger.LogStartContext("Initialize"); - - var clientCapabilitiesManager = context.GetRequiredLspService(); - var clientCapabilities = clientCapabilitiesManager.TryGetClientCapabilities(); - if (clientCapabilities != null) - { - throw new InvalidOperationException($"{nameof(Methods.InitializeName)} called multiple times"); - } + throw new InvalidOperationException($"{nameof(Methods.InitializeName)} called multiple times"); + } - clientCapabilities = request.Capabilities; - clientCapabilitiesManager.SetInitializeParams(request); + clientCapabilities = request.Capabilities; + clientCapabilitiesManager.SetInitializeParams(request); - var capabilitiesProvider = context.GetRequiredLspService(); - var serverCapabilities = capabilitiesProvider.GetCapabilities(clientCapabilities); + var capabilitiesProvider = context.GetRequiredLspService(); + var serverCapabilities = capabilitiesProvider.GetCapabilities(clientCapabilities); - // Record a telemetry event indicating what capabilities are being provided by the server. - // Useful for figuring out if a particular session is opted into an LSP feature. - Logger.Log(FunctionId.LSP_Initialize, KeyValueLogMessage.Create(m => - { - m["serverKind"] = context.ServerKind.ToTelemetryString(); - m["capabilities"] = JsonConvert.SerializeObject(serverCapabilities); - })); + // Record a telemetry event indicating what capabilities are being provided by the server. + // Useful for figuring out if a particular session is opted into an LSP feature. + Logger.Log(FunctionId.LSP_Initialize, KeyValueLogMessage.Create(m => + { + m["serverKind"] = context.ServerKind.ToTelemetryString(); + m["capabilities"] = JsonConvert.SerializeObject(serverCapabilities); + })); - return Task.FromResult(new InitializeResult - { - Capabilities = serverCapabilities, - }); - } - finally + return Task.FromResult(new InitializeResult { - logger.LogEndContext("Initialize"); - } + Capabilities = serverCapabilities, + }); } } diff --git a/src/Features/LanguageServer/Protocol/NoOpLspLogger.cs b/src/Features/LanguageServer/Protocol/NoOpLspLogger.cs index d1f492de309f0..b244447f53f7a 100644 --- a/src/Features/LanguageServer/Protocol/NoOpLspLogger.cs +++ b/src/Features/LanguageServer/Protocol/NoOpLspLogger.cs @@ -3,8 +3,7 @@ // See the LICENSE file in the project root for more information. using System; -using System.Threading; -using System.Threading.Tasks; +using Microsoft.CommonLanguageServerProtocol.Framework; namespace Microsoft.CodeAnalysis.LanguageServer { @@ -37,5 +36,10 @@ public void LogStartContext(string message, params object[] @params) public void LogEndContext(string message, params object[] @params) { } + + public ILspRequestScope TrackLspRequest(string message, ILspServices lspServices) + { + throw new NotImplementedException(); + } } } diff --git a/src/VisualStudio/Core/Def/LanguageClient/LogHubLspLogger.cs b/src/VisualStudio/Core/Def/LanguageClient/LogHubLspLogger.cs index c4cf998739911..3efc0abde4730 100644 --- a/src/VisualStudio/Core/Def/LanguageClient/LogHubLspLogger.cs +++ b/src/VisualStudio/Core/Def/LanguageClient/LogHubLspLogger.cs @@ -4,9 +4,9 @@ using System; using System.Diagnostics; -using System.Threading; -using System.Threading.Tasks; using Microsoft.CodeAnalysis.LanguageServer; +using Microsoft.CodeAnalysis.LanguageServer.Handler; +using Microsoft.CommonLanguageServerProtocol.Framework; using Microsoft.VisualStudio.LogHub; using Roslyn.Utilities; @@ -71,5 +71,51 @@ public void LogEndContext(string message, params object[] @params) { _traceSource.TraceEvent(TraceEventType.Stop, id: 0, message); } + + public ILspRequestScope TrackLspRequest(string message, ILspServices lspServices) + { + var telemetryLogger = lspServices.GetRequiredService(); + + return new LogHubLspRequestScope(message, this, telemetryLogger); + } + + internal sealed class LogHubLspRequestScope : AbstractLspRequestScope + { + private readonly ILspServiceLogger _hostLogger; + private readonly RequestTelemetryScope _telemetryScope; + + public LogHubLspRequestScope(string name, ILspServiceLogger hostLogger, RequestTelemetryLogger requestTelemetryLogger) + : base(name) + { + _telemetryScope = new RequestTelemetryScope(name, requestTelemetryLogger); + + _hostLogger = hostLogger; + _hostLogger.LogStartContext(name); + } + + public override void RecordCancellation() + { + _hostLogger.LogInformation($"{Name} - Canceled"); + _telemetryScope.RecordCancellation(); + } + + public override void RecordException(Exception exception) + { + _hostLogger.LogException(exception); + _telemetryScope.RecordException(exception); + } + + public override void RecordWarning(string message) + { + _hostLogger.LogWarning(message); + _telemetryScope.RecordWarning(message); + } + + public override void Dispose() + { + _hostLogger.LogEndContext(Name); + _telemetryScope.Dispose(); + } + } } } From 796c7af5356ffeb95d761799ecea4873d782da9b Mon Sep 17 00:00:00 2001 From: Todd Grunke Date: Thu, 7 Dec 2023 11:06:53 -0800 Subject: [PATCH 02/10] remove accidental setting of launchDebugger flag --- .../Microsoft.CodeAnalysis.LanguageServer/Program.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Features/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Program.cs b/src/Features/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Program.cs index 80d9ce55e0386..422eb6b3309c3 100644 --- a/src/Features/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Program.cs +++ b/src/Features/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Program.cs @@ -198,7 +198,7 @@ static CliRootCommand CreateCommandLineParser() }; rootCommand.SetAction((parseResult, cancellationToken) => { - var launchDebugger = parseResult.GetValue(debugOption) || true; + var launchDebugger = parseResult.GetValue(debugOption); var logLevel = parseResult.GetValue(logLevelOption); var starredCompletionsPath = parseResult.GetValue(starredCompletionsPathOption); var telemetryLevel = parseResult.GetValue(telemetryLevelOption); From 612a6b1dcf6dc945320d857f2b6e15866b7582e1 Mon Sep 17 00:00:00 2001 From: Todd Grunke Date: Thu, 7 Dec 2023 11:55:10 -0800 Subject: [PATCH 03/10] make an abstract class for ILspLogger (and ILspRequestScope) --- .../LanguageServer/TestOutputLspLogger.cs | 27 +++++++------------ .../Logging/LspServiceLogger.cs | 16 +++++------ .../Mocks/NoOpLspLogger.cs | 16 +++++------ .../AbstractLspLogger.cs | 19 +++++++++++++ .../AbstractLspRequestScope.cs | 2 +- .../ILspLogger.cs | 2 -- .../ILspRequestScope.cs | 16 ----------- .../QueueItem.cs | 27 +++++++++++++------ .../LanguageServer/Protocol/NoOpLspLogger.cs | 16 +++++------ .../Def/LanguageClient/LogHubLspLogger.cs | 16 +++++------ 10 files changed, 80 insertions(+), 77 deletions(-) create mode 100644 src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractLspLogger.cs delete mode 100644 src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/ILspRequestScope.cs diff --git a/src/EditorFeatures/TestUtilities/LanguageServer/TestOutputLspLogger.cs b/src/EditorFeatures/TestUtilities/LanguageServer/TestOutputLspLogger.cs index e5d21ec6f315f..2661d2fe320d6 100644 --- a/src/EditorFeatures/TestUtilities/LanguageServer/TestOutputLspLogger.cs +++ b/src/EditorFeatures/TestUtilities/LanguageServer/TestOutputLspLogger.cs @@ -3,16 +3,12 @@ // See the LICENSE file in the project root for more information. using System; -using System.Collections.Generic; -using System.IO; -using System.Linq; -using System.Text; -using System.Threading.Tasks; using Microsoft.CommonLanguageServerProtocol.Framework; using Xunit.Abstractions; namespace Microsoft.CodeAnalysis.LanguageServer.UnitTests; -public class TestOutputLspLogger : ILspServiceLogger + +public sealed class TestOutputLspLogger : AbstractLspLogger, ILspServiceLogger { private readonly ITestOutputHelper _testOutputHelper; public TestOutputLspLogger(ITestOutputHelper testOutputHelper) @@ -20,25 +16,20 @@ public TestOutputLspLogger(ITestOutputHelper testOutputHelper) _testOutputHelper = testOutputHelper; } - public ILspRequestScope BeginScope(string message) - { - throw new NotImplementedException(); - } - - public void LogEndContext(string message, params object[] @params) => Log("End", message, @params); + public override void LogEndContext(string message, params object[] @params) => Log("End", message, @params); - public void LogError(string message, params object[] @params) => Log("Error", message, @params); + public override void LogError(string message, params object[] @params) => Log("Error", message, @params); - public void LogException(Exception exception, string? message = null, params object[] @params) + public override void LogException(Exception exception, string? message = null, params object[] @params) => Log("Warning", $"{message}{Environment.NewLine}{exception}", @params); - public void LogInformation(string message, params object[] @params) => Log("Info", message, @params); + public override void LogInformation(string message, params object[] @params) => Log("Info", message, @params); - public void LogStartContext(string message, params object[] @params) => Log("Start", message, @params); + public override void LogStartContext(string message, params object[] @params) => Log("Start", message, @params); - public void LogWarning(string message, params object[] @params) => Log("Warning", message, @params); + public override void LogWarning(string message, params object[] @params) => Log("Warning", message, @params); - public ILspRequestScope TrackLspRequest(string message, ILspServices lspServices) + public override AbstractLspRequestScope TrackLspRequest(string message, ILspServices lspServices) { throw new NotImplementedException(); } diff --git a/src/Features/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Logging/LspServiceLogger.cs b/src/Features/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Logging/LspServiceLogger.cs index 460e1edb3f876..190f627dce677 100644 --- a/src/Features/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Logging/LspServiceLogger.cs +++ b/src/Features/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Logging/LspServiceLogger.cs @@ -11,7 +11,7 @@ namespace Microsoft.CodeAnalysis.LanguageServer.Logging; /// /// Implements by sending LSP log messages back to the client. /// -internal sealed class LspServiceLogger : ILspServiceLogger +internal sealed class LspServiceLogger : AbstractLspLogger, ILspServiceLogger { private readonly ILogger _hostLogger; @@ -20,22 +20,22 @@ public LspServiceLogger(ILogger hostLogger) _hostLogger = hostLogger; } - public void LogEndContext(string message, params object[] @params) => _hostLogger.LogDebug($"[{DateTime.UtcNow:hh:mm:ss.fff}][End]{message}", @params); + public override void LogEndContext(string message, params object[] @params) => _hostLogger.LogDebug($"[{DateTime.UtcNow:hh:mm:ss.fff}][End]{message}", @params); - public void LogError(string message, params object[] @params) => _hostLogger.LogError(message, @params); + public override void LogError(string message, params object[] @params) => _hostLogger.LogError(message, @params); - public void LogException(Exception exception, string? message = null, params object[] @params) => _hostLogger.LogError(exception, message, @params); + public override void LogException(Exception exception, string? message = null, params object[] @params) => _hostLogger.LogError(exception, message, @params); /// /// TODO - This should call LogInformation, however we need to introduce a LogDebug call in clasp first. /// - public void LogInformation(string message, params object[] @params) => _hostLogger.LogDebug(message, @params); + public override void LogInformation(string message, params object[] @params) => _hostLogger.LogDebug(message, @params); - public void LogStartContext(string message, params object[] @params) => _hostLogger.LogDebug($"[{DateTime.UtcNow:hh:mm:ss.fff}][Start]{message}", @params); + public override void LogStartContext(string message, params object[] @params) => _hostLogger.LogDebug($"[{DateTime.UtcNow:hh:mm:ss.fff}][Start]{message}", @params); - public void LogWarning(string message, params object[] @params) => _hostLogger.LogWarning(message, @params); + public override void LogWarning(string message, params object[] @params) => _hostLogger.LogWarning(message, @params); - public ILspRequestScope TrackLspRequest(string lspMethodName, ILspServices lspServices) + public override AbstractLspRequestScope TrackLspRequest(string lspMethodName, ILspServices lspServices) { var telemetryLogger = lspServices.GetRequiredService(); diff --git a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework.UnitTests/Mocks/NoOpLspLogger.cs b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework.UnitTests/Mocks/NoOpLspLogger.cs index b96900cc703dc..4b0563a99729d 100644 --- a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework.UnitTests/Mocks/NoOpLspLogger.cs +++ b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework.UnitTests/Mocks/NoOpLspLogger.cs @@ -6,35 +6,35 @@ namespace Microsoft.CommonLanguageServerProtocol.Framework.UnitTests; -public class NoOpLspLogger : ILspLogger +public sealed class NoOpLspLogger : AbstractLspLogger, ILspLogger { public static NoOpLspLogger Instance = new(); - public void LogError(string message, params object[] @params) + public override void LogError(string message, params object[] @params) { } - public void LogException(Exception exception, string? message = null, params object[] @params) + public override void LogException(Exception exception, string? message = null, params object[] @params) { } - public void LogInformation(string message, params object[] @params) + public override void LogInformation(string message, params object[] @params) { } - public void LogStartContext(string context, params object[] @params) + public override void LogStartContext(string context, params object[] @params) { } - public void LogEndContext(string context, params object[] @params) + public override void LogEndContext(string context, params object[] @params) { } - public void LogWarning(string message, params object[] @params) + public override void LogWarning(string message, params object[] @params) { } - public ILspRequestScope TrackLspRequest(string message, ILspServices lspServices) + public override AbstractLspRequestScope TrackLspRequest(string message, ILspServices lspServices) { throw new NotImplementedException(); } diff --git a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractLspLogger.cs b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractLspLogger.cs new file mode 100644 index 0000000000000..7963346eae863 --- /dev/null +++ b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractLspLogger.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; + +namespace Microsoft.CommonLanguageServerProtocol.Framework; + +public abstract class AbstractLspLogger : ILspLogger +{ + public abstract void LogStartContext(string message, params object[] @params); + public abstract void LogEndContext(string message, params object[] @params); + public abstract void LogInformation(string message, params object[] @params); + public abstract void LogWarning(string message, params object[] @params); + public abstract void LogError(string message, params object[] @params); + public abstract void LogException(Exception exception, string? message = null, params object[] @params); + + public abstract AbstractLspRequestScope TrackLspRequest(string message, ILspServices lspServices); +} diff --git a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractLspRequestScope.cs b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractLspRequestScope.cs index 6b0379c05c40f..70824b7883d96 100644 --- a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractLspRequestScope.cs +++ b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractLspRequestScope.cs @@ -7,7 +7,7 @@ namespace Microsoft.CommonLanguageServerProtocol.Framework; -public abstract class AbstractLspRequestScope : ILspRequestScope +public abstract class AbstractLspRequestScope { private readonly Stopwatch _stopwatch; diff --git a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/ILspLogger.cs b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/ILspLogger.cs index 58b8dab2a670c..930ce4c6d939f 100644 --- a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/ILspLogger.cs +++ b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/ILspLogger.cs @@ -14,6 +14,4 @@ public interface ILspLogger void LogWarning(string message, params object[] @params); void LogError(string message, params object[] @params); void LogException(Exception exception, string? message = null, params object[] @params); - - ILspRequestScope TrackLspRequest(string message, ILspServices lspServices); } diff --git a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/ILspRequestScope.cs b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/ILspRequestScope.cs deleted file mode 100644 index 66368358c0b46..0000000000000 --- a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/ILspRequestScope.cs +++ /dev/null @@ -1,16 +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; - -namespace Microsoft.CommonLanguageServerProtocol.Framework; - -public interface ILspRequestScope : IDisposable -{ - void RecordExecutionStart(); - - void RecordCancellation(); - void RecordException(Exception exception); - void RecordWarning(string message); -} diff --git a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/QueueItem.cs b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/QueueItem.cs index b3c672d6bb1e3..301d4bfef13df 100644 --- a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/QueueItem.cs +++ b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/QueueItem.cs @@ -22,6 +22,10 @@ internal class QueueItem : IQueueItem /// A task completion source representing the result of this queue item's work. /// This is the task that the client is waiting on. @@ -36,8 +40,6 @@ internal class QueueItem : IQueueItem, Task) Create( @@ -89,7 +94,7 @@ public static (IQueueItem, Task) Create( { cancellationToken.ThrowIfCancellationRequested(); - _requestScope.RecordExecutionStart(); + _requestScope?.RecordExecutionStart(); var requestContextFactory = LspServices.GetRequiredService>(); var context = await requestContextFactory.CreateRequestContextAsync(this, _request, cancellationToken).ConfigureAwait(false); @@ -105,6 +110,7 @@ public static (IQueueItem, Task) Create( /// The result of the request. public async Task StartRequestAsync(TRequestContext? context, CancellationToken cancellationToken) { + _logger?.LogStartContext($"{MethodName}"); try { cancellationToken.ThrowIfCancellationRequested(); @@ -118,7 +124,9 @@ public async Task StartRequestAsync(TRequestContext? context, CancellationToken // the requests this could happen for. However, this assumption may not hold in the future. // If that turns out to be the case, we could defer to the individual handler to decide // what to do. - _requestScope.RecordWarning($"Could not get request context for {MethodName}"); + _requestScope?.RecordWarning($"Could not get request context for {MethodName}"); + _logger?.LogWarning($"Could not get request context for {MethodName}"); + _completionSource.TrySetException(new InvalidOperationException($"Unable to create request context for {MethodName}")); } else if (_handler is IRequestHandler requestHandler) @@ -155,7 +163,8 @@ public async Task StartRequestAsync(TRequestContext? context, CancellationToken catch (OperationCanceledException ex) { // Record logs + metrics on cancellation. - _requestScope.RecordCancellation(); + _requestScope?.RecordCancellation(); + _logger?.LogInformation($"{MethodName} - Canceled"); _completionSource.TrySetCanceled(ex.CancellationToken); } @@ -163,13 +172,15 @@ public async Task StartRequestAsync(TRequestContext? context, CancellationToken { // Record logs and metrics on the exception. // It's important that this can NEVER throw, or the queue will hang. - _requestScope.RecordException(ex); + _requestScope?.RecordException(ex); + _logger?.LogException(ex); _completionSource.TrySetException(ex); } finally { - _requestScope.Dispose(); + _requestScope?.Dispose(); + _logger?.LogEndContext($"{MethodName}"); } // Return the result of this completion source to the caller diff --git a/src/Features/LanguageServer/Protocol/NoOpLspLogger.cs b/src/Features/LanguageServer/Protocol/NoOpLspLogger.cs index b244447f53f7a..d242c47404ffe 100644 --- a/src/Features/LanguageServer/Protocol/NoOpLspLogger.cs +++ b/src/Features/LanguageServer/Protocol/NoOpLspLogger.cs @@ -7,37 +7,37 @@ namespace Microsoft.CodeAnalysis.LanguageServer { - internal class NoOpLspLogger : ILspServiceLogger + internal sealed class NoOpLspLogger : AbstractLspLogger, ILspServiceLogger { public static readonly ILspServiceLogger Instance = new NoOpLspLogger(); private NoOpLspLogger() { } - public void LogException(Exception exception, string? message = null, params object[] @params) + public override void LogException(Exception exception, string? message = null, params object[] @params) { } - public void LogInformation(string message, params object[] @params) + public override void LogInformation(string message, params object[] @params) { } - public void LogWarning(string message, params object[] @params) + public override void LogWarning(string message, params object[] @params) { } - public void LogError(string message, params object[] @params) + public override void LogError(string message, params object[] @params) { } - public void LogStartContext(string message, params object[] @params) + public override void LogStartContext(string message, params object[] @params) { } - public void LogEndContext(string message, params object[] @params) + public override void LogEndContext(string message, params object[] @params) { } - public ILspRequestScope TrackLspRequest(string message, ILspServices lspServices) + public override AbstractLspRequestScope TrackLspRequest(string message, ILspServices lspServices) { throw new NotImplementedException(); } diff --git a/src/VisualStudio/Core/Def/LanguageClient/LogHubLspLogger.cs b/src/VisualStudio/Core/Def/LanguageClient/LogHubLspLogger.cs index 3efc0abde4730..d800ed7622a3b 100644 --- a/src/VisualStudio/Core/Def/LanguageClient/LogHubLspLogger.cs +++ b/src/VisualStudio/Core/Def/LanguageClient/LogHubLspLogger.cs @@ -12,7 +12,7 @@ namespace Microsoft.VisualStudio.LanguageServices.Implementation.LanguageClient { - internal class LogHubLspLogger : ILspServiceLogger + internal sealed class LogHubLspLogger : AbstractLspLogger, ILspServiceLogger { private readonly TraceConfiguration _configuration; private readonly TraceSource _traceSource; @@ -38,7 +38,7 @@ public void Dispose() _configuration.Dispose(); } - public void LogInformation(string message, params object[] @params) + public override void LogInformation(string message, params object[] @params) { // Explicitly call TraceEvent here instead of TraceInformation. // TraceInformation indirectly calls string.Format which throws if the message @@ -47,32 +47,32 @@ public void LogInformation(string message, params object[] @params) _traceSource.TraceEvent(TraceEventType.Information, id: 0, message); } - public void LogWarning(string message, params object[] @params) + public override void LogWarning(string message, params object[] @params) { _traceSource.TraceEvent(TraceEventType.Warning, id: 0, message); } - public void LogError(string message, params object[] @params) + public override void LogError(string message, params object[] @params) { _traceSource.TraceEvent(TraceEventType.Error, id: 0, message); } - public void LogException(Exception exception, string? message = null, params object[] @params) + public override void LogException(Exception exception, string? message = null, params object[] @params) { _traceSource.TraceEvent(TraceEventType.Error, id: 0, "Exception: {0}", exception); } - public void LogStartContext(string message, params object[] @params) + public override void LogStartContext(string message, params object[] @params) { _traceSource.TraceEvent(TraceEventType.Start, id: 0, message); } - public void LogEndContext(string message, params object[] @params) + public override void LogEndContext(string message, params object[] @params) { _traceSource.TraceEvent(TraceEventType.Stop, id: 0, message); } - public ILspRequestScope TrackLspRequest(string message, ILspServices lspServices) + public override AbstractLspRequestScope TrackLspRequest(string message, ILspServices lspServices) { var telemetryLogger = lspServices.GetRequiredService(); From d877316f82ee67d35f5cc9e41c75da0d256f1d30 Mon Sep 17 00:00:00 2001 From: Todd Grunke Date: Thu, 7 Dec 2023 16:40:49 -0800 Subject: [PATCH 04/10] Add AbstractTelemetryService per conversation with David --- .../LanguageServer/TestOutputLspLogger.cs | 7 ++-- .../Logging/LspServiceLogger.cs | 11 ++---- .../Mocks/NoOpLspLogger.cs | 9 +++-- .../AbstractLspLogger.cs | 3 +- .../AbstractTelemetryService.cs | 10 ++++++ .../QueueItem.cs | 34 +++++++++---------- .../LspServices/LspTelemetryService.cs | 25 ++++++++++++++ .../LanguageServer/Protocol/NoOpLspLogger.cs | 9 +++-- .../Protocol/RoslynLanguageServer.cs | 1 + .../Def/LanguageClient/LogHubLspLogger.cs | 12 +++---- 10 files changed, 72 insertions(+), 49 deletions(-) create mode 100644 src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractTelemetryService.cs create mode 100644 src/Features/LanguageServer/Protocol/LspServices/LspTelemetryService.cs diff --git a/src/EditorFeatures/TestUtilities/LanguageServer/TestOutputLspLogger.cs b/src/EditorFeatures/TestUtilities/LanguageServer/TestOutputLspLogger.cs index 2661d2fe320d6..f0dec6d3ce3ae 100644 --- a/src/EditorFeatures/TestUtilities/LanguageServer/TestOutputLspLogger.cs +++ b/src/EditorFeatures/TestUtilities/LanguageServer/TestOutputLspLogger.cs @@ -16,6 +16,8 @@ public TestOutputLspLogger(ITestOutputHelper testOutputHelper) _testOutputHelper = testOutputHelper; } + public override void LogDebug(string message, params object[] @params) => Log("Debug", message, @params); + public override void LogEndContext(string message, params object[] @params) => Log("End", message, @params); public override void LogError(string message, params object[] @params) => Log("Error", message, @params); @@ -29,11 +31,6 @@ public override void LogException(Exception exception, string? message = null, p public override void LogWarning(string message, params object[] @params) => Log("Warning", message, @params); - public override AbstractLspRequestScope TrackLspRequest(string message, ILspServices lspServices) - { - throw new NotImplementedException(); - } - private void Log(string level, string message, params object[] @params) => _testOutputHelper.WriteLine($"[{DateTime.UtcNow:hh:mm:ss.fff}][{level}]{message}", @params); } diff --git a/src/Features/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Logging/LspServiceLogger.cs b/src/Features/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Logging/LspServiceLogger.cs index 190f627dce677..b721d096eb3b0 100644 --- a/src/Features/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Logging/LspServiceLogger.cs +++ b/src/Features/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Logging/LspServiceLogger.cs @@ -20,6 +20,8 @@ public LspServiceLogger(ILogger hostLogger) _hostLogger = hostLogger; } + public override void LogDebug(string message, params object[] @params) => _hostLogger.LogDebug(message, @params); + public override void LogEndContext(string message, params object[] @params) => _hostLogger.LogDebug($"[{DateTime.UtcNow:hh:mm:ss.fff}][End]{message}", @params); public override void LogError(string message, params object[] @params) => _hostLogger.LogError(message, @params); @@ -27,18 +29,11 @@ public LspServiceLogger(ILogger hostLogger) public override void LogException(Exception exception, string? message = null, params object[] @params) => _hostLogger.LogError(exception, message, @params); /// - /// TODO - This should call LogInformation, however we need to introduce a LogDebug call in clasp first. + /// TODO - Switch this to call LogInformation once appropriate callers have been changed to LogDebug. /// public override void LogInformation(string message, params object[] @params) => _hostLogger.LogDebug(message, @params); public override void LogStartContext(string message, params object[] @params) => _hostLogger.LogDebug($"[{DateTime.UtcNow:hh:mm:ss.fff}][Start]{message}", @params); public override void LogWarning(string message, params object[] @params) => _hostLogger.LogWarning(message, @params); - - public override AbstractLspRequestScope TrackLspRequest(string lspMethodName, ILspServices lspServices) - { - var telemetryLogger = lspServices.GetRequiredService(); - - return new RequestTelemetryScope(lspMethodName, telemetryLogger); - } } diff --git a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework.UnitTests/Mocks/NoOpLspLogger.cs b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework.UnitTests/Mocks/NoOpLspLogger.cs index 4b0563a99729d..55e6a48e3eda1 100644 --- a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework.UnitTests/Mocks/NoOpLspLogger.cs +++ b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework.UnitTests/Mocks/NoOpLspLogger.cs @@ -10,6 +10,10 @@ public sealed class NoOpLspLogger : AbstractLspLogger, ILspLogger { public static NoOpLspLogger Instance = new(); + public override void LogDebug(string message, params object[] @params) + { + } + public override void LogError(string message, params object[] @params) { } @@ -33,9 +37,4 @@ public override void LogEndContext(string context, params object[] @params) public override void LogWarning(string message, params object[] @params) { } - - public override AbstractLspRequestScope TrackLspRequest(string message, ILspServices lspServices) - { - throw new NotImplementedException(); - } } diff --git a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractLspLogger.cs b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractLspLogger.cs index 7963346eae863..3193fc8282f81 100644 --- a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractLspLogger.cs +++ b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractLspLogger.cs @@ -8,12 +8,11 @@ namespace Microsoft.CommonLanguageServerProtocol.Framework; public abstract class AbstractLspLogger : ILspLogger { + public abstract void LogDebug(string message, params object[] @params); public abstract void LogStartContext(string message, params object[] @params); public abstract void LogEndContext(string message, params object[] @params); public abstract void LogInformation(string message, params object[] @params); public abstract void LogWarning(string message, params object[] @params); public abstract void LogError(string message, params object[] @params); public abstract void LogException(Exception exception, string? message = null, params object[] @params); - - public abstract AbstractLspRequestScope TrackLspRequest(string message, ILspServices lspServices); } diff --git a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractTelemetryService.cs b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractTelemetryService.cs new file mode 100644 index 0000000000000..b4efc82490f05 --- /dev/null +++ b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractTelemetryService.cs @@ -0,0 +1,10 @@ +// 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. + +namespace Microsoft.CommonLanguageServerProtocol.Framework; + +public abstract class AbstractTelemetryService +{ + public abstract AbstractLspRequestScope CreateRequestScope(string lspMethodName, ILspServices lspServices); +} diff --git a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/QueueItem.cs b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/QueueItem.cs index 301d4bfef13df..04ca8442d747e 100644 --- a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/QueueItem.cs +++ b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/QueueItem.cs @@ -3,6 +3,7 @@ // See the LICENSE file in the project root for more information. using System; +using System.Linq; using System.Threading; using System.Threading.Tasks; using Microsoft.VisualStudio.Threading; @@ -22,9 +23,8 @@ internal class QueueItem : IQueueItem /// A task completion source representing the result of this queue item's work. @@ -54,6 +54,7 @@ private QueueItem( cancellationToken.Register(() => _completionSource.TrySetCanceled(cancellationToken)); _handler = handler; + _logger = logger; _request = request; LspServices = lspServices; MethodHandler = methodHandler; @@ -61,10 +62,9 @@ private QueueItem( MutatesServerState = mutatesSolutionState; MethodName = methodName; - if (logger is AbstractLspLogger lspLogger) - _requestScope = lspLogger.TrackLspRequest(methodName, LspServices); - else - _logger = logger; + var telemetryService = lspServices.GetRequiredServices().FirstOrDefault(); + + _requestTelemetryScope = telemetryService?.CreateRequestScope(methodName, LspServices); } public static (IQueueItem, Task) Create( @@ -94,7 +94,7 @@ public static (IQueueItem, Task) Create( { cancellationToken.ThrowIfCancellationRequested(); - _requestScope?.RecordExecutionStart(); + _requestTelemetryScope?.RecordExecutionStart(); var requestContextFactory = LspServices.GetRequiredService>(); var context = await requestContextFactory.CreateRequestContextAsync(this, _request, cancellationToken).ConfigureAwait(false); @@ -110,7 +110,7 @@ public static (IQueueItem, Task) Create( /// The result of the request. public async Task StartRequestAsync(TRequestContext? context, CancellationToken cancellationToken) { - _logger?.LogStartContext($"{MethodName}"); + _logger.LogStartContext($"{MethodName}"); try { cancellationToken.ThrowIfCancellationRequested(); @@ -124,8 +124,8 @@ public async Task StartRequestAsync(TRequestContext? context, CancellationToken // the requests this could happen for. However, this assumption may not hold in the future. // If that turns out to be the case, we could defer to the individual handler to decide // what to do. - _requestScope?.RecordWarning($"Could not get request context for {MethodName}"); - _logger?.LogWarning($"Could not get request context for {MethodName}"); + _requestTelemetryScope?.RecordWarning($"Could not get request context for {MethodName}"); + _logger.LogWarning($"Could not get request context for {MethodName}"); _completionSource.TrySetException(new InvalidOperationException($"Unable to create request context for {MethodName}")); } @@ -163,8 +163,8 @@ public async Task StartRequestAsync(TRequestContext? context, CancellationToken catch (OperationCanceledException ex) { // Record logs + metrics on cancellation. - _requestScope?.RecordCancellation(); - _logger?.LogInformation($"{MethodName} - Canceled"); + _requestTelemetryScope?.RecordCancellation(); + _logger.LogInformation($"{MethodName} - Canceled"); _completionSource.TrySetCanceled(ex.CancellationToken); } @@ -172,15 +172,15 @@ public async Task StartRequestAsync(TRequestContext? context, CancellationToken { // Record logs and metrics on the exception. // It's important that this can NEVER throw, or the queue will hang. - _requestScope?.RecordException(ex); - _logger?.LogException(ex); + _requestTelemetryScope?.RecordException(ex); + _logger.LogException(ex); _completionSource.TrySetException(ex); } finally { - _requestScope?.Dispose(); - _logger?.LogEndContext($"{MethodName}"); + _requestTelemetryScope?.Dispose(); + _logger.LogEndContext($"{MethodName}"); } // Return the result of this completion source to the caller diff --git a/src/Features/LanguageServer/Protocol/LspServices/LspTelemetryService.cs b/src/Features/LanguageServer/Protocol/LspServices/LspTelemetryService.cs new file mode 100644 index 0000000000000..81e9dc654f258 --- /dev/null +++ b/src/Features/LanguageServer/Protocol/LspServices/LspTelemetryService.cs @@ -0,0 +1,25 @@ +// 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.LanguageServer.Handler; +using Microsoft.CommonLanguageServerProtocol.Framework; + +namespace Microsoft.CodeAnalysis.LanguageServer; + +internal sealed class LspTelemetryService : AbstractTelemetryService, ILspService +{ + private readonly RequestTelemetryLogger _requestTelemetryLogger; + + public LspTelemetryService(ILspServices lspServices) + { + var requestTelemetryLogger = lspServices.GetRequiredService(); + + _requestTelemetryLogger = requestTelemetryLogger; + } + + public override AbstractLspRequestScope CreateRequestScope(string lspMethodName, ILspServices lspServices) + { + return new RequestTelemetryScope(lspMethodName, _requestTelemetryLogger); + } +} diff --git a/src/Features/LanguageServer/Protocol/NoOpLspLogger.cs b/src/Features/LanguageServer/Protocol/NoOpLspLogger.cs index d242c47404ffe..8c7a0ebba369c 100644 --- a/src/Features/LanguageServer/Protocol/NoOpLspLogger.cs +++ b/src/Features/LanguageServer/Protocol/NoOpLspLogger.cs @@ -13,6 +13,10 @@ internal sealed class NoOpLspLogger : AbstractLspLogger, ILspServiceLogger private NoOpLspLogger() { } + public override void LogDebug(string message, params object[] @params) + { + } + public override void LogException(Exception exception, string? message = null, params object[] @params) { } @@ -36,10 +40,5 @@ public override void LogStartContext(string message, params object[] @params) public override void LogEndContext(string message, params object[] @params) { } - - public override AbstractLspRequestScope TrackLspRequest(string message, ILspServices lspServices) - { - throw new NotImplementedException(); - } } } diff --git a/src/Features/LanguageServer/Protocol/RoslynLanguageServer.cs b/src/Features/LanguageServer/Protocol/RoslynLanguageServer.cs index 4b55c474be0e6..b008b4af897bc 100644 --- a/src/Features/LanguageServer/Protocol/RoslynLanguageServer.cs +++ b/src/Features/LanguageServer/Protocol/RoslynLanguageServer.cs @@ -74,6 +74,7 @@ private ImmutableDictionary>> Ge AddBaseService(new ServerInfoProvider(serverKind, supportedLanguages)); AddBaseServiceFromFunc>((lspServices) => new RequestContextFactory(lspServices)); AddBaseServiceFromFunc>((_) => GetRequestExecutionQueue()); + AddBaseServiceFromFunc((lspServices) => new LspTelemetryService(lspServices)); AddBaseService(new InitializeManager()); AddBaseService(new InitializeHandler()); AddBaseService(new InitializedHandler()); diff --git a/src/VisualStudio/Core/Def/LanguageClient/LogHubLspLogger.cs b/src/VisualStudio/Core/Def/LanguageClient/LogHubLspLogger.cs index d800ed7622a3b..c5f8241e7c241 100644 --- a/src/VisualStudio/Core/Def/LanguageClient/LogHubLspLogger.cs +++ b/src/VisualStudio/Core/Def/LanguageClient/LogHubLspLogger.cs @@ -38,6 +38,11 @@ public void Dispose() _configuration.Dispose(); } + public override void LogDebug(string message, params object[] @params) + { + _traceSource.TraceEvent(TraceEventType.Verbose, id: 0, message); + } + public override void LogInformation(string message, params object[] @params) { // Explicitly call TraceEvent here instead of TraceInformation. @@ -72,13 +77,6 @@ public override void LogEndContext(string message, params object[] @params) _traceSource.TraceEvent(TraceEventType.Stop, id: 0, message); } - public override AbstractLspRequestScope TrackLspRequest(string message, ILspServices lspServices) - { - var telemetryLogger = lspServices.GetRequiredService(); - - return new LogHubLspRequestScope(message, this, telemetryLogger); - } - internal sealed class LogHubLspRequestScope : AbstractLspRequestScope { private readonly ILspServiceLogger _hostLogger; From e22f677e4e0f992961a5756b10d2df6e305afaa0 Mon Sep 17 00:00:00 2001 From: Todd Grunke Date: Thu, 7 Dec 2023 16:45:47 -0800 Subject: [PATCH 05/10] Remove now unused LogHubLspRequestScope --- .../Def/LanguageClient/LogHubLspLogger.cs | 40 ------------------- 1 file changed, 40 deletions(-) diff --git a/src/VisualStudio/Core/Def/LanguageClient/LogHubLspLogger.cs b/src/VisualStudio/Core/Def/LanguageClient/LogHubLspLogger.cs index c5f8241e7c241..f55dd4cd995fb 100644 --- a/src/VisualStudio/Core/Def/LanguageClient/LogHubLspLogger.cs +++ b/src/VisualStudio/Core/Def/LanguageClient/LogHubLspLogger.cs @@ -5,7 +5,6 @@ using System; using System.Diagnostics; using Microsoft.CodeAnalysis.LanguageServer; -using Microsoft.CodeAnalysis.LanguageServer.Handler; using Microsoft.CommonLanguageServerProtocol.Framework; using Microsoft.VisualStudio.LogHub; using Roslyn.Utilities; @@ -76,44 +75,5 @@ public override void LogEndContext(string message, params object[] @params) { _traceSource.TraceEvent(TraceEventType.Stop, id: 0, message); } - - internal sealed class LogHubLspRequestScope : AbstractLspRequestScope - { - private readonly ILspServiceLogger _hostLogger; - private readonly RequestTelemetryScope _telemetryScope; - - public LogHubLspRequestScope(string name, ILspServiceLogger hostLogger, RequestTelemetryLogger requestTelemetryLogger) - : base(name) - { - _telemetryScope = new RequestTelemetryScope(name, requestTelemetryLogger); - - _hostLogger = hostLogger; - _hostLogger.LogStartContext(name); - } - - public override void RecordCancellation() - { - _hostLogger.LogInformation($"{Name} - Canceled"); - _telemetryScope.RecordCancellation(); - } - - public override void RecordException(Exception exception) - { - _hostLogger.LogException(exception); - _telemetryScope.RecordException(exception); - } - - public override void RecordWarning(string message) - { - _hostLogger.LogWarning(message); - _telemetryScope.RecordWarning(message); - } - - public override void Dispose() - { - _hostLogger.LogEndContext(Name); - _telemetryScope.Dispose(); - } - } } } From 2e01ab83671b47f0718839a583abdeeb5d9d6947 Mon Sep 17 00:00:00 2001 From: Todd Grunke Date: Fri, 8 Dec 2023 08:24:44 -0800 Subject: [PATCH 06/10] Some cleanup --- .../AbstractTelemetryService.cs | 2 +- .../QueueItem.cs | 2 +- .../LanguageServer/Protocol/LspServices/LspTelemetryService.cs | 2 +- .../Protocol/{Handler => LspServices}/RequestTelemetryScope.cs | 3 ++- 4 files changed, 5 insertions(+), 4 deletions(-) rename src/Features/LanguageServer/Protocol/{Handler => LspServices}/RequestTelemetryScope.cs (91%) diff --git a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractTelemetryService.cs b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractTelemetryService.cs index b4efc82490f05..13b3efabf16cc 100644 --- a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractTelemetryService.cs +++ b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractTelemetryService.cs @@ -6,5 +6,5 @@ namespace Microsoft.CommonLanguageServerProtocol.Framework; public abstract class AbstractTelemetryService { - public abstract AbstractLspRequestScope CreateRequestScope(string lspMethodName, ILspServices lspServices); + public abstract AbstractLspRequestScope CreateRequestScope(string lspMethodName); } diff --git a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/QueueItem.cs b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/QueueItem.cs index 04ca8442d747e..9754feea88927 100644 --- a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/QueueItem.cs +++ b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/QueueItem.cs @@ -64,7 +64,7 @@ private QueueItem( var telemetryService = lspServices.GetRequiredServices().FirstOrDefault(); - _requestTelemetryScope = telemetryService?.CreateRequestScope(methodName, LspServices); + _requestTelemetryScope = telemetryService?.CreateRequestScope(methodName); } public static (IQueueItem, Task) Create( diff --git a/src/Features/LanguageServer/Protocol/LspServices/LspTelemetryService.cs b/src/Features/LanguageServer/Protocol/LspServices/LspTelemetryService.cs index 81e9dc654f258..afad3212392b5 100644 --- a/src/Features/LanguageServer/Protocol/LspServices/LspTelemetryService.cs +++ b/src/Features/LanguageServer/Protocol/LspServices/LspTelemetryService.cs @@ -18,7 +18,7 @@ public LspTelemetryService(ILspServices lspServices) _requestTelemetryLogger = requestTelemetryLogger; } - public override AbstractLspRequestScope CreateRequestScope(string lspMethodName, ILspServices lspServices) + public override AbstractLspRequestScope CreateRequestScope(string lspMethodName) { return new RequestTelemetryScope(lspMethodName, _requestTelemetryLogger); } diff --git a/src/Features/LanguageServer/Protocol/Handler/RequestTelemetryScope.cs b/src/Features/LanguageServer/Protocol/LspServices/RequestTelemetryScope.cs similarity index 91% rename from src/Features/LanguageServer/Protocol/Handler/RequestTelemetryScope.cs rename to src/Features/LanguageServer/Protocol/LspServices/RequestTelemetryScope.cs index 9e4cd13b63cf5..1214f764a4a56 100644 --- a/src/Features/LanguageServer/Protocol/Handler/RequestTelemetryScope.cs +++ b/src/Features/LanguageServer/Protocol/LspServices/RequestTelemetryScope.cs @@ -3,9 +3,10 @@ // See the LICENSE file in the project root for more information. using System; +using Microsoft.CodeAnalysis.LanguageServer.Handler; using Microsoft.CommonLanguageServerProtocol.Framework; -namespace Microsoft.CodeAnalysis.LanguageServer.Handler; +namespace Microsoft.CodeAnalysis.LanguageServer; internal sealed class RequestTelemetryScope(string name, RequestTelemetryLogger telemetryLogger) : AbstractLspRequestScope(name) From 7e04d6ba991adb842ac5e71c46752d91365117c9 Mon Sep 17 00:00:00 2001 From: Todd Grunke Date: Fri, 8 Dec 2023 08:53:40 -0800 Subject: [PATCH 07/10] Rename a couple classes. Move some work from AbstractRequestScope to RequestTelemetryScope to allow for usage of SharedStopwatch Remove RequestMetrics class --- .../AbstractLspRequestScope.cs | 40 -------------- .../AbstractRequestScope.cs | 20 +++++++ .../AbstractTelemetryService.cs | 2 +- .../QueueItem.cs | 2 +- .../Protocol/Handler/RequestMetrics.cs | 54 ------------------- .../LspServices/RequestTelemetryScope.cs | 18 +++++-- ...elemetryService.cs => TelemetryService.cs} | 6 +-- .../Protocol/RoslynLanguageServer.cs | 2 +- .../Impl/Logging/VSCodeTelemetryLogger.cs | 2 +- 9 files changed, 40 insertions(+), 106 deletions(-) delete mode 100644 src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractLspRequestScope.cs create mode 100644 src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractRequestScope.cs delete mode 100644 src/Features/LanguageServer/Protocol/Handler/RequestMetrics.cs rename src/Features/LanguageServer/Protocol/LspServices/{LspTelemetryService.cs => TelemetryService.cs} (75%) diff --git a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractLspRequestScope.cs b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractLspRequestScope.cs deleted file mode 100644 index 70824b7883d96..0000000000000 --- a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractLspRequestScope.cs +++ /dev/null @@ -1,40 +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.Diagnostics; - -namespace Microsoft.CommonLanguageServerProtocol.Framework; - -public abstract class AbstractLspRequestScope -{ - private readonly Stopwatch _stopwatch; - - protected string Name { get; } - - protected TimeSpan QueuedDuration { get; private set; } - protected TimeSpan RequestDuration { get; private set; } - - protected AbstractLspRequestScope(string name) - { - _stopwatch = Stopwatch.StartNew(); - Name = name; - } - - public abstract void RecordCancellation(); - public abstract void RecordException(Exception exception); - public abstract void RecordWarning(string message); - - public void RecordExecutionStart() - { - QueuedDuration = _stopwatch.Elapsed; - } - - public virtual void Dispose() - { - RequestDuration = _stopwatch.Elapsed; - - _stopwatch.Stop(); - } -} diff --git a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractRequestScope.cs b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractRequestScope.cs new file mode 100644 index 0000000000000..efd36dccd0e4b --- /dev/null +++ b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractRequestScope.cs @@ -0,0 +1,20 @@ +// 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; + +namespace Microsoft.CommonLanguageServerProtocol.Framework; + +public abstract class AbstractRequestScope(string name) : IDisposable +{ + public string Name { get; } = name; + + public abstract void RecordCancellation(); + public abstract void RecordException(Exception exception); + public abstract void RecordWarning(string message); + + public abstract void RecordExecutionStart(); + + public abstract void Dispose(); +} diff --git a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractTelemetryService.cs b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractTelemetryService.cs index 13b3efabf16cc..cb60f7e6852f6 100644 --- a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractTelemetryService.cs +++ b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractTelemetryService.cs @@ -6,5 +6,5 @@ namespace Microsoft.CommonLanguageServerProtocol.Framework; public abstract class AbstractTelemetryService { - public abstract AbstractLspRequestScope CreateRequestScope(string lspMethodName); + public abstract AbstractRequestScope CreateRequestScope(string lspMethodName); } diff --git a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/QueueItem.cs b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/QueueItem.cs index 9754feea88927..6cfa4a29ed01c 100644 --- a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/QueueItem.cs +++ b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/QueueItem.cs @@ -24,7 +24,7 @@ internal class QueueItem : IQueueItem /// A task completion source representing the result of this queue item's work. diff --git a/src/Features/LanguageServer/Protocol/Handler/RequestMetrics.cs b/src/Features/LanguageServer/Protocol/Handler/RequestMetrics.cs deleted file mode 100644 index e2c01bccc5cc4..0000000000000 --- a/src/Features/LanguageServer/Protocol/Handler/RequestMetrics.cs +++ /dev/null @@ -1,54 +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 Microsoft.CommonLanguageServerProtocol.Framework; -using Roslyn.Utilities; - -namespace Microsoft.CodeAnalysis.LanguageServer.Handler -{ - internal class RequestMetrics - { - private readonly string _methodName; - private readonly SharedStopwatch _sharedStopWatch; - private TimeSpan? _queuedDuration; - - private readonly RequestTelemetryLogger _requestTelemetryLogger; - - public RequestMetrics(string methodName, RequestTelemetryLogger requestTelemetryLogger) - { - _methodName = methodName; - _requestTelemetryLogger = requestTelemetryLogger; - _sharedStopWatch = SharedStopwatch.StartNew(); - } - - public void RecordExecutionStart() - { - // Request has de-queued and is starting execution. Record the time it spent in queue. - _queuedDuration = _sharedStopWatch.Elapsed; - } - - public void RecordSuccess() - { - RecordCompletion(RequestTelemetryLogger.Result.Succeeded); - } - - public void RecordFailure() - { - RecordCompletion(RequestTelemetryLogger.Result.Failed); - } - - public void RecordCancellation() - { - RecordCompletion(RequestTelemetryLogger.Result.Cancelled); - } - - private void RecordCompletion(RequestTelemetryLogger.Result result) - { - Contract.ThrowIfNull(_queuedDuration, "RecordExecutionStart was not called"); - var overallDuration = _sharedStopWatch.Elapsed; - _requestTelemetryLogger.UpdateTelemetryData(_methodName, _queuedDuration.Value, overallDuration, result); - } - } -} diff --git a/src/Features/LanguageServer/Protocol/LspServices/RequestTelemetryScope.cs b/src/Features/LanguageServer/Protocol/LspServices/RequestTelemetryScope.cs index 1214f764a4a56..9c4798d119d42 100644 --- a/src/Features/LanguageServer/Protocol/LspServices/RequestTelemetryScope.cs +++ b/src/Features/LanguageServer/Protocol/LspServices/RequestTelemetryScope.cs @@ -5,20 +5,21 @@ using System; using Microsoft.CodeAnalysis.LanguageServer.Handler; using Microsoft.CommonLanguageServerProtocol.Framework; +using Roslyn.Utilities; namespace Microsoft.CodeAnalysis.LanguageServer; internal sealed class RequestTelemetryScope(string name, RequestTelemetryLogger telemetryLogger) - : AbstractLspRequestScope(name) + : AbstractRequestScope(name) { private readonly RequestTelemetryLogger _telemetryLogger = telemetryLogger; private RequestTelemetryLogger.Result _result = RequestTelemetryLogger.Result.Succeeded; + private readonly SharedStopwatch _stopwatch = SharedStopwatch.StartNew(); + private TimeSpan _queuedDuration; - public override void Dispose() + public override void RecordExecutionStart() { - base.Dispose(); - - _telemetryLogger.UpdateTelemetryData(Name, QueuedDuration, RequestDuration, _result); + _queuedDuration = _stopwatch.Elapsed; } public override void RecordCancellation() @@ -35,4 +36,11 @@ public override void RecordWarning(string message) { _result = RequestTelemetryLogger.Result.Failed; } + + public override void Dispose() + { + var requestDuration = _stopwatch.Elapsed; + + _telemetryLogger.UpdateTelemetryData(Name, _queuedDuration, requestDuration, _result); + } } diff --git a/src/Features/LanguageServer/Protocol/LspServices/LspTelemetryService.cs b/src/Features/LanguageServer/Protocol/LspServices/TelemetryService.cs similarity index 75% rename from src/Features/LanguageServer/Protocol/LspServices/LspTelemetryService.cs rename to src/Features/LanguageServer/Protocol/LspServices/TelemetryService.cs index afad3212392b5..ce6c97dcda840 100644 --- a/src/Features/LanguageServer/Protocol/LspServices/LspTelemetryService.cs +++ b/src/Features/LanguageServer/Protocol/LspServices/TelemetryService.cs @@ -7,18 +7,18 @@ namespace Microsoft.CodeAnalysis.LanguageServer; -internal sealed class LspTelemetryService : AbstractTelemetryService, ILspService +internal sealed class TelemetryService : AbstractTelemetryService, ILspService { private readonly RequestTelemetryLogger _requestTelemetryLogger; - public LspTelemetryService(ILspServices lspServices) + public TelemetryService(ILspServices lspServices) { var requestTelemetryLogger = lspServices.GetRequiredService(); _requestTelemetryLogger = requestTelemetryLogger; } - public override AbstractLspRequestScope CreateRequestScope(string lspMethodName) + public override AbstractRequestScope CreateRequestScope(string lspMethodName) { return new RequestTelemetryScope(lspMethodName, _requestTelemetryLogger); } diff --git a/src/Features/LanguageServer/Protocol/RoslynLanguageServer.cs b/src/Features/LanguageServer/Protocol/RoslynLanguageServer.cs index b008b4af897bc..f47cfde3ad849 100644 --- a/src/Features/LanguageServer/Protocol/RoslynLanguageServer.cs +++ b/src/Features/LanguageServer/Protocol/RoslynLanguageServer.cs @@ -74,7 +74,7 @@ private ImmutableDictionary>> Ge AddBaseService(new ServerInfoProvider(serverKind, supportedLanguages)); AddBaseServiceFromFunc>((lspServices) => new RequestContextFactory(lspServices)); AddBaseServiceFromFunc>((_) => GetRequestExecutionQueue()); - AddBaseServiceFromFunc((lspServices) => new LspTelemetryService(lspServices)); + AddBaseServiceFromFunc((lspServices) => new TelemetryService(lspServices)); AddBaseService(new InitializeManager()); AddBaseService(new InitializeHandler()); AddBaseService(new InitializedHandler()); diff --git a/src/VisualStudio/DevKit/Impl/Logging/VSCodeTelemetryLogger.cs b/src/VisualStudio/DevKit/Impl/Logging/VSCodeTelemetryLogger.cs index 3e7d00fa2223d..c28adc1aacbe1 100644 --- a/src/VisualStudio/DevKit/Impl/Logging/VSCodeTelemetryLogger.cs +++ b/src/VisualStudio/DevKit/Impl/Logging/VSCodeTelemetryLogger.cs @@ -39,7 +39,7 @@ public void InitializeSession(string telemetryLevel, string? sessionId, bool isD if (isDefaultSession) { - TelemetryService.SetDefaultSession(session); + VisualStudio.Telemetry.TelemetryService.SetDefaultSession(session); } session.Start(); From 8cf7d6c0f87cffbbd8db2e0bf0c7103f4d93f8c6 Mon Sep 17 00:00:00 2001 From: Todd Grunke Date: Fri, 8 Dec 2023 09:15:52 -0800 Subject: [PATCH 08/10] Get rid of internal ILspServiceLogger interface. Since it was internal, switch all usages to AbstractLspLogger. --- .../LanguageServer/AbstractInProcLanguageClient.cs | 3 +-- .../AbstractLanguageServerProtocolTests.cs | 6 +++--- .../LanguageServer/TestOutputLspLogger.cs | 2 +- .../Logging/LspServiceLogger.cs | 5 ++--- .../CSharpVisualBasicLanguageServerFactory.cs | 8 +++----- ...ChangeConfigurationNotificationHandlerFactory.cs | 3 ++- .../Protocol/Handler/RequestContextFactory.cs | 2 +- .../Protocol/ILanguageServerFactory.cs | 3 +-- .../LanguageServer/Protocol/ILspServiceLogger.cs | 13 ------------- .../Protocol/ILspServiceLoggerFactory.cs | 2 +- .../LanguageServer/Protocol/NoOpLspLogger.cs | 4 ++-- .../LanguageServer/Protocol/RoslynLanguageServer.cs | 6 +++--- .../Workspaces/LspWorkspaceManagerFactory.cs | 3 ++- .../Core/Def/LanguageClient/LogHubLspLogger.cs | 2 +- .../VisualStudioLogHubLoggerFactory.cs | 2 +- 15 files changed, 24 insertions(+), 40 deletions(-) delete mode 100644 src/Features/LanguageServer/Protocol/ILspServiceLogger.cs diff --git a/src/EditorFeatures/Core/LanguageServer/AbstractInProcLanguageClient.cs b/src/EditorFeatures/Core/LanguageServer/AbstractInProcLanguageClient.cs index db996d5b5f6df..abe00f37ee641 100644 --- a/src/EditorFeatures/Core/LanguageServer/AbstractInProcLanguageClient.cs +++ b/src/EditorFeatures/Core/LanguageServer/AbstractInProcLanguageClient.cs @@ -6,7 +6,6 @@ using System.Collections.Generic; using System.Collections.Immutable; using System.IO; -using System.Runtime.ExceptionServices; using System.Threading; using System.Threading.Tasks; using Microsoft.CodeAnalysis.Editor.Shared.Utilities; @@ -227,7 +226,7 @@ public virtual AbstractLanguageServer Create( JsonRpc jsonRpc, ICapabilitiesProvider capabilitiesProvider, WellKnownLspServerKinds serverKind, - ILspServiceLogger logger, + AbstractLspLogger logger, HostServices hostServices) { var server = new RoslynLanguageServer( diff --git a/src/EditorFeatures/TestUtilities/LanguageServer/AbstractLanguageServerProtocolTests.cs b/src/EditorFeatures/TestUtilities/LanguageServer/AbstractLanguageServerProtocolTests.cs index 648deac1e090a..f953c92a686fe 100644 --- a/src/EditorFeatures/TestUtilities/LanguageServer/AbstractLanguageServerProtocolTests.cs +++ b/src/EditorFeatures/TestUtilities/LanguageServer/AbstractLanguageServerProtocolTests.cs @@ -44,7 +44,7 @@ namespace Roslyn.Test.Utilities [UseExportProvider] public abstract partial class AbstractLanguageServerProtocolTests { - private protected readonly ILspServiceLogger TestOutputLspLogger; + private protected readonly AbstractLspLogger TestOutputLspLogger; protected AbstractLanguageServerProtocolTests(ITestOutputHelper? testOutputHelper) { TestOutputLspLogger = testOutputHelper != null ? new TestOutputLspLogger(testOutputHelper) : NoOpLspLogger.Instance; @@ -580,7 +580,7 @@ private static JsonMessageFormatter CreateJsonMessageFormatter() return messageFormatter; } - internal static async Task CreateAsync(TestWorkspace testWorkspace, InitializationOptions initializationOptions, ILspServiceLogger logger) + internal static async Task CreateAsync(TestWorkspace testWorkspace, InitializationOptions initializationOptions, AbstractLspLogger logger) { var locations = await GetAnnotatedLocationsAsync(testWorkspace, testWorkspace.CurrentSolution); @@ -618,7 +618,7 @@ internal static async Task CreateAsync(TestWorkspace testWorkspac return server; } - private static RoslynLanguageServer CreateLanguageServer(Stream inputStream, Stream outputStream, TestWorkspace workspace, WellKnownLspServerKinds serverKind, ILspServiceLogger logger) + private static RoslynLanguageServer CreateLanguageServer(Stream inputStream, Stream outputStream, TestWorkspace workspace, WellKnownLspServerKinds serverKind, AbstractLspLogger logger) { var capabilitiesProvider = workspace.ExportProvider.GetExportedValue(); var servicesProvider = workspace.ExportProvider.GetExportedValue(); diff --git a/src/EditorFeatures/TestUtilities/LanguageServer/TestOutputLspLogger.cs b/src/EditorFeatures/TestUtilities/LanguageServer/TestOutputLspLogger.cs index f0dec6d3ce3ae..45f51a01f86d1 100644 --- a/src/EditorFeatures/TestUtilities/LanguageServer/TestOutputLspLogger.cs +++ b/src/EditorFeatures/TestUtilities/LanguageServer/TestOutputLspLogger.cs @@ -8,7 +8,7 @@ namespace Microsoft.CodeAnalysis.LanguageServer.UnitTests; -public sealed class TestOutputLspLogger : AbstractLspLogger, ILspServiceLogger +public sealed class TestOutputLspLogger : AbstractLspLogger, ILspService { private readonly ITestOutputHelper _testOutputHelper; public TestOutputLspLogger(ITestOutputHelper testOutputHelper) diff --git a/src/Features/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Logging/LspServiceLogger.cs b/src/Features/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Logging/LspServiceLogger.cs index b721d096eb3b0..861d4956c3d1b 100644 --- a/src/Features/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Logging/LspServiceLogger.cs +++ b/src/Features/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Logging/LspServiceLogger.cs @@ -2,16 +2,15 @@ // 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.LanguageServer.Handler; using Microsoft.CommonLanguageServerProtocol.Framework; using Microsoft.Extensions.Logging; namespace Microsoft.CodeAnalysis.LanguageServer.Logging; /// -/// Implements by sending LSP log messages back to the client. +/// Implements by sending LSP log messages back to the client. /// -internal sealed class LspServiceLogger : AbstractLspLogger, ILspServiceLogger +internal sealed class LspServiceLogger : AbstractLspLogger, ILspService { private readonly ILogger _hostLogger; diff --git a/src/Features/LanguageServer/Protocol/CSharpVisualBasicLanguageServerFactory.cs b/src/Features/LanguageServer/Protocol/CSharpVisualBasicLanguageServerFactory.cs index 57450ecae1b49..cabf59bcd9dd3 100644 --- a/src/Features/LanguageServer/Protocol/CSharpVisualBasicLanguageServerFactory.cs +++ b/src/Features/LanguageServer/Protocol/CSharpVisualBasicLanguageServerFactory.cs @@ -5,13 +5,11 @@ using System; using System.Composition; using System.IO; -using System.Threading.Tasks; +using Microsoft.CodeAnalysis.Host; using Microsoft.CodeAnalysis.Host.Mef; using Microsoft.CodeAnalysis.LanguageServer.Handler; using Microsoft.CommonLanguageServerProtocol.Framework; -using Microsoft.CodeAnalysis.ExternalAccess.Razor; using StreamJsonRpc; -using Microsoft.CodeAnalysis.Host; namespace Microsoft.CodeAnalysis.LanguageServer { @@ -32,7 +30,7 @@ public AbstractLanguageServer Create( JsonRpc jsonRpc, ICapabilitiesProvider capabilitiesProvider, WellKnownLspServerKinds serverKind, - ILspServiceLogger logger, + AbstractLspLogger logger, HostServices hostServices) { var server = new RoslynLanguageServer( @@ -47,7 +45,7 @@ public AbstractLanguageServer Create( return server; } - public AbstractLanguageServer Create(Stream input, Stream output, ICapabilitiesProvider capabilitiesProvider, ILspServiceLogger logger, HostServices hostServices) + public AbstractLanguageServer Create(Stream input, Stream output, ICapabilitiesProvider capabilitiesProvider, AbstractLspLogger logger, HostServices hostServices) { var jsonRpc = new JsonRpc(new HeaderDelimitedMessageHandler(output, input)); return Create(jsonRpc, capabilitiesProvider, WellKnownLspServerKinds.CSharpVisualBasicLspServer, logger, hostServices); diff --git a/src/Features/LanguageServer/Protocol/Handler/Configuration/DidChangeConfigurationNotificationHandlerFactory.cs b/src/Features/LanguageServer/Protocol/Handler/Configuration/DidChangeConfigurationNotificationHandlerFactory.cs index e050706998871..c0fbba1507e28 100644 --- a/src/Features/LanguageServer/Protocol/Handler/Configuration/DidChangeConfigurationNotificationHandlerFactory.cs +++ b/src/Features/LanguageServer/Protocol/Handler/Configuration/DidChangeConfigurationNotificationHandlerFactory.cs @@ -6,6 +6,7 @@ using System.Composition; using Microsoft.CodeAnalysis.Host.Mef; using Microsoft.CodeAnalysis.Options; +using Microsoft.CommonLanguageServerProtocol.Framework; namespace Microsoft.CodeAnalysis.LanguageServer.Handler.Configuration { @@ -25,7 +26,7 @@ public DidChangeConfigurationNotificationHandlerFactory( public ILspService CreateILspService(LspServices lspServices, WellKnownLspServerKinds serverKind) { var clientManager = lspServices.GetRequiredService(); - var lspLogger = lspServices.GetRequiredService(); + var lspLogger = lspServices.GetRequiredService(); return new DidChangeConfigurationNotificationHandler(lspLogger, _globalOptionService, clientManager); } } diff --git a/src/Features/LanguageServer/Protocol/Handler/RequestContextFactory.cs b/src/Features/LanguageServer/Protocol/Handler/RequestContextFactory.cs index 5bd4eb233cc1b..dd902cc006bb0 100644 --- a/src/Features/LanguageServer/Protocol/Handler/RequestContextFactory.cs +++ b/src/Features/LanguageServer/Protocol/Handler/RequestContextFactory.cs @@ -23,7 +23,7 @@ public Task CreateRequestContextAsync(IQueueItem< { var clientCapabilitiesManager = _lspServices.GetRequiredService(); var clientCapabilities = clientCapabilitiesManager.TryGetClientCapabilities(); - var logger = _lspServices.GetRequiredService(); + var logger = _lspServices.GetRequiredService(); var serverInfoProvider = _lspServices.GetRequiredService(); if (clientCapabilities is null && queueItem.MethodName != Methods.InitializeName) diff --git a/src/Features/LanguageServer/Protocol/ILanguageServerFactory.cs b/src/Features/LanguageServer/Protocol/ILanguageServerFactory.cs index 0eb5a5e79185f..243190649afe8 100644 --- a/src/Features/LanguageServer/Protocol/ILanguageServerFactory.cs +++ b/src/Features/LanguageServer/Protocol/ILanguageServerFactory.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.Threading.Tasks; using Microsoft.CodeAnalysis.Host; using Microsoft.CodeAnalysis.LanguageServer.Handler; using Microsoft.CommonLanguageServerProtocol.Framework; @@ -16,7 +15,7 @@ public AbstractLanguageServer Create( JsonRpc jsonRpc, ICapabilitiesProvider capabilitiesProvider, WellKnownLspServerKinds serverKind, - ILspServiceLogger logger, + AbstractLspLogger logger, HostServices hostServices); } } diff --git a/src/Features/LanguageServer/Protocol/ILspServiceLogger.cs b/src/Features/LanguageServer/Protocol/ILspServiceLogger.cs deleted file mode 100644 index 79a87f31e54ed..0000000000000 --- a/src/Features/LanguageServer/Protocol/ILspServiceLogger.cs +++ /dev/null @@ -1,13 +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 Microsoft.CommonLanguageServerProtocol.Framework; - -namespace Microsoft.CodeAnalysis.LanguageServer -{ - - internal interface ILspServiceLogger : ILspLogger, ILspService - { - } -} diff --git a/src/Features/LanguageServer/Protocol/ILspServiceLoggerFactory.cs b/src/Features/LanguageServer/Protocol/ILspServiceLoggerFactory.cs index 781bb52160fee..d0e5c17865269 100644 --- a/src/Features/LanguageServer/Protocol/ILspServiceLoggerFactory.cs +++ b/src/Features/LanguageServer/Protocol/ILspServiceLoggerFactory.cs @@ -11,6 +11,6 @@ namespace Microsoft.CodeAnalysis.LanguageServer { internal interface ILspServiceLoggerFactory { - Task CreateLoggerAsync(string serverTypeName, JsonRpc jsonRpc, CancellationToken cancellationToken); + Task CreateLoggerAsync(string serverTypeName, JsonRpc jsonRpc, CancellationToken cancellationToken); } } diff --git a/src/Features/LanguageServer/Protocol/NoOpLspLogger.cs b/src/Features/LanguageServer/Protocol/NoOpLspLogger.cs index 8c7a0ebba369c..5a74a68253a8c 100644 --- a/src/Features/LanguageServer/Protocol/NoOpLspLogger.cs +++ b/src/Features/LanguageServer/Protocol/NoOpLspLogger.cs @@ -7,9 +7,9 @@ namespace Microsoft.CodeAnalysis.LanguageServer { - internal sealed class NoOpLspLogger : AbstractLspLogger, ILspServiceLogger + internal sealed class NoOpLspLogger : AbstractLspLogger, ILspService { - public static readonly ILspServiceLogger Instance = new NoOpLspLogger(); + public static readonly NoOpLspLogger Instance = new NoOpLspLogger(); private NoOpLspLogger() { } diff --git a/src/Features/LanguageServer/Protocol/RoslynLanguageServer.cs b/src/Features/LanguageServer/Protocol/RoslynLanguageServer.cs index f47cfde3ad849..dcc541071dc89 100644 --- a/src/Features/LanguageServer/Protocol/RoslynLanguageServer.cs +++ b/src/Features/LanguageServer/Protocol/RoslynLanguageServer.cs @@ -27,7 +27,7 @@ public RoslynLanguageServer( AbstractLspServiceProvider lspServiceProvider, JsonRpc jsonRpc, ICapabilitiesProvider capabilitiesProvider, - ILspServiceLogger logger, + AbstractLspLogger logger, HostServices hostServices, ImmutableArray supportedLanguages, WellKnownLspServerKinds serverKind) @@ -56,7 +56,7 @@ protected override IRequestExecutionQueue ConstructRequestExecut private ImmutableDictionary>> GetBaseServices( JsonRpc jsonRpc, - ILspServiceLogger logger, + AbstractLspLogger logger, ICapabilitiesProvider capabilitiesProvider, HostServices hostServices, WellKnownLspServerKinds serverKind, @@ -68,7 +68,7 @@ private ImmutableDictionary>> Ge AddBaseService(clientLanguageServerManager); AddBaseService(logger); - AddBaseService(logger); + AddBaseService(logger); AddBaseService(capabilitiesProvider); AddBaseService(lifeCycleManager); AddBaseService(new ServerInfoProvider(serverKind, supportedLanguages)); diff --git a/src/Features/LanguageServer/Protocol/Workspaces/LspWorkspaceManagerFactory.cs b/src/Features/LanguageServer/Protocol/Workspaces/LspWorkspaceManagerFactory.cs index e4f846521cfb9..17991a8b4b357 100644 --- a/src/Features/LanguageServer/Protocol/Workspaces/LspWorkspaceManagerFactory.cs +++ b/src/Features/LanguageServer/Protocol/Workspaces/LspWorkspaceManagerFactory.cs @@ -6,6 +6,7 @@ using System.Composition; using Microsoft.CodeAnalysis.Host.Mef; using Microsoft.CodeAnalysis.LanguageServer.Handler; +using Microsoft.CommonLanguageServerProtocol.Framework; namespace Microsoft.CodeAnalysis.LanguageServer; @@ -23,7 +24,7 @@ public LspWorkspaceManagerFactory(LspWorkspaceRegistrationService lspWorkspaceRe public ILspService CreateILspService(LspServices lspServices, WellKnownLspServerKinds serverKind) { - var logger = lspServices.GetRequiredService(); + var logger = lspServices.GetRequiredService(); var telemetryLogger = lspServices.GetRequiredService(); var miscFilesWorkspace = lspServices.GetService(); return new LspWorkspaceManager(logger, miscFilesWorkspace, _workspaceRegistrationService, telemetryLogger); diff --git a/src/VisualStudio/Core/Def/LanguageClient/LogHubLspLogger.cs b/src/VisualStudio/Core/Def/LanguageClient/LogHubLspLogger.cs index f55dd4cd995fb..a831a326f0c11 100644 --- a/src/VisualStudio/Core/Def/LanguageClient/LogHubLspLogger.cs +++ b/src/VisualStudio/Core/Def/LanguageClient/LogHubLspLogger.cs @@ -11,7 +11,7 @@ namespace Microsoft.VisualStudio.LanguageServices.Implementation.LanguageClient { - internal sealed class LogHubLspLogger : AbstractLspLogger, ILspServiceLogger + internal sealed class LogHubLspLogger : AbstractLspLogger, ILspService { private readonly TraceConfiguration _configuration; private readonly TraceSource _traceSource; diff --git a/src/VisualStudio/Core/Def/LanguageClient/VisualStudioLogHubLoggerFactory.cs b/src/VisualStudio/Core/Def/LanguageClient/VisualStudioLogHubLoggerFactory.cs index 436f195c0487f..740e7c2dfaf84 100644 --- a/src/VisualStudio/Core/Def/LanguageClient/VisualStudioLogHubLoggerFactory.cs +++ b/src/VisualStudio/Core/Def/LanguageClient/VisualStudioLogHubLoggerFactory.cs @@ -37,7 +37,7 @@ public VisualStudioLogHubLoggerFactory( _brokeredServiceContainer = brokeredServiceContainer; } - public async Task CreateLoggerAsync(string serverTypeName, JsonRpc jsonRpc, CancellationToken cancellationToken) + public async Task CreateLoggerAsync(string serverTypeName, JsonRpc jsonRpc, CancellationToken cancellationToken) { var logName = $"Roslyn.{serverTypeName}.{Interlocked.Increment(ref s_logHubSessionId)}"; var logId = new LogId(logName, new ServiceMoniker(typeof(AbstractLanguageServer<>).FullName)); From 462dad9a59a5ce3e768233c7c383a91f0e087bc5 Mon Sep 17 00:00:00 2001 From: Todd Grunke Date: Fri, 8 Dec 2023 17:30:49 -0800 Subject: [PATCH 09/10] Obsolete ILspLogger Change RequestTelemetryLogger to use TelemetryLogging apis --- .../ILspLogger.cs | 1 + .../Handler/RequestTelemetryLogger.cs | 94 +++++-------------- .../Def/Telemetry/AggregatingTelemetryLog.cs | 40 ++++++-- .../AggregatingTelemetryLogManager.cs | 6 +- .../Def/Telemetry/TelemetryLogProvider.cs | 8 ++ .../Telemetry/ITelemetryLogProvider.cs | 5 + .../Portable/Telemetry/TelemetryLogging.cs | 14 +++ 7 files changed, 87 insertions(+), 81 deletions(-) diff --git a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/ILspLogger.cs b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/ILspLogger.cs index 930ce4c6d939f..6391df1f1b253 100644 --- a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/ILspLogger.cs +++ b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/ILspLogger.cs @@ -6,6 +6,7 @@ namespace Microsoft.CommonLanguageServerProtocol.Framework; +[Obsolete("Use AbstractLspLogger instead")] public interface ILspLogger { void LogStartContext(string message, params object[] @params); diff --git a/src/Features/LanguageServer/Protocol/Handler/RequestTelemetryLogger.cs b/src/Features/LanguageServer/Protocol/Handler/RequestTelemetryLogger.cs index 1f6cd5520feb6..8a24ab46cfa87 100644 --- a/src/Features/LanguageServer/Protocol/Handler/RequestTelemetryLogger.cs +++ b/src/Features/LanguageServer/Protocol/Handler/RequestTelemetryLogger.cs @@ -4,10 +4,9 @@ using System; using System.Collections.Concurrent; -using System.Composition; using System.Threading; -using Microsoft.CodeAnalysis.Host.Mef; using Microsoft.CodeAnalysis.Internal.Log; +using Microsoft.CodeAnalysis.Telemetry; namespace Microsoft.CodeAnalysis.LanguageServer.Handler; @@ -17,25 +16,8 @@ namespace Microsoft.CodeAnalysis.LanguageServer.Handler; /// internal sealed class RequestTelemetryLogger : IDisposable, ILspService { - private const string QueuedDurationKey = "QueuedDuration"; - private readonly string _serverTypeName; - /// - /// Histogram to aggregate the time in queue metrics. - /// - private readonly HistogramLogAggregator _queuedDurationLogAggregator; - - /// - /// Histogram to aggregate total request duration metrics. - /// This histogram is log based as request latencies can be highly variable depending - /// on the request being handled. As such, we apply the log based function - /// defined by ComputeLogValue to the request latencies for storing in the histogram. - /// This provides highly detailed buckets when duration is in MS, but less detailed - /// when the duration is in terms of seconds or minutes. - /// - private readonly HistogramLogAggregator _requestDurationLogAggregator; - /// /// Store request counters in a concurrent dictionary as non-mutating LSP requests can /// run alongside other non-mutating requests. @@ -54,14 +36,6 @@ public RequestTelemetryLogger(string serverTypeName) _requestCounters = new(); _findDocumentResults = new(); _usedForkedSolutionCounter = new(); - - // Buckets queued duration into 10ms buckets with the last bucket starting at 1000ms. - // Queue times are relatively short and fall under 50ms, so tracking past 1000ms is not useful. - _queuedDurationLogAggregator = new HistogramLogAggregator(bucketSize: 10, maxBucketValue: 1000); - - // Since this is a log based histogram, these are appropriate bucket sizes for the log data. - // A bucket at 1 corresponds to ~26ms, while the max bucket value corresponds to ~17minutes - _requestDurationLogAggregator = new HistogramLogAggregator(bucketSize: 1, maxBucketValue: 40); } public void UpdateFindDocumentTelemetryData(bool success, string? workspaceKind) @@ -85,24 +59,25 @@ public void UpdateTelemetryData( TimeSpan requestDuration, Result result) { - // Find the bucket corresponding to the queued duration and update the count of durations in that bucket. - // This is not broken down per method as time in queue is not specific to an LSP method. - _queuedDurationLogAggregator.LogTime(QueuedDurationKey, queuedDuration); - // Store the request time metrics per LSP method. - _requestDurationLogAggregator.IncreaseCount(methodName, (int)ComputeLogValue(requestDuration.TotalMilliseconds)); - _requestCounters.GetOrAdd(methodName, (_) => new Counter()).IncrementCount(result); - } + TelemetryLogging.LogAggregated(FunctionId.LSP_TimeInQueue, KeyValueLogMessage.Create(m => + { + m[TelemetryLogging.KeyName] = _serverTypeName; + m[TelemetryLogging.KeyValue] = queuedDuration.Milliseconds; + m[TelemetryLogging.KeyMetricName] = "TimeInQueue"; + m["server"] = _serverTypeName; + })); - /// - /// Given an input duration in MS, this transforms it using - /// the log function below to put in reasonable log based buckets - /// from 50ms to 1 hour. Similar transformations must be done to read - /// the data from kusto. - /// - private static double ComputeLogValue(double durationInMS) - { - return 10d * Math.Log10((durationInMS / 100d) + 1); + TelemetryLogging.LogAggregated(FunctionId.LSP_RequestDuration, KeyValueLogMessage.Create(m => + { + m[TelemetryLogging.KeyName] = _serverTypeName + "." + methodName; + m[TelemetryLogging.KeyValue] = requestDuration.Milliseconds; + m[TelemetryLogging.KeyMetricName] = "RequestDuration"; + m["server"] = _serverTypeName; + m["method"] = methodName; + })); + + _requestCounters.GetOrAdd(methodName, (_) => new Counter()).IncrementCount(result); } /// @@ -116,23 +91,9 @@ public void Dispose() return; } - if (_queuedDurationLogAggregator.IsEmpty || _requestDurationLogAggregator.IsEmpty) - { - return; - } - - var queuedDurationCounter = _queuedDurationLogAggregator.GetValue(QueuedDurationKey); - Logger.Log(FunctionId.LSP_TimeInQueue, KeyValueLogMessage.Create(LogType.Trace, m => - { - m["server"] = _serverTypeName; - m["bucketsize_ms"] = queuedDurationCounter?.BucketSize; - m["maxbucketvalue_ms"] = queuedDurationCounter?.MaxBucketValue; - m["buckets"] = queuedDurationCounter?.GetBucketsAsString(); - })); - foreach (var kvp in _requestCounters) { - Logger.Log(FunctionId.LSP_RequestCounter, KeyValueLogMessage.Create(LogType.Trace, m => + TelemetryLogging.Log(FunctionId.LSP_RequestCounter, KeyValueLogMessage.Create(LogType.Trace, m => { m["server"] = _serverTypeName; m["method"] = kvp.Key; @@ -140,19 +101,9 @@ public void Dispose() m["failed"] = kvp.Value.FailedCount; m["cancelled"] = kvp.Value.CancelledCount; })); - - var requestExecutionDuration = _requestDurationLogAggregator.GetValue(kvp.Key); - Logger.Log(FunctionId.LSP_RequestDuration, KeyValueLogMessage.Create(LogType.Trace, m => - { - m["server"] = _serverTypeName; - m["method"] = kvp.Key; - m["bucketsize_logms"] = requestExecutionDuration?.BucketSize; - m["maxbucketvalue_logms"] = requestExecutionDuration?.MaxBucketValue; - m["bucketdata_logms"] = requestExecutionDuration?.GetBucketsAsString(); - })); } - Logger.Log(FunctionId.LSP_FindDocumentInWorkspace, KeyValueLogMessage.Create(LogType.Trace, m => + TelemetryLogging.Log(FunctionId.LSP_FindDocumentInWorkspace, KeyValueLogMessage.Create(LogType.Trace, m => { m["server"] = _serverTypeName; foreach (var kvp in _findDocumentResults) @@ -162,7 +113,7 @@ public void Dispose() } })); - Logger.Log(FunctionId.LSP_UsedForkedSolution, KeyValueLogMessage.Create(LogType.Trace, m => + TelemetryLogging.Log(FunctionId.LSP_UsedForkedSolution, KeyValueLogMessage.Create(LogType.Trace, m => { m["server"] = _serverTypeName; foreach (var kvp in _usedForkedSolutionCounter) @@ -172,6 +123,9 @@ public void Dispose() } })); + // Flush all telemetry logged through TelemetryLogging + TelemetryLogging.Flush(); + _requestCounters.Clear(); } diff --git a/src/VisualStudio/Core/Def/Telemetry/AggregatingTelemetryLog.cs b/src/VisualStudio/Core/Def/Telemetry/AggregatingTelemetryLog.cs index a5f452e1b5469..2f6b02b76d8c3 100644 --- a/src/VisualStudio/Core/Def/Telemetry/AggregatingTelemetryLog.cs +++ b/src/VisualStudio/Core/Def/Telemetry/AggregatingTelemetryLog.cs @@ -27,9 +27,10 @@ internal sealed class AggregatingTelemetryLog : ITelemetryLog private readonly TelemetrySession _session; private readonly HistogramConfiguration? _histogramConfiguration; private readonly string _eventName; + private readonly FunctionId _functionId; private readonly AggregatingTelemetryLogManager _aggregatingTelemetryLogManager; - private ImmutableDictionary> _histograms = ImmutableDictionary>.Empty; + private ImmutableDictionary Histogram, TelemetryEvent TelemetryEvent)> _histograms = ImmutableDictionary, TelemetryEvent)>.Empty; /// /// Creates a new aggregating telemetry log @@ -46,6 +47,7 @@ public AggregatingTelemetryLog(TelemetrySession session, FunctionId functionId, _session = session; _meter = meterProvider.CreateMeter(meterName, version: MeterVersion); _eventName = TelemetryLogger.GetEventName(functionId); + _functionId = functionId; _aggregatingTelemetryLogManager = aggregatingTelemetryLogManager; if (bucketBoundaries != null) @@ -64,13 +66,36 @@ public void Log(KeyValueLogMessage logMessage) if (!IsEnabled) return; - if (!logMessage.Properties.TryGetValue(TelemetryLogging.KeyName, out var nameValue) || nameValue is not string metricName) + // Name is the key for this message in our histogram 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(); if (!logMessage.Properties.TryGetValue(TelemetryLogging.KeyValue, out var valueValue) || valueValue is not int value) throw ExceptionUtilities.Unreachable(); - var histogram = ImmutableInterlocked.GetOrAdd(ref _histograms, metricName, metricName => _meter.CreateHistogram(metricName, _histogramConfiguration)); + (var histogram, _) = ImmutableInterlocked.GetOrAdd(ref _histograms, name, name => + { + var telemetryEvent = new TelemetryEvent(_eventName); + + // For aggregated telemetry, the first Log request that comes in for a particular name determines the additional + // properties added for the telemetry event. + if (!logMessage.Properties.TryGetValue(TelemetryLogging.KeyMetricName, out var metricNameValue) || metricNameValue is not string metricName) + metricName = name; + + foreach (var (curName, curValue) in logMessage.Properties) + { + if (curName is not TelemetryLogging.KeyName and not TelemetryLogging.KeyValue and not TelemetryLogging.KeyMetricName) + { + var propertyName = TelemetryLogger.GetPropertyName(_functionId, curName); + telemetryEvent.Properties.Add(propertyName, curValue); + } + } + + var histogram = _meter.CreateHistogram(metricName, _histogramConfiguration); + + return (histogram, telemetryEvent); + }); histogram.Record(value); @@ -90,17 +115,16 @@ public void Log(KeyValueLogMessage logMessage) private bool IsEnabled => _session.IsOptedIn; - public void PostTelemetry(TelemetrySession session) + public void Flush() { - foreach (var histogram in _histograms.Values) + foreach (var (histogram, telemetryEvent) in _histograms.Values) { - var telemetryEvent = new TelemetryEvent(_eventName); var histogramEvent = new TelemetryHistogramEvent(telemetryEvent, histogram); - session.PostMetricEvent(histogramEvent); + _session.PostMetricEvent(histogramEvent); } - _histograms = ImmutableDictionary>.Empty; + _histograms = ImmutableDictionary, TelemetryEvent)>.Empty; } } } diff --git a/src/VisualStudio/Core/Def/Telemetry/AggregatingTelemetryLogManager.cs b/src/VisualStudio/Core/Def/Telemetry/AggregatingTelemetryLogManager.cs index 9a2c8d2d858a9..9f3bae01b8181 100644 --- a/src/VisualStudio/Core/Def/Telemetry/AggregatingTelemetryLogManager.cs +++ b/src/VisualStudio/Core/Def/Telemetry/AggregatingTelemetryLogManager.cs @@ -55,19 +55,19 @@ private ValueTask PostCollectedTelemetryAsync(CancellationToken token) { token.ThrowIfCancellationRequested(); - PostCollectedTelemetry(); + Flush(); return ValueTaskFactory.CompletedTask; } - private void PostCollectedTelemetry() + public void Flush() { if (!_session.IsOptedIn) return; foreach (var log in _aggregatingLogs.Values) { - log.PostTelemetry(_session); + log.Flush(); } } } diff --git a/src/VisualStudio/Core/Def/Telemetry/TelemetryLogProvider.cs b/src/VisualStudio/Core/Def/Telemetry/TelemetryLogProvider.cs index aa82b492ae938..15e1437e1e88a 100644 --- a/src/VisualStudio/Core/Def/Telemetry/TelemetryLogProvider.cs +++ b/src/VisualStudio/Core/Def/Telemetry/TelemetryLogProvider.cs @@ -47,5 +47,13 @@ public static TelemetryLogProvider Create(TelemetrySession session, ILogger tele { return _aggregatingTelemetryLogManager.GetLog(functionId, bucketBoundaries); } + + /// + /// Flushes all telemetry logs + /// + public void Flush() + { + _aggregatingTelemetryLogManager.Flush(); + } } } diff --git a/src/Workspaces/Core/Portable/Telemetry/ITelemetryLogProvider.cs b/src/Workspaces/Core/Portable/Telemetry/ITelemetryLogProvider.cs index eb84d9917571b..b767a0a1de63e 100644 --- a/src/Workspaces/Core/Portable/Telemetry/ITelemetryLogProvider.cs +++ b/src/Workspaces/Core/Portable/Telemetry/ITelemetryLogProvider.cs @@ -21,5 +21,10 @@ internal interface ITelemetryLogProvider /// 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); + + /// + /// Flushes all telemetry logs + /// + public void Flush(); } } diff --git a/src/Workspaces/Core/Portable/Telemetry/TelemetryLogging.cs b/src/Workspaces/Core/Portable/Telemetry/TelemetryLogging.cs index ea72dc657bdf5..629375c4f0643 100644 --- a/src/Workspaces/Core/Portable/Telemetry/TelemetryLogging.cs +++ b/src/Workspaces/Core/Portable/Telemetry/TelemetryLogging.cs @@ -18,6 +18,7 @@ internal static class TelemetryLogging public const string KeyName = "Name"; public const string KeyValue = "Value"; public const string KeyLanguageName = "LanguageName"; + public const string KeyMetricName = "MetricName>"; public static void SetLogProvider(ITelemetryLogProvider logProvider) { @@ -62,6 +63,14 @@ public static void LogAggregated(FunctionId functionId, TelemetryLoggingInterpol aggregatingLog.Log(logMessage); } + public static void LogAggregated(FunctionId functionId, KeyValueLogMessage logMessage) + { + if (GetAggregatingLog(functionId) is not { } aggregatingLog) + return; + + aggregatingLog.Log(logMessage); + } + /// /// Adds block execution time to an aggregated telemetry event representing the operation /// with metric only if the block duration meets or exceeds milliseconds. @@ -95,5 +104,10 @@ public static void LogAggregated(FunctionId functionId, TelemetryLoggingInterpol { return s_logProvider?.GetAggregatingLog(functionId, bucketBoundaries); } + + public static void Flush() + { + s_logProvider?.Flush(); + } } } From 146e88ba00a302ea36ae1f7365e09cb406b1bf30 Mon Sep 17 00:00:00 2001 From: Todd Grunke Date: Fri, 8 Dec 2023 19:35:58 -0800 Subject: [PATCH 10/10] remove the Obsolete attribute on ILspLogger. Too viral for now. --- .../ILspLogger.cs | 1 - 1 file changed, 1 deletion(-) diff --git a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/ILspLogger.cs b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/ILspLogger.cs index 6391df1f1b253..930ce4c6d939f 100644 --- a/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/ILspLogger.cs +++ b/src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/ILspLogger.cs @@ -6,7 +6,6 @@ namespace Microsoft.CommonLanguageServerProtocol.Framework; -[Obsolete("Use AbstractLspLogger instead")] public interface ILspLogger { void LogStartContext(string message, params object[] @params);