Report LSP loading telemetry

src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/HostWorkspace/ProjectInitializationHandler.cs

@@ -8,6 +8,7 @@
 using Microsoft.CodeAnalysis.LanguageServer.BrokeredServices.Services;
 using Microsoft.CodeAnalysis.LanguageServer.BrokeredServices.Services.Definitions;
 using Microsoft.CodeAnalysis.LanguageServer.LanguageServer;
+using Microsoft.CodeAnalysis.LanguageServer.Telemetry;
 using Microsoft.Extensions.Logging;
 using Microsoft.ServiceHub.Framework;
 using Roslyn.Utilities;
@@ -111,6 +112,7 @@ public void OnError(Exception error)
         public void OnNext(ProjectInitializationCompletionState value)
         {
             _logger.LogDebug("Devkit project initialization completed");
+            VSCodeRequestTelemetryLogger.ReportProjectInitializationComplete();
             _ = SendProjectInitializationCompleteNotificationAsync().ReportNonFatalErrorAsync();
         }
     }

src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/HostWorkspace/WorkspaceProjectFactoryService.cs

@@ -5,6 +5,7 @@
 using System.Collections.Immutable;
 using System.ComponentModel.Composition;
 using Microsoft.CodeAnalysis.Host.Mef;
+using Microsoft.CodeAnalysis.LanguageServer.Telemetry;
 using Microsoft.CodeAnalysis.Remote.ProjectSystem;
 using Microsoft.Extensions.Logging;
 using Microsoft.ServiceHub.Framework;
@@ -44,7 +45,7 @@ async Task IExportedBrokeredService.InitializeAsync(CancellationToken cancellati
     public async Task<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))

src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Program.cs

@@ -21,6 +21,7 @@
 using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Logging.Console;
 using Roslyn.Utilities;
+using RoslynLog = Microsoft.CodeAnalysis.Internal.Log;
 
 // Setting the title can fail if the process is run without a window, such
 // as when launched detached from nodejs
@@ -137,6 +138,7 @@ static async Task RunAsync(ServerConfiguration serverConfiguration, Cancellation
     server.Start();
 
     logger.LogInformation("Language server initialized");
+    RoslynLog.Logger.Log(RoslynLog.FunctionId.VSCode_LanguageServer_Started, logLevel: RoslynLog.LogLevel.Information);
 
     try
     {

src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Telemetry/VSCodeRequestTelemetryLogger.cs

@@ -0,0 +1,73 @@
+// Licensed to the .NET Foundation under one or more agreements.
+// The .NET Foundation licenses this file to you under the MIT license.
+// See the LICENSE file in the project root for more information.
+
+using System.Collections.Concurrent;
+using System.Composition;
+using Microsoft.CodeAnalysis.Host.Mef;
+using Microsoft.CodeAnalysis.Internal.Log;
+using Microsoft.CodeAnalysis.LanguageServer.Handler;
+using Microsoft.CodeAnalysis.Telemetry;
+
+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();
+    }
+
+}

src/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Telemetry/VSCodeRequestTelemetryLoggerFactory.cs

@@ -0,0 +1,24 @@
+// Licensed to the .NET Foundation under one or more agreements.
+// The .NET Foundation licenses this file to you under the MIT license.
+// See the LICENSE file in the project root for more information.
+
+using System;
+using System.Composition;
+using Microsoft.CodeAnalysis.Host.Mef;
+
+namespace Microsoft.CodeAnalysis.LanguageServer.Handler;
+
+[ExportCSharpVisualBasicLspServiceFactory(typeof(RequestTelemetryLogger)), Shared]
+internal sealed class RequestTelemetryLoggerFactory : ILspServiceFactory
+{
+    [ImportingConstructor]
+    [Obsolete(MefConstruction.ImportingConstructorMessage, error: true)]
+    public RequestTelemetryLoggerFactory()
+    {
+    }
+
+    public ILspService CreateILspService(LspServices lspServices, WellKnownLspServerKinds serverKind)
+    {
+        return new RequestTelemetryLogger(serverKind.ToTelemetryString());
+    }
+}

src/LanguageServer/Protocol/Handler/RequestTelemetryLogger.cs → src/LanguageServer/Protocol/Handler/Telemetry/RequestTelemetryLogger.cs

@@ -14,9 +14,9 @@ namespace Microsoft.CodeAnalysis.LanguageServer.Handler;
 /// Logs metadata on LSP requests (duration, success / failure metrics)
 /// for this particular LSP server instance.
 /// </summary>
-internal sealed class RequestTelemetryLogger : IDisposable, ILspService
+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
@@ -32,7 +32,7 @@ internal sealed class RequestTelemetryLogger : IDisposable, ILspService
 
     public RequestTelemetryLogger(string serverTypeName)
     {
-        _serverTypeName = serverTypeName;
+        ServerTypeName = serverTypeName;
         _requestCounters = new();
         _findDocumentResults = new();
         _usedForkedSolutionCounter = new();
@@ -46,10 +46,15 @@ public void UpdateFindDocumentTelemetryData(bool success, string? workspaceKind)
 
         if (workspaceKindTelemetryProperty != null)
         {
-            _findDocumentResults.IncreaseCount(workspaceKindTelemetryProperty);
+            IncreaseFindDocumentCount(workspaceKindTelemetryProperty);
         }
     }
 
+    protected virtual void IncreaseFindDocumentCount(string workspaceInfo)
+    {
+        _findDocumentResults.IncreaseCount(workspaceInfo);
+    }
+
     public void UpdateUsedForkedSolutionCounter(bool usedForkedSolution)
     {
         _usedForkedSolutionCounter.IncreaseCount(usedForkedSolution);
@@ -65,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;
         }));
@@ -103,13 +108,29 @@ public void Dispose()
         TelemetryLogging.Flushed -= OnFlushed;
     }
 
+    protected virtual void ReportFindDocumentCounter()
+    {
+        if (!_findDocumentResults.IsEmpty)
+        {
+            TelemetryLogging.Log(FunctionId.LSP_FindDocumentInWorkspace, KeyValueLogMessage.Create(LogType.Trace, m =>
+            {
+                m["server"] = ServerTypeName;
+                foreach (var kvp in _findDocumentResults)
+                {
+                    var info = kvp.Key.ToString()!;
+                    m[info] = kvp.Value.GetCount();
+                }
+            }));
+        }
+    }
+
     private void OnFlushed(object? sender, EventArgs e)
     {
         foreach (var kvp in _requestCounters)
         {
             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;
@@ -118,24 +139,13 @@ private void OnFlushed(object? sender, EventArgs e)
             }));
         }
 
-        if (!_findDocumentResults.IsEmpty)
-        {
-            TelemetryLogging.Log(FunctionId.LSP_FindDocumentInWorkspace, KeyValueLogMessage.Create(LogType.Trace, m =>
-            {
-                m["server"] = _serverTypeName;
-                foreach (var kvp in _findDocumentResults)
-                {
-                    var info = kvp.Key.ToString()!;
-                    m[info] = kvp.Value.GetCount();
-                }
-            }));
-        }
+        ReportFindDocumentCounter();
 
         if (!_usedForkedSolutionCounter.IsEmpty)
         {
             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()!;

src/LanguageServer/Protocol/LspServices/LspServices.cs

@@ -7,6 +7,7 @@
 using System.Collections.Generic;
 using System.Collections.Immutable;
 using System.Diagnostics.CodeAnalysis;
+using System.Linq;
 using Microsoft.CodeAnalysis.ErrorReporting;
 using Microsoft.CodeAnalysis.PooledObjects;
 using Microsoft.CommonLanguageServerProtocol.Framework;
@@ -40,36 +41,48 @@ public LspServices(
     {
         var serviceMap = new Dictionary<string, Lazy<ILspService, LspServiceMetadataView>>();
 
-        // Convert MEF exported service factories to the lazy LSP services that they create.
-        foreach (var lazyServiceFactory in mefLspServiceFactories)
-        {
-            var metadata = lazyServiceFactory.Metadata;
+        // Add services from factories exported for this server kind.
+        foreach (var lazyServiceFactory in mefLspServiceFactories.Where(f => f.Metadata.ServerKind == serverKind))
+            AddSpecificService(new(() => lazyServiceFactory.Value.CreateILspService(this, serverKind), lazyServiceFactory.Metadata));
 
-            // Make sure that we only include services exported for the specified server kind (or NotSpecified).
-            if (metadata.ServerKind == serverKind ||
-                metadata.ServerKind == WellKnownLspServerKinds.Any)
-            {
-                serviceMap.Add(
-                    metadata.TypeRef.TypeName,
-                    new(() => lazyServiceFactory.Value.CreateILspService(this, serverKind), metadata));
-            }
-        }
+        // Add services exported for this server kind.
+        foreach (var lazyService in mefLspServices.Where(s => s.Metadata.ServerKind == serverKind))
+            AddSpecificService(lazyService);
 
-        foreach (var lazyService in mefLspServices)
-        {
-            var metadata = lazyService.Metadata;
+        // Add services from factories exported for any (if there is not already an existing service for the specific server kind).
+        foreach (var lazyServiceFactory in mefLspServiceFactories.Where(f => f.Metadata.ServerKind == WellKnownLspServerKinds.Any))
+            TryAddAnyService(new(() => lazyServiceFactory.Value.CreateILspService(this, serverKind), lazyServiceFactory.Metadata));
 
-            // Make sure that we only include services exported for the specified server kind (or NotSpecified).
-            if (metadata.ServerKind == serverKind ||
-                metadata.ServerKind == WellKnownLspServerKinds.Any)
-            {
-                serviceMap.Add(metadata.TypeRef.TypeName, lazyService);
-            }
-        }
+        // Add services exported for any (if there is not already an existing service for the specific server kind).
+        foreach (var lazyService in mefLspServices.Where(s => s.Metadata.ServerKind == WellKnownLspServerKinds.Any))
+            TryAddAnyService(lazyService);
 
         _lazyMefLspServices = serviceMap.ToFrozenDictionary();
 
         _baseServices = baseServices;
+
+        void AddSpecificService(Lazy<ILspService, LspServiceMetadataView> serviceGetter)
+        {
+            var metadata = serviceGetter.Metadata;
+            Contract.ThrowIfFalse(metadata.ServerKind == serverKind);
+            serviceMap.Add(metadata.TypeRef.TypeName, serviceGetter);
+        }
+
+        void TryAddAnyService(Lazy<ILspService, LspServiceMetadataView> serviceGetter)
+        {
+            var metadata = serviceGetter.Metadata;
+            Contract.ThrowIfFalse(metadata.ServerKind == WellKnownLspServerKinds.Any);
+            if (!serviceMap.TryGetValue(metadata.TypeRef.TypeName, out var existing))
+            {
+                serviceMap.Add(metadata.TypeRef.TypeName, serviceGetter);
+            }
+            else
+            {
+                // Make sure we're not trying to add a duplicate Any service, but otherwise we should skip adding
+                // this service as we already have a more specific service available.
+                Contract.ThrowIfTrue(existing.Metadata.ServerKind == WellKnownLspServerKinds.Any);
+            }
+        }
     }
 
     public T GetRequiredService<T>() where T : notnull