Skip to content

Commit

Permalink
Add LSP funnel telemetry to help indicate when drop offs occur
Browse files Browse the repository at this point in the history
  • Loading branch information
dibarbet committed Oct 5, 2024
1 parent 1e8e45c commit a4ea1df
Show file tree
Hide file tree
Showing 7 changed files with 106 additions and 65 deletions.
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,7 @@
using Microsoft.CodeAnalysis.LanguageServer.BrokeredServices.Services;
using Microsoft.CodeAnalysis.LanguageServer.BrokeredServices.Services.Definitions;
using Microsoft.CodeAnalysis.LanguageServer.LanguageServer;
using Microsoft.CodeAnalysis.LanguageServer.Telemetry;
using Microsoft.Extensions.Logging;
using Microsoft.ServiceHub.Framework;
using Roslyn.Utilities;
Expand Down Expand Up @@ -111,6 +112,7 @@ public void OnError(Exception error)
public void OnNext(ProjectInitializationCompletionState value)
{
_logger.LogDebug("Devkit project initialization completed");
VSCodeRequestTelemetryLogger.ReportProjectInitializationComplete();
_ = SendProjectInitializationCompleteNotificationAsync().ReportNonFatalErrorAsync();
}
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,7 @@
using System.Collections.Immutable;
using System.ComponentModel.Composition;
using Microsoft.CodeAnalysis.Host.Mef;
using Microsoft.CodeAnalysis.LanguageServer.Telemetry;
using Microsoft.CodeAnalysis.Remote.ProjectSystem;
using Microsoft.Extensions.Logging;
using Microsoft.ServiceHub.Framework;
Expand Down Expand Up @@ -44,7 +45,7 @@ async Task IExportedBrokeredService.InitializeAsync(CancellationToken cancellati
public async Task<IWorkspaceProject> CreateAndAddProjectAsync(WorkspaceProjectCreationInfo creationInfo, CancellationToken _)
{
_logger.LogInformation(string.Format(LanguageServerResources.Project_0_loaded_by_CSharp_Dev_Kit, creationInfo.FilePath));

VSCodeRequestTelemetryLogger.ReportProjectLoadStarted();
try
{
if (creationInfo.BuildSystemProperties.TryGetValue("SolutionPath", out var solutionPath))
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -21,6 +21,7 @@
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Console;
using Roslyn.Utilities;
using RoslynLog = Microsoft.CodeAnalysis.Internal.Log;

// Setting the title can fail if the process is run without a window, such
// as when launched detached from nodejs
Expand Down Expand Up @@ -137,6 +138,7 @@ static async Task RunAsync(ServerConfiguration serverConfiguration, Cancellation
server.Start();

logger.LogInformation("Language server initialized");
RoslynLog.Logger.Log(RoslynLog.FunctionId.VSCode_LanguageServer_Started, logLevel: RoslynLog.LogLevel.Information);

try
{
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -2,61 +2,72 @@
// The .NET Foundation licenses this file to you under the MIT license.
// See the LICENSE file in the project root for more information.

using System;
using System.Collections.Concurrent;
using System.Collections.Generic;
using System.Composition;
using System.Linq;
using System.Text;
using System.Threading.Tasks;
using Microsoft.CodeAnalysis.Host.Mef;
using Microsoft.CodeAnalysis.Internal.Log;
using Microsoft.CodeAnalysis.LanguageServer.Handler;
using Microsoft.CodeAnalysis.Telemetry;

//namespace Microsoft.CodeAnalysis.LanguageServer.Telemetry;

//internal class VSCodeRequestTelemetryLogger : RequestTelemetryLogger
//{
// /// <summary>
// /// Tracks whether or not the initial project load has completed so we can see
// /// how often we get misc file requests after we've loaded.
// /// </summary>
// private static bool _initialProjectLoadCompleted = false;

// private readonly ConcurrentDictionary<bool, ConcurrentDictionary<string, Counter>> _findDocumentCounters;

// public VSCodeRequestTelemetryLogger(string serverTypeName) : base(serverTypeName)
// {
// }

// public static void ReportProjectInitializationComplete()
// {
// _initialProjectLoadCompleted = true;
// Logger.Log(FunctionId.VSCode_Projects_Load_Completed, logLevel: LogLevel.Information);
// }

// public static void ReportProjectLoadStarted()
// {
// Logger.Log(FunctionId.VSCode_Project_Load_Started, logLevel: LogLevel.Information);
// }

// protected override void IncreaseFindDocumentCount(string workspaceInfo)
// {
// TelemetryLogging.LogAggregated(FunctionId.LSP_FindDocumentInWorkspace, KeyValueLogMessage.Create(m =>
// {
// m[TelemetryLogging.KeyName] = _serverTypeName;
// m[TelemetryLogging.KeyValue] = (int)queuedDuration.TotalMilliseconds;
// m[TelemetryLogging.KeyMetricName] = "Count";
// m["server"] = _serverTypeName;
// m["method"] = methodName;
// m["language"] = language;
// }));

// base.IncreaseFindDocumentCount(workspaceInfo);
// }

// protected override void ReportFindDocumentCounter()
// {
// base.ReportFindDocumentCounter();
// }
//}
namespace Microsoft.CodeAnalysis.LanguageServer.Telemetry;

[ExportCSharpVisualBasicStatelessLspService(typeof(RequestTelemetryLogger), serverKind: WellKnownLspServerKinds.CSharpVisualBasicLspServer), Shared]
[method: ImportingConstructor]
[method: Obsolete(MefConstruction.ImportingConstructorMessage, error: true)]
internal class VSCodeRequestTelemetryLogger() : RequestTelemetryLogger(WellKnownLspServerKinds.CSharpVisualBasicLspServer.ToTelemetryString())
{
/// <summary>
/// Tracks whether or not the initial project load has completed.
/// </summary>
private static bool s_initialProjectLoadCompleted = false;

/// <summary>
/// Store which workspace a document came from for each request. This is tracked separately before and after initial project load:
/// 1. Before initial load, almost all requests should resolve to the misc files workspace.
/// 2. After initial load, almost all requests should resolve to the host workspace.
/// A large amount of misc files requests in 2 could indicate either a bug or feature improvements in order to load what the user is expecting.
/// </summary>
private readonly ConcurrentDictionary<bool, CountLogAggregator<string>> _findDocumentCounters = new()
{
[true] = new(),
[false] = new(),
};

public static void ReportProjectInitializationComplete()
{
s_initialProjectLoadCompleted = true;
Logger.Log(FunctionId.VSCode_Projects_Load_Completed, logLevel: LogLevel.Information);
}

public static void ReportProjectLoadStarted()
{
Logger.Log(FunctionId.VSCode_Project_Load_Started, logLevel: LogLevel.Information);
}

protected override void IncreaseFindDocumentCount(string workspaceInfo)
{
_findDocumentCounters.GetOrAdd(s_initialProjectLoadCompleted, (_) => new CountLogAggregator<string>()).IncreaseCount(workspaceInfo);
}

protected override void ReportFindDocumentCounter()
{
foreach (var (isInitialLoadComplete, counter) in _findDocumentCounters)
{
if (!counter.IsEmpty)
{
TelemetryLogging.Log(FunctionId.LSP_FindDocumentInWorkspace, KeyValueLogMessage.Create(LogType.Trace, m =>
{
m["server"] = ServerTypeName;
m["projectsLoaded"] = isInitialLoadComplete;
foreach (var kvp in counter)
{
var info = kvp.Key.ToString()!;
m[info] = kvp.Value.GetCount();
}
}));
}
}
_findDocumentCounters.Clear();
}

}
Original file line number Diff line number Diff line change
@@ -0,0 +1,24 @@
// Licensed to the .NET Foundation under one or more agreements.
// The .NET Foundation licenses this file to you under the MIT license.
// See the LICENSE file in the project root for more information.

using System;
using System.Composition;
using Microsoft.CodeAnalysis.Host.Mef;

namespace Microsoft.CodeAnalysis.LanguageServer.Handler;

[ExportCSharpVisualBasicLspServiceFactory(typeof(RequestTelemetryLogger)), Shared]
internal sealed class RequestTelemetryLoggerFactory : ILspServiceFactory
{
[ImportingConstructor]
[Obsolete(MefConstruction.ImportingConstructorMessage, error: true)]
public RequestTelemetryLoggerFactory()
{
}

public ILspService CreateILspService(LspServices lspServices, WellKnownLspServerKinds serverKind)
{
return new RequestTelemetryLogger(serverKind.ToTelemetryString());
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -16,7 +16,7 @@ namespace Microsoft.CodeAnalysis.LanguageServer.Handler;
/// </summary>
internal class RequestTelemetryLogger : IDisposable, ILspService
{
private readonly string _serverTypeName;
protected readonly string ServerTypeName;

/// <summary>
/// Store request counters in a concurrent dictionary as non-mutating LSP requests can
Expand All @@ -32,7 +32,7 @@ internal class RequestTelemetryLogger : IDisposable, ILspService

public RequestTelemetryLogger(string serverTypeName)
{
_serverTypeName = serverTypeName;
ServerTypeName = serverTypeName;
_requestCounters = new();
_findDocumentResults = new();
_usedForkedSolutionCounter = new();
Expand Down Expand Up @@ -70,20 +70,20 @@ public void UpdateTelemetryData(
// Store the request time metrics per LSP method.
TelemetryLogging.LogAggregated(FunctionId.LSP_TimeInQueue, KeyValueLogMessage.Create(m =>
{
m[TelemetryLogging.KeyName] = _serverTypeName;
m[TelemetryLogging.KeyName] = ServerTypeName;
m[TelemetryLogging.KeyValue] = (int)queuedDuration.TotalMilliseconds;
m[TelemetryLogging.KeyMetricName] = "TimeInQueue";
m["server"] = _serverTypeName;
m["server"] = ServerTypeName;
m["method"] = methodName;
m["language"] = language;
}));

TelemetryLogging.LogAggregated(FunctionId.LSP_RequestDuration, KeyValueLogMessage.Create(m =>
{
m[TelemetryLogging.KeyName] = _serverTypeName + "." + methodName;
m[TelemetryLogging.KeyName] = ServerTypeName + "." + methodName;
m[TelemetryLogging.KeyValue] = (int)requestDuration.TotalMilliseconds;
m[TelemetryLogging.KeyMetricName] = "RequestDuration";
m["server"] = _serverTypeName;
m["server"] = ServerTypeName;
m["method"] = methodName;
m["language"] = language;
}));
Expand Down Expand Up @@ -114,7 +114,7 @@ protected virtual void ReportFindDocumentCounter()
{
TelemetryLogging.Log(FunctionId.LSP_FindDocumentInWorkspace, KeyValueLogMessage.Create(LogType.Trace, m =>
{
m["server"] = _serverTypeName;
m["server"] = ServerTypeName;
foreach (var kvp in _findDocumentResults)
{
var info = kvp.Key.ToString()!;
Expand All @@ -130,7 +130,7 @@ private void OnFlushed(object? sender, EventArgs e)
{
TelemetryLogging.Log(FunctionId.LSP_RequestCounter, KeyValueLogMessage.Create(LogType.Trace, m =>
{
m["server"] = _serverTypeName;
m["server"] = ServerTypeName;
m["method"] = kvp.Key.Method;
m["language"] = kvp.Key.Language;
m["successful"] = kvp.Value.SucceededCount;
Expand All @@ -145,7 +145,7 @@ private void OnFlushed(object? sender, EventArgs e)
{
TelemetryLogging.Log(FunctionId.LSP_UsedForkedSolution, KeyValueLogMessage.Create(LogType.Trace, m =>
{
m["server"] = _serverTypeName;
m["server"] = ServerTypeName;
foreach (var kvp in _usedForkedSolutionCounter)
{
var info = kvp.Key.ToString()!;
Expand All @@ -159,7 +159,7 @@ private void OnFlushed(object? sender, EventArgs e)
_usedForkedSolutionCounter.Clear();
}

protected class Counter
private class Counter
{
private int _succeededCount;
private int _failedCount;
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -636,6 +636,7 @@ internal enum FunctionId
Copilot_On_The_Fly_Docs_Content_Excluded = 816,
Copilot_Rename = 851,

VSCode_Project_Load_Started = 860,
VSCode_Projects_Load_Completed = 861,
VSCode_LanguageServer_Started = 860,
VSCode_Project_Load_Started = 861,
VSCode_Projects_Load_Completed = 862,
}

0 comments on commit a4ea1df

Please sign in to comment.