From a5aec7618e264ccd8e9f480eec8279ff7e2f26fb Mon Sep 17 00:00:00 2001 From: Jason Malinowski Date: Tue, 26 Jul 2022 16:45:33 -0700 Subject: [PATCH] Add telemetry for the time and files outputted for source generators This adds telemetry for the overall time being spent running generators during a single solution session, and whether individual generators on average actually outputted files or not. This can help us generally understand the execution cost of generators in the wild, as well as how many solutions have generators but aren't actually getting outputs from them. --- src/VisualStudio/Core/Def/RoslynPackage.cs | 3 +- ...lemetryCollectorWorkspaceServiceFactory.cs | 105 ++++++++++++++++++ .../Portable/Log/AbstractLogAggregator.cs | 2 + ...ratorTelemetryCollectorWorkspaceService.cs | 16 +++ ...ratorTelemetryCollectorWorkspaceService.cs | 73 ++++++++++++ .../SolutionState.CompilationTracker.cs | 4 + .../Compiler/Core/Log/FunctionId.cs | 3 + 7 files changed, 205 insertions(+), 1 deletion(-) create mode 100644 src/VisualStudio/Core/Def/Workspace/VisualStudioSourceGeneratorTelemetryCollectorWorkspaceServiceFactory.cs create mode 100644 src/Workspaces/Core/Portable/SourceGeneratorTelemetry/ISourceGeneratorTelemetryCollectorWorkspaceService.cs create mode 100644 src/Workspaces/Core/Portable/SourceGeneratorTelemetry/SourceGeneratorTelemetryCollectorWorkspaceService.cs diff --git a/src/VisualStudio/Core/Def/RoslynPackage.cs b/src/VisualStudio/Core/Def/RoslynPackage.cs index 6570a9c91c06e..f38e2be545830 100644 --- a/src/VisualStudio/Core/Def/RoslynPackage.cs +++ b/src/VisualStudio/Core/Def/RoslynPackage.cs @@ -311,13 +311,14 @@ protected override void Dispose(bool disposing) base.Dispose(disposing); } - private static void ReportSessionWideTelemetry() + private void ReportSessionWideTelemetry() { SolutionLogger.ReportTelemetry(); AsyncCompletionLogger.ReportTelemetry(); CompletionProvidersLogger.ReportTelemetry(); ChangeSignatureLogger.ReportTelemetry(); InheritanceMarginLogger.ReportTelemetry(); + ComponentModel.GetService().ReportOtherWorkspaceTelemetry(); } private void DisposeVisualStudioServices() diff --git a/src/VisualStudio/Core/Def/Workspace/VisualStudioSourceGeneratorTelemetryCollectorWorkspaceServiceFactory.cs b/src/VisualStudio/Core/Def/Workspace/VisualStudioSourceGeneratorTelemetryCollectorWorkspaceServiceFactory.cs new file mode 100644 index 0000000000000..ca1392f3ed739 --- /dev/null +++ b/src/VisualStudio/Core/Def/Workspace/VisualStudioSourceGeneratorTelemetryCollectorWorkspaceServiceFactory.cs @@ -0,0 +1,105 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +using System; +using System.Composition; +using System.Threading; +using System.Threading.Tasks; +using Microsoft.CodeAnalysis.Editor.Shared.Utilities; +using Microsoft.CodeAnalysis.Host; +using Microsoft.CodeAnalysis.Host.Mef; +using Microsoft.CodeAnalysis.Internal.Log; +using Microsoft.CodeAnalysis.SourceGeneratorTelemetry; +using Microsoft.VisualStudio.Shell; +using Microsoft.VisualStudio.Shell.Interop; + +namespace Microsoft.VisualStudio.LanguageServices +{ + /// + /// Exports a which is watched across all workspaces. This lets us collect + /// statistics for all workspaces (including things like interactive, preview, etc.) so we can get the overall counts to report. + /// + [Export] + [ExportWorkspaceServiceFactory(typeof(ISourceGeneratorTelemetryCollectorWorkspaceService)), Shared] + internal class VisualStudioSourceGeneratorTelemetryCollectorWorkspaceServiceFactory : IWorkspaceServiceFactory, IVsSolutionEvents + { + /// + /// The collector that's used to collect all the telemetry for operations within . We'll report this + /// when the solution is closed, so the telemetry is linked to that. + /// + private readonly SourceGeneratorTelemetryCollectorWorkspaceService _visualStudioWorkspaceInstance = new SourceGeneratorTelemetryCollectorWorkspaceService(); + + /// + /// The collector used to collect telemetry for any other workspaces that might be created; we'll report this at the end of the session since nothing here is necessarily + /// linked to a specific solution. The expectation is this may be empty for many/most sessions, but we don't want a hole in our reporting and discover that the hard way. + /// + private readonly SourceGeneratorTelemetryCollectorWorkspaceService _otherWorkspacesInstance = new SourceGeneratorTelemetryCollectorWorkspaceService(); + + private readonly IThreadingContext _threadingContext; + private readonly IAsyncServiceProvider _serviceProvider; + private volatile int _subscribedToSolutionEvents; + + [ImportingConstructor] + [Obsolete(MefConstruction.ImportingConstructorMessage, error: true)] + public VisualStudioSourceGeneratorTelemetryCollectorWorkspaceServiceFactory(IThreadingContext threadingContext, SVsServiceProvider serviceProvider) + { + _threadingContext = threadingContext; + _serviceProvider = (IAsyncServiceProvider)serviceProvider; + } + + public IWorkspaceService CreateService(HostWorkspaceServices workspaceServices) + { + // We will record all generators for the main workspace in one bucket, and any other generators running in other + // workspaces (interactive, for example) will be put in a different bucket. This allows us to report the telemetry + // from the primary workspace on solution closed, while not letting the unrelated runs pollute those numbers. + if (workspaceServices.Workspace is VisualStudioWorkspace) + { + EnsureSubscribedToSolutionEvents(); + return _visualStudioWorkspaceInstance; + } + else + { + return _otherWorkspacesInstance; + } + } + + private void EnsureSubscribedToSolutionEvents() + { + if (Interlocked.CompareExchange(ref _subscribedToSolutionEvents, 1, 0) == 0) + { + Task.Run(async () => + { + var shellService = await _serviceProvider.GetServiceAsync(_threadingContext.JoinableTaskFactory).ConfigureAwait(true); + await _threadingContext.JoinableTaskFactory.SwitchToMainThreadAsync(_threadingContext.DisposalToken); + shellService.AdviseSolutionEvents(this, out _); + }, _threadingContext.DisposalToken); + } + } + + public void ReportOtherWorkspaceTelemetry() + { + _otherWorkspacesInstance.ReportStatisticsAndClear(FunctionId.SourceGenerator_OtherWorkspaceSessionStatistics); + } + + int IVsSolutionEvents.OnAfterOpenProject(IVsHierarchy pHierarchy, int fAdded) => VSConstants.E_NOTIMPL; + int IVsSolutionEvents.OnQueryCloseProject(IVsHierarchy pHierarchy, int fRemoving, ref int pfCancel) => VSConstants.E_NOTIMPL; + int IVsSolutionEvents.OnBeforeCloseProject(IVsHierarchy pHierarchy, int fRemoved) => VSConstants.E_NOTIMPL; + int IVsSolutionEvents.OnAfterLoadProject(IVsHierarchy pStubHierarchy, IVsHierarchy pRealHierarchy) => VSConstants.E_NOTIMPL; + int IVsSolutionEvents.OnQueryUnloadProject(IVsHierarchy pRealHierarchy, ref int pfCancel) => VSConstants.E_NOTIMPL; + int IVsSolutionEvents.OnBeforeUnloadProject(IVsHierarchy pRealHierarchy, IVsHierarchy pStubHierarchy) => VSConstants.E_NOTIMPL; + int IVsSolutionEvents.OnAfterOpenSolution(object pUnkReserved, int fNewSolution) => VSConstants.E_NOTIMPL; + int IVsSolutionEvents.OnQueryCloseSolution(object pUnkReserved, ref int pfCancel) => VSConstants.E_NOTIMPL; + + int IVsSolutionEvents.OnBeforeCloseSolution(object pUnkReserved) + { + // Report the telemetry now before the solution is closed; since this will be reported per solution session ID, it means + // we can distinguish how many solutions have generators versus just overall sessions. + _visualStudioWorkspaceInstance.ReportStatisticsAndClear(FunctionId.SourceGenerator_SolutionStatistics); + + return VSConstants.S_OK; + } + + int IVsSolutionEvents.OnAfterCloseSolution(object pUnkReserved) => VSConstants.E_NOTIMPL; + } +} diff --git a/src/Workspaces/Core/Portable/Log/AbstractLogAggregator.cs b/src/Workspaces/Core/Portable/Log/AbstractLogAggregator.cs index db02c406b7e8f..0c7aaf58af5cf 100644 --- a/src/Workspaces/Core/Portable/Log/AbstractLogAggregator.cs +++ b/src/Workspaces/Core/Portable/Log/AbstractLogAggregator.cs @@ -30,6 +30,8 @@ protected AbstractLogAggregator() public bool IsEmpty => _map.IsEmpty; + public void Clear() => _map.Clear(); + public IEnumerator> GetEnumerator() => _map.GetEnumerator(); diff --git a/src/Workspaces/Core/Portable/SourceGeneratorTelemetry/ISourceGeneratorTelemetryCollectorWorkspaceService.cs b/src/Workspaces/Core/Portable/SourceGeneratorTelemetry/ISourceGeneratorTelemetryCollectorWorkspaceService.cs new file mode 100644 index 0000000000000..11687f1346ed0 --- /dev/null +++ b/src/Workspaces/Core/Portable/SourceGeneratorTelemetry/ISourceGeneratorTelemetryCollectorWorkspaceService.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; +using System.Collections.Generic; +using System.Text; +using Microsoft.CodeAnalysis.Host; + +namespace Microsoft.CodeAnalysis.SourceGeneratorTelemetry +{ + internal interface ISourceGeneratorTelemetryCollectorWorkspaceService : IWorkspaceService + { + void CollectRunResult(GeneratorDriverRunResult driverRunResult, GeneratorDriverTimingInfo driverTimingInfo); + } +} diff --git a/src/Workspaces/Core/Portable/SourceGeneratorTelemetry/SourceGeneratorTelemetryCollectorWorkspaceService.cs b/src/Workspaces/Core/Portable/SourceGeneratorTelemetry/SourceGeneratorTelemetryCollectorWorkspaceService.cs new file mode 100644 index 0000000000000..2eca052d40aff --- /dev/null +++ b/src/Workspaces/Core/Portable/SourceGeneratorTelemetry/SourceGeneratorTelemetryCollectorWorkspaceService.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; +using System.Diagnostics; +using System.Runtime.CompilerServices; +using Microsoft.CodeAnalysis.Internal.Log; +using Roslyn.Utilities; + +namespace Microsoft.CodeAnalysis.SourceGeneratorTelemetry +{ + internal class SourceGeneratorTelemetryCollectorWorkspaceService : ISourceGeneratorTelemetryCollectorWorkspaceService + { + private record GeneratorTelemetryKey + { + public GeneratorTelemetryKey(ISourceGenerator generator) + { + Identity = new SourceGeneratorIdentity(generator); + FileVersion = FileVersionInfo.GetVersionInfo(generator.GetGeneratorType().Assembly.Location).FileVersion ?? "(null)"; + } + + // TODO: mark these 'required' when we have the attributes in place + public SourceGeneratorIdentity Identity { get; init; } + public string FileVersion { get; init; } + } + + /// + /// Cache of the for a generator to avoid repeatedly reading version information from disk; + /// this is a ConditionalWeakTable so having telemetry for older runs doesn't keep the generator itself alive. + /// + private readonly ConditionalWeakTable _generatorTelemetryKeys = new ConditionalWeakTable(); + + private readonly StatisticLogAggregator _elapsedTimeByGenerator = new StatisticLogAggregator(); + private readonly StatisticLogAggregator _producedFilesByGenerator = new StatisticLogAggregator(); + + private GeneratorTelemetryKey GetTelemetryKey(ISourceGenerator generator) => _generatorTelemetryKeys.GetValue(generator, static g => new GeneratorTelemetryKey(g)); + + public void CollectRunResult(GeneratorDriverRunResult driverRunResult, GeneratorDriverTimingInfo driverTimingInfo) + { + foreach (var generatorTime in driverTimingInfo.GeneratorTimes) + { + _elapsedTimeByGenerator.AddDataPoint(GetTelemetryKey(generatorTime.Generator), generatorTime.ElapsedTime); + } + + foreach (var generatorResult in driverRunResult.Results) + { + _producedFilesByGenerator.AddDataPoint(GetTelemetryKey(generatorResult.Generator), generatorResult.GeneratedSources.Length); + } + } + + public void ReportStatisticsAndClear(FunctionId functionId) + { + foreach (var (telemetryKey, elapsedTimeCounter) in _elapsedTimeByGenerator) + { + // We'll log one event per generator + Logger.Log(functionId, KeyValueLogMessage.Create(map => + { + map[nameof(telemetryKey.Identity.AssemblyName)] = telemetryKey.Identity.AssemblyName; + map[nameof(telemetryKey.Identity.AssemblyVersion)] = telemetryKey.Identity.AssemblyVersion.ToString(); + map[nameof(telemetryKey.Identity.TypeName)] = telemetryKey.Identity.TypeName; + map[nameof(telemetryKey.FileVersion)] = telemetryKey.FileVersion; + + var result = elapsedTimeCounter.GetStatisticResult(); + result.WriteTelemetryPropertiesTo(map, prefix: "ElapsedTimePerRun."); + + var producedFileCount = _producedFilesByGenerator.GetStatisticResult(telemetryKey); + producedFileCount.WriteTelemetryPropertiesTo(map, prefix: "GeneratedFileCountPerRun."); + })); + } + } + } +} diff --git a/src/Workspaces/Core/Portable/Workspace/Solution/SolutionState.CompilationTracker.cs b/src/Workspaces/Core/Portable/Workspace/Solution/SolutionState.CompilationTracker.cs index 0564ab69557f5..565b50ee89414 100644 --- a/src/Workspaces/Core/Portable/Workspace/Solution/SolutionState.CompilationTracker.cs +++ b/src/Workspaces/Core/Portable/Workspace/Solution/SolutionState.CompilationTracker.cs @@ -18,6 +18,7 @@ using Microsoft.CodeAnalysis.Logging; using Microsoft.CodeAnalysis.PooledObjects; using Microsoft.CodeAnalysis.Shared.Collections; +using Microsoft.CodeAnalysis.SourceGeneratorTelemetry; using Roslyn.Utilities; namespace Microsoft.CodeAnalysis @@ -861,6 +862,9 @@ public CompilationInfo(Compilation compilation, bool hasSuccessfullyLoaded, Comp // END HACK HACK HACK HACK. generatorInfo = generatorInfo.WithDriver(generatorInfo.Driver!.RunGenerators(compilationToRunGeneratorsOn, cancellationToken)); + + solution.Services.GetService()?.CollectRunResult(generatorInfo.Driver!.GetRunResult(), generatorInfo.Driver!.GetTimingInfo()); + var runResult = generatorInfo.Driver!.GetRunResult(); // We may be able to reuse compilationWithStaleGeneratedTrees if the generated trees are identical. We will assign null diff --git a/src/Workspaces/SharedUtilitiesAndExtensions/Compiler/Core/Log/FunctionId.cs b/src/Workspaces/SharedUtilitiesAndExtensions/Compiler/Core/Log/FunctionId.cs index 9951758ebd9d4..7a41c3a75ee18 100644 --- a/src/Workspaces/SharedUtilitiesAndExtensions/Compiler/Core/Log/FunctionId.cs +++ b/src/Workspaces/SharedUtilitiesAndExtensions/Compiler/Core/Log/FunctionId.cs @@ -573,5 +573,8 @@ internal enum FunctionId SpellCheckFixer_RenameSpanNotWithinTokenSpan = 603, SpellCheckFixer_ReplacementTextInvalid = 604, SpellCheckFixer_TryApplyChangesFailure = 605, + + SourceGenerator_SolutionStatistics = 620, + SourceGenerator_OtherWorkspaceSessionStatistics = 621 } }