Skip to content

Commit

Permalink
Add telemetry for the time and files outputted for source generators
Browse files Browse the repository at this point in the history
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.
  • Loading branch information
jasonmalinowski committed Aug 17, 2022
1 parent 166035a commit a5aec76
Show file tree
Hide file tree
Showing 7 changed files with 205 additions and 1 deletion.
3 changes: 2 additions & 1 deletion src/VisualStudio/Core/Def/RoslynPackage.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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<VisualStudioSourceGeneratorTelemetryCollectorWorkspaceServiceFactory>().ReportOtherWorkspaceTelemetry();
}

private void DisposeVisualStudioServices()
Expand Down
Original file line number Diff line number Diff line change
@@ -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
{
/// <summary>
/// Exports a <see cref="ISourceGeneratorTelemetryCollectorWorkspaceService"/> 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.
/// </summary>
[Export]
[ExportWorkspaceServiceFactory(typeof(ISourceGeneratorTelemetryCollectorWorkspaceService)), Shared]
internal class VisualStudioSourceGeneratorTelemetryCollectorWorkspaceServiceFactory : IWorkspaceServiceFactory, IVsSolutionEvents
{
/// <summary>
/// The collector that's used to collect all the telemetry for operations within <see cref="VisualStudioWorkspace"/>. We'll report this
/// when the solution is closed, so the telemetry is linked to that.
/// </summary>
private readonly SourceGeneratorTelemetryCollectorWorkspaceService _visualStudioWorkspaceInstance = new SourceGeneratorTelemetryCollectorWorkspaceService();

/// <summary>
/// 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.
/// </summary>
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<SVsSolution, IVsSolution>(_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;
}
}
2 changes: 2 additions & 0 deletions src/Workspaces/Core/Portable/Log/AbstractLogAggregator.cs
Original file line number Diff line number Diff line change
Expand Up @@ -30,6 +30,8 @@ protected AbstractLogAggregator()

public bool IsEmpty => _map.IsEmpty;

public void Clear() => _map.Clear();

public IEnumerator<KeyValuePair<TKey, TValue>> GetEnumerator()
=> _map.GetEnumerator();

Expand Down
Original file line number Diff line number Diff line change
@@ -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);
}
}
Original file line number Diff line number Diff line change
@@ -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; }
}

/// <summary>
/// Cache of the <see cref="GeneratorTelemetryKey"/> 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.
/// </summary>
private readonly ConditionalWeakTable<ISourceGenerator, GeneratorTelemetryKey> _generatorTelemetryKeys = new ConditionalWeakTable<ISourceGenerator, GeneratorTelemetryKey>();

private readonly StatisticLogAggregator<GeneratorTelemetryKey> _elapsedTimeByGenerator = new StatisticLogAggregator<GeneratorTelemetryKey>();
private readonly StatisticLogAggregator<GeneratorTelemetryKey> _producedFilesByGenerator = new StatisticLogAggregator<GeneratorTelemetryKey>();

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.");
}));
}
}
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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<ISourceGeneratorTelemetryCollectorWorkspaceService>()?.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
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -573,5 +573,8 @@ internal enum FunctionId
SpellCheckFixer_RenameSpanNotWithinTokenSpan = 603,
SpellCheckFixer_ReplacementTextInvalid = 604,
SpellCheckFixer_TryApplyChangesFailure = 605,

SourceGenerator_SolutionStatistics = 620,
SourceGenerator_OtherWorkspaceSessionStatistics = 621
}
}

0 comments on commit a5aec76

Please sign in to comment.