Skip to content

Commit

Permalink
Source generators/timing (#55892)
Browse files Browse the repository at this point in the history
* Add logging event source

* Track timing information in the generator driver
- Expose via runrunresult and ETW
- Extract out helper from event source
- Add extension methods to create a start/stop pair of events the driver can use
  • Loading branch information
chsienki authored Sep 3, 2021
1 parent 504755d commit d1ba282
Show file tree
Hide file tree
Showing 8 changed files with 165 additions and 21 deletions.
Original file line number Diff line number Diff line change
Expand Up @@ -408,7 +408,8 @@ private DriverStateTable.Builder GetBuilder(DriverStateTable previous)
ImmutableArray<AdditionalText>.Empty,
ImmutableArray<GeneratorState>.Empty,
previous,
disabledOutputs: IncrementalGeneratorOutputKind.None);
disabledOutputs: IncrementalGeneratorOutputKind.None,
runtime: TimeSpan.Zero);

return new DriverStateTable.Builder(c, state, ImmutableArray<ISyntaxInputNode>.Empty);
}
Expand Down
41 changes: 41 additions & 0 deletions src/Compilers/Core/Portable/CodeAnalysisEventSource.cs
Original file line number Diff line number Diff line change
@@ -0,0 +1,41 @@
// 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.Tracing;
using Roslyn.Utilities;

namespace Microsoft.CodeAnalysis
{
[EventSource(Name = "Microsoft-CodeAnalysis-General")]
internal sealed class CodeAnalysisEventSource : EventSource
{
public static readonly CodeAnalysisEventSource Log = new CodeAnalysisEventSource();

public static class Keywords
{
public const EventKeywords Performance = (EventKeywords)1;
}

public static class Tasks
{
public const EventTask GeneratorDriverRunTime = (EventTask)1;
public const EventTask SingleGeneratorRunTime = (EventTask)2;
}

private CodeAnalysisEventSource() { }

[Event(1, Keywords = Keywords.Performance, Level = EventLevel.Informational, Opcode = EventOpcode.Start, Task = Tasks.GeneratorDriverRunTime)]
internal void StartGeneratorDriverRunTime(string id) => WriteEvent(1, id);

[Event(2, Message = "Generators ran for {0} ticks", Keywords = Keywords.Performance, Level = EventLevel.Informational, Opcode = EventOpcode.Stop, Task = Tasks.GeneratorDriverRunTime)]
internal void StopGeneratorDriverRunTime(long elapsedTicks, string id) => WriteEvent(2, elapsedTicks, id);

[Event(3, Keywords = Keywords.Performance, Level = EventLevel.Informational, Opcode = EventOpcode.Start, Task = Tasks.SingleGeneratorRunTime)]
internal void StartSingleGeneratorRunTime(string generatorName, string assemblyPath, string id) => WriteEvent(3, generatorName, assemblyPath, id);

[Event(4, Message = "Generator {0} ran for {2} ticks", Keywords = Keywords.Performance, Level = EventLevel.Informational, Opcode = EventOpcode.Stop, Task = Tasks.SingleGeneratorRunTime)]
internal void StopSingleGeneratorRunTime(string generatorName, string assemblyPath, long elapsedTicks, string id) => WriteEvent(4, generatorName, assemblyPath, elapsedTicks, id);
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -40,6 +40,7 @@ internal class DefaultAnalyzerAssemblyLoader : AnalyzerAssemblyLoader
"System.Console",
"System.Diagnostics.Debug",
"System.Diagnostics.StackTrace",
"System.Diagnostics.Tracing",
"System.IO.Compression",
"System.IO.FileSystem",
"System.Linq",
Expand Down
21 changes: 12 additions & 9 deletions src/Compilers/Core/Portable/SourceGeneration/GeneratorDriver.cs
Original file line number Diff line number Diff line change
Expand Up @@ -36,7 +36,7 @@ internal GeneratorDriver(GeneratorDriverState state)
internal GeneratorDriver(ParseOptions parseOptions, ImmutableArray<ISourceGenerator> generators, AnalyzerConfigOptionsProvider optionsProvider, ImmutableArray<AdditionalText> additionalTexts, GeneratorDriverOptions driverOptions)
{
(var filteredGenerators, var incrementalGenerators) = GetIncrementalGenerators(generators, SourceExtension);
_state = new GeneratorDriverState(parseOptions, optionsProvider, filteredGenerators, incrementalGenerators, additionalTexts, ImmutableArray.Create(new GeneratorState[filteredGenerators.Length]), DriverStateTable.Empty, driverOptions.DisabledOutputs);
_state = new GeneratorDriverState(parseOptions, optionsProvider, filteredGenerators, incrementalGenerators, additionalTexts, ImmutableArray.Create(new GeneratorState[filteredGenerators.Length]), DriverStateTable.Empty, driverOptions.DisabledOutputs, runtime: TimeSpan.Zero);
}

public GeneratorDriver RunGenerators(Compilation compilation, CancellationToken cancellationToken = default)
Expand Down Expand Up @@ -135,8 +135,9 @@ public GeneratorDriverRunResult GetRunResult()
=> new GeneratorRunResult(generator,
diagnostics: generatorState.Diagnostics,
exception: generatorState.Exception,
generatedSources: getGeneratorSources(generatorState)));
return new GeneratorDriverRunResult(results);
generatedSources: getGeneratorSources(generatorState),
elapsedTime: generatorState.ElapsedTime));
return new GeneratorDriverRunResult(results, _state.RunTime);

static ImmutableArray<GeneratedSourceResult> getGeneratorSources(GeneratorState generatorState)
{
Expand All @@ -158,10 +159,11 @@ internal GeneratorDriverState RunGeneratorsCore(Compilation compilation, Diagnos
// with no generators, there is no work to do
if (_state.Generators.IsEmpty)
{
return _state.With(stateTable: DriverStateTable.Empty);
return _state.With(stateTable: DriverStateTable.Empty, runTime: TimeSpan.Zero);
}

// run the actual generation
using var timer = CodeAnalysisEventSource.Log.CreateGeneratorDriverRunTimer();
var state = _state;
var stateBuilder = ArrayBuilder<GeneratorState>.GetInstance(state.Generators.Length);
var constantSourcesBuilder = ArrayBuilder<SyntaxTree>.GetInstance();
Expand Down Expand Up @@ -244,21 +246,22 @@ internal GeneratorDriverState RunGeneratorsCore(Compilation compilation, Diagnos
continue;
}

using var generatorTimer = CodeAnalysisEventSource.Log.CreateSingleGeneratorRunTimer(state.Generators[i]);
try
{
var context = UpdateOutputs(generatorState.OutputNodes, IncrementalGeneratorOutputKind.Source | IncrementalGeneratorOutputKind.Implementation, cancellationToken, driverStateBuilder);
(var sources, var generatorDiagnostics) = context.ToImmutableAndFree();
generatorDiagnostics = FilterDiagnostics(compilation, generatorDiagnostics, driverDiagnostics: diagnosticsBag, cancellationToken);

stateBuilder[i] = new GeneratorState(generatorState.Info, generatorState.PostInitTrees, generatorState.InputNodes, generatorState.OutputNodes, ParseAdditionalSources(state.Generators[i], sources, cancellationToken), generatorDiagnostics);
stateBuilder[i] = new GeneratorState(generatorState.Info, generatorState.PostInitTrees, generatorState.InputNodes, generatorState.OutputNodes, ParseAdditionalSources(state.Generators[i], sources, cancellationToken), generatorDiagnostics, generatorTimer.Elapsed);
}
catch (UserFunctionException ufe)
{
stateBuilder[i] = SetGeneratorException(MessageProvider, stateBuilder[i], state.Generators[i], ufe.InnerException, diagnosticsBag);
stateBuilder[i] = SetGeneratorException(MessageProvider, stateBuilder[i], state.Generators[i], ufe.InnerException, diagnosticsBag, generatorTimer.Elapsed);
}
}

state = state.With(stateTable: driverStateBuilder.ToImmutable(), generatorStates: stateBuilder.ToImmutableAndFree());
state = state.With(stateTable: driverStateBuilder.ToImmutable(), generatorStates: stateBuilder.ToImmutableAndFree(), runTime: timer.Elapsed);
return state;
}

Expand Down Expand Up @@ -290,7 +293,7 @@ private ImmutableArray<GeneratedSyntaxTree> ParseAdditionalSources(ISourceGenera
return trees.ToImmutableAndFree();
}

private static GeneratorState SetGeneratorException(CommonMessageProvider provider, GeneratorState generatorState, ISourceGenerator generator, Exception e, DiagnosticBag? diagnosticBag, bool isInit = false)
private static GeneratorState SetGeneratorException(CommonMessageProvider provider, GeneratorState generatorState, ISourceGenerator generator, Exception e, DiagnosticBag? diagnosticBag, TimeSpan? runTime = null, bool isInit = false)
{
var errorCode = isInit ? provider.WRN_GeneratorFailedDuringInitialization : provider.WRN_GeneratorFailedDuringGeneration;

Expand All @@ -313,7 +316,7 @@ private static GeneratorState SetGeneratorException(CommonMessageProvider provid
var diagnostic = Diagnostic.Create(descriptor, Location.None, generator.GetGeneratorType().Name, e.GetType().Name, e.Message);

diagnosticBag?.Add(diagnostic);
return new GeneratorState(generatorState.Info, e, diagnostic);
return new GeneratorState(generatorState.Info, e, diagnostic, runTime ?? TimeSpan.Zero);
}

private static ImmutableArray<Diagnostic> FilterDiagnostics(Compilation compilation, ImmutableArray<Diagnostic> generatorDiagnostics, DiagnosticBag? driverDiagnostics, CancellationToken cancellationToken)
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,7 @@
// 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.Immutable;
using System.Diagnostics;
using Microsoft.CodeAnalysis.Diagnostics;
Expand All @@ -17,7 +18,8 @@ internal GeneratorDriverState(ParseOptions parseOptions,
ImmutableArray<AdditionalText> additionalTexts,
ImmutableArray<GeneratorState> generatorStates,
DriverStateTable stateTable,
IncrementalGeneratorOutputKind disabledOutputs)
IncrementalGeneratorOutputKind disabledOutputs,
TimeSpan runtime)
{
Generators = sourceGenerators;
IncrementalGenerators = incrementalGenerators;
Expand All @@ -27,6 +29,7 @@ internal GeneratorDriverState(ParseOptions parseOptions,
OptionsProvider = optionsProvider;
StateTable = stateTable;
DisabledOutputs = disabledOutputs;
RunTime = runtime;
Debug.Assert(Generators.Length == GeneratorStates.Length);
Debug.Assert(IncrementalGenerators.Length == GeneratorStates.Length);
}
Expand Down Expand Up @@ -80,6 +83,8 @@ internal GeneratorDriverState(ParseOptions parseOptions,
/// </summary>
internal readonly IncrementalGeneratorOutputKind DisabledOutputs;

internal readonly TimeSpan RunTime;

internal GeneratorDriverState With(
ImmutableArray<ISourceGenerator>? sourceGenerators = null,
ImmutableArray<IIncrementalGenerator>? incrementalGenerators = null,
Expand All @@ -88,7 +93,8 @@ internal GeneratorDriverState With(
DriverStateTable? stateTable = null,
ParseOptions? parseOptions = null,
AnalyzerConfigOptionsProvider? optionsProvider = null,
IncrementalGeneratorOutputKind? disabledOutputs = null)
IncrementalGeneratorOutputKind? disabledOutputs = null,
TimeSpan? runTime = null)
{
return new GeneratorDriverState(
parseOptions ?? this.ParseOptions,
Expand All @@ -98,7 +104,8 @@ internal GeneratorDriverState With(
additionalTexts ?? this.AdditionalTexts,
generatorStates ?? this.GeneratorStates,
stateTable ?? this.StateTable,
disabledOutputs ?? this.DisabledOutputs
disabledOutputs ?? this.DisabledOutputs,
runTime ?? this.RunTime
);
}
}
Expand Down
15 changes: 9 additions & 6 deletions src/Compilers/Core/Portable/SourceGeneration/GeneratorState.cs
Original file line number Diff line number Diff line change
Expand Up @@ -32,27 +32,27 @@ public GeneratorState(GeneratorInfo info, ImmutableArray<GeneratedSyntaxTree> po
/// Creates a new generator state that contains information, constant trees and an execution pipeline
/// </summary>
public GeneratorState(GeneratorInfo info, ImmutableArray<GeneratedSyntaxTree> postInitTrees, ImmutableArray<ISyntaxInputNode> inputNodes, ImmutableArray<IIncrementalGeneratorOutputNode> outputNodes)
: this(info, postInitTrees, inputNodes, outputNodes, ImmutableArray<GeneratedSyntaxTree>.Empty, ImmutableArray<Diagnostic>.Empty, exception: null)
: this(info, postInitTrees, inputNodes, outputNodes, ImmutableArray<GeneratedSyntaxTree>.Empty, ImmutableArray<Diagnostic>.Empty, exception: null, elapsedTime: TimeSpan.Zero)
{
}

/// <summary>
/// Creates a new generator state that contains an exception and the associated diagnostic
/// </summary>
public GeneratorState(GeneratorInfo info, Exception e, Diagnostic error)
: this(info, ImmutableArray<GeneratedSyntaxTree>.Empty, ImmutableArray<ISyntaxInputNode>.Empty, ImmutableArray<IIncrementalGeneratorOutputNode>.Empty, ImmutableArray<GeneratedSyntaxTree>.Empty, ImmutableArray.Create(error), exception: e)
public GeneratorState(GeneratorInfo info, Exception e, Diagnostic error, TimeSpan elapsedTime)
: this(info, ImmutableArray<GeneratedSyntaxTree>.Empty, ImmutableArray<ISyntaxInputNode>.Empty, ImmutableArray<IIncrementalGeneratorOutputNode>.Empty, ImmutableArray<GeneratedSyntaxTree>.Empty, ImmutableArray.Create(error), exception: e, elapsedTime)
{
}

/// <summary>
/// Creates a generator state that contains results
/// </summary>
public GeneratorState(GeneratorInfo info, ImmutableArray<GeneratedSyntaxTree> postInitTrees, ImmutableArray<ISyntaxInputNode> inputNodes, ImmutableArray<IIncrementalGeneratorOutputNode> outputNodes, ImmutableArray<GeneratedSyntaxTree> generatedTrees, ImmutableArray<Diagnostic> diagnostics)
: this(info, postInitTrees, inputNodes, outputNodes, generatedTrees, diagnostics, exception: null)
public GeneratorState(GeneratorInfo info, ImmutableArray<GeneratedSyntaxTree> postInitTrees, ImmutableArray<ISyntaxInputNode> inputNodes, ImmutableArray<IIncrementalGeneratorOutputNode> outputNodes, ImmutableArray<GeneratedSyntaxTree> generatedTrees, ImmutableArray<Diagnostic> diagnostics, TimeSpan elapsedTime)
: this(info, postInitTrees, inputNodes, outputNodes, generatedTrees, diagnostics, exception: null, elapsedTime)
{
}

private GeneratorState(GeneratorInfo info, ImmutableArray<GeneratedSyntaxTree> postInitTrees, ImmutableArray<ISyntaxInputNode> inputNodes, ImmutableArray<IIncrementalGeneratorOutputNode> outputNodes, ImmutableArray<GeneratedSyntaxTree> generatedTrees, ImmutableArray<Diagnostic> diagnostics, Exception? exception)
private GeneratorState(GeneratorInfo info, ImmutableArray<GeneratedSyntaxTree> postInitTrees, ImmutableArray<ISyntaxInputNode> inputNodes, ImmutableArray<IIncrementalGeneratorOutputNode> outputNodes, ImmutableArray<GeneratedSyntaxTree> generatedTrees, ImmutableArray<Diagnostic> diagnostics, Exception? exception, TimeSpan elapsedTime)
{
this.Initialized = true;
this.PostInitTrees = postInitTrees;
Expand All @@ -62,6 +62,7 @@ private GeneratorState(GeneratorInfo info, ImmutableArray<GeneratedSyntaxTree> p
this.Info = info;
this.Diagnostics = diagnostics;
this.Exception = exception;
this.ElapsedTime = elapsedTime;
}

internal bool Initialized { get; }
Expand All @@ -78,6 +79,8 @@ private GeneratorState(GeneratorInfo info, ImmutableArray<GeneratedSyntaxTree> p

internal Exception? Exception { get; }

internal TimeSpan ElapsedTime { get; }

internal ImmutableArray<Diagnostic> Diagnostics { get; }
}
}
Original file line number Diff line number Diff line change
@@ -0,0 +1,76 @@
// 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.Diagnostics.Tracing;
using System.Text;
using Roslyn.Utilities;
using static Microsoft.CodeAnalysis.CodeAnalysisEventSource;

namespace Microsoft.CodeAnalysis
{
internal static class GeneratorTimerExtensions
{
public static RunTimer CreateGeneratorDriverRunTimer(this CodeAnalysisEventSource eventSource)
{
if (eventSource.IsEnabled(EventLevel.Informational, Keywords.Performance))
{
var id = Guid.NewGuid().ToString();
eventSource.StartGeneratorDriverRunTime(id);
return new RunTimer(t => eventSource.StopGeneratorDriverRunTime(t.Ticks, id));
}
else
{
return new RunTimer();
}
}

public static RunTimer CreateSingleGeneratorRunTimer(this CodeAnalysisEventSource eventSource, ISourceGenerator generator)
{
if (eventSource.IsEnabled(EventLevel.Informational, Keywords.Performance))
{
var id = Guid.NewGuid().ToString();
var type = generator.GetGeneratorType();
eventSource.StartSingleGeneratorRunTime(type.FullName!, type.Assembly.Location, id);
return new RunTimer(t => eventSource.StopSingleGeneratorRunTime(type.FullName!, type.Assembly.Location, t.Ticks, id));
}
else
{
return new RunTimer();
}
}

internal readonly struct RunTimer : IDisposable
{
private readonly SharedStopwatch _timer;
private readonly Action<TimeSpan>? _callback;

public TimeSpan Elapsed => _timer.Elapsed;

public RunTimer()
{
// start twice to improve accuracy. See AnalyzerExecutor.ExecuteAndCatchIfThrows for more details
_ = SharedStopwatch.StartNew();
_timer = SharedStopwatch.StartNew();
_callback = null;
}

public RunTimer(Action<TimeSpan> callback)
: this()
{
_callback = callback;
}

public void Dispose()
{
if (_callback is not null)
{
var elapsed = _timer.Elapsed;
_callback(elapsed);
}
}
}
}
}
Loading

0 comments on commit d1ba282

Please sign in to comment.