Source generators/timing #55892

chsienki · 2021-08-25T18:54:01Z

Implements wall clock timing for the generator driver and each generator running within it.

Also implements a roslyn ETW event source that can be used to emit performance data. For now we're only using it for generators but we'll likely want to add other things as we go.

Fixes #54770

As we're emitting ETW you can view the data live coming out of visual studio. I've created a small app you can run that allows you to view the data in realtime: https://github.com/chsienki/GeneratorTracer

chsienki · 2021-08-25T20:09:01Z

src/Compilers/Core/Portable/PublicAPI.Unshipped.txt

@@ -13,7 +13,9 @@ Microsoft.CodeAnalysis.GeneratorDriver.WithUpdatedParseOptions(Microsoft.CodeAna
 Microsoft.CodeAnalysis.GeneratorDriverOptions
 Microsoft.CodeAnalysis.GeneratorDriverOptions.GeneratorDriverOptions() -> void
 Microsoft.CodeAnalysis.GeneratorDriverOptions.GeneratorDriverOptions(Microsoft.CodeAnalysis.IncrementalGeneratorOutputKind disabledOutputs) -> void
+Microsoft.CodeAnalysis.GeneratorDriverRunResult.RunTime.get -> System.TimeSpan


@333fred These are new public APIs, but nothing major. Can we just get consensus over email?

Spoke in the API review meeting and agreed to call them ElapsedTime

chsienki · 2021-08-25T20:26:08Z

cc @NTaylorMullen @jasonmalinowski @eerhardt

chsienki · 2021-08-25T20:28:05Z

src/Compilers/Core/Portable/SourceGeneration/GeneratorState.cs

@@ -78,6 +79,8 @@ private GeneratorState(GeneratorInfo info, ImmutableArray<GeneratedSyntaxTree> p

        internal Exception? Exception { get; }

+        internal TimeSpan RunTime { get; }


@jkoritzinsky We probably want to add timing info to the individual steps as well, but we can figure that out when we merge your changes in.

chsienki · 2021-08-25T20:28:36Z

@dotnet/roslyn-compiler for review please :)

NTaylorMullen · 2021-08-25T20:28:46Z

Love the visualizations, the extension to view it in real time and the foresight to add an ETW event. 👏

eerhardt

🎆 This is awesome!

eerhardt · 2021-08-25T20:35:06Z

src/Compilers/Core/Portable/LoggingEventSource.cs

+            public const EventKeywords Performance = (EventKeywords)1;
+        }
+
+        public class Tasks


I don't think we need Tasks here. I think they are only necessary/useful when you have "op codes":

https://github.com/Microsoft/dotnet-samples/blob/master/Microsoft.Diagnostics.Tracing/EventSource/docs/EventSource.md#glossary

cc @brianrob @noahfalk @josalem

You're correct @eerhardt. In this case though it looks like tasks are actually more desirable than the current setup. Please correct me if I read this wrong since I only skimmed the code, but it looks like this patch currently:

adds a Timer to the state of the source generators

sends a completion event with the duration for a given generator

sends a completion event with the duration for the generator driver

I'd maybe look at changing this to use the tasks here by doing the following:

emit a GeneratorDriverStart/GeneratorDriverStop event pair using the driver task and op codes

emit a GeneratorStart/GeneratorStop event pair using the generator task and op codes

calculate the run time by diffing the timestamps of the events (the infrastructure should already do this by embedding the duration in the *Stop events)

What's currently written should be fine, but would subject the times in the events to any issues the timer has with waking up etc. The times are already being provided by the event infrastructure so you can take advantage of that.

I only used them so I could distinguish them in the viewer linked above. Happy to remove them but it seemed like a useful concept. Especially if we convert to a pair of start / stop.

so I could distinguish them in the viewer linked above

Where are you distinguishing them in that viewer? Is it this code?

https://github.com/chsienki/GeneratorTracer/blob/f05dfa908fb7e78741ce2cb96e21cc3c77927609/GeneratorTracer/Program.cs#L30

If so, I think you can just rename the ReportGeneratorDriverRunTime method => GeneratorDriverRunTime and that will be the name of your Event. But this is getting into "beyond my EventSource knowledge" area.

Especially if we convert to a pair of start / stop.

Yeah, if you convert to start / stop, then the Tasks would be useful.

src/Compilers/Core/Portable/LoggingEventSource.cs

src/Compilers/Core/Portable/CodeAnalysisEventSource.cs

eerhardt

The EventSource changes LGTM.

Nice work! I think this is really going to help in diagnosing perf issues related to source generators.

eerhardt · 2021-08-26T19:24:38Z

@chsienki @jaredpar - any thoughts on also backporting this to VS 2019 / Roslyn 3.x? It may be useful to have there for diagnostic purposes when customers are running into sluggish VS performance (e.g. dotnet/runtime#56702).

chsienki · 2021-08-26T21:01:49Z

@chsienki @jaredpar - any thoughts on also backporting this to VS 2019 / Roslyn 3.x? It may be useful to have there for diagnostic purposes when customers are running into sluggish VS performance (e.g. dotnet/runtime#56702).

@eerhardt Sadly if we wanted to do that it'd have to be a manual port, as we've significantly altered the driver architecture between releases, so it seems unlikely.

jasonmalinowski

The API shape looks good, I can't speak to the implementation or the EventSource stuff so somebody else needs to sign off on that.

src/Compilers/Core/Portable/CodeAnalysisEventSource.cs

jaredpar · 2021-08-26T23:36:38Z

src/Compilers/Core/Portable/CodeAnalysisEventSource.cs

+        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);


How does assemblyPath get used here given there is no {1} in the Message string?

It's still available in the ETW event, just not directly in the message attached to it. See https://github.com/chsienki/GeneratorTracer/blob/master/GeneratorTracer/Program.cs#L35

src/Compilers/Core/Portable/SourceGeneration/GeneratorTimerExtensions.cs

jasonmalinowski · 2021-08-30T21:34:13Z

@chsienki Hmm, one thought: what happens in the case of cancellation? It'd be good that if the IDE requests cancellation of a run, we still can see how much time was spent before we abandoned it. Practically a slow generator might get cancelled a lot in our case, and that's the actual indicator of the problem.

chsienki · 2021-08-31T16:45:31Z

@chsienki Hmm, one thought: what happens in the case of cancellation? It'd be good that if the IDE requests cancellation of a run, we still can see how much time was spent before we abandoned it. Practically a slow generator might get cancelled a lot in our case, and that's the actual indicator of the problem.

@jasonmalinowski That's an interesting point. Currently we just let the OperationCancelledException propagate up to the caller, so there is no new instance to get any data/run results from. We could potentially catch it, and mark the driver state as having been cancelled. That way we'd retain whatever we recorded so far, but that seems like a bigger architectural change.

Given that, I think we should take this as-is for now, and work on the cancellation later

jasonmalinowski · 2021-08-31T17:50:46Z

Given that, I think we should take this as-is for now, and work on the cancellation later

If this wasn't going to be a public API I'd heartily agree; in the current form though I'm not sure the IDE will get the benefit we want -- any telemetry we try reporting from would be skewed in a problematic way -- the long generators (that are regularly being cancelled) will be underrepresented in the data.

This won't work for IDE needs, so we'll need something else.

chsienki · 2021-08-31T18:52:42Z

@jasonmalinowski Ok, that makes sense to me.

@jaredpar Should we split out the public API and ETW parts into two parts? I wanted to get the ETW timing in ASAP, and don't want to delay if we need to redesign the public API parts.

jasonmalinowski · 2021-08-31T19:03:15Z

@chsienki: we can make the API internal, right? The API wasn't being used by another layer I don't think in this?

chsienki · 2021-08-31T19:18:49Z

@jasonmalinowski Yep, we can do that. I actually have a change that mostly enables the behaviour the IDE needs, although we need to go through API review again because it adds a WasCancelled property to run result.

chsienki · 2021-08-31T19:19:28Z

Given the above, i'll make the API internal for now, and we can turn it back to public with the Cancellation tracking change afterwards.

cston · 2021-09-01T22:45:46Z

src/Compilers/Core/Portable/CodeAnalysisEventSource.cs

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


Log

Since we have a singleton instance, should CodeAnalysisEventSource have a private constructor? #Closed

Yup, seems like a good idea.

cston · 2021-09-01T22:57:40Z

src/Compilers/Core/Portable/SourceGeneration/GeneratorDriver.cs

@@ -155,10 +156,12 @@ static ImmutableArray<GeneratedSourceResult> getGeneratorSources(GeneratorState

        internal GeneratorDriverState RunGeneratorsCore(Compilation compilation, DiagnosticBag? diagnosticsBag, CancellationToken cancellationToken = default)
        {
+            using var timer = CodeAnalysisEventSource.Log.CreateGeneratorDriverRunTimer();


using var timer

Consider moving after the if (_state.Generators.IsEmpty) { ... } case below, or use timer.Elapsed in that return value. #Closed

cston · 2021-09-01T23:10:30Z

src/Compilers/Core/Portable/SourceGeneration/GeneratorState.cs

        {
        }

        /// <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 runTime)


runTime

Consider naming "elapsedTime" to match the field, here and in constructor below. #Closed

chsienki · 2021-09-01T23:32:44Z

Addressed feedback + rebased to rel/dev17.0

cston · 2021-09-01T23:36:20Z

src/Compilers/Core/Portable/SourceGeneration/GeneratorTimerExtensions.cs

+        {
+            private readonly SharedStopwatch _timer;
+            private readonly Action<TimeSpan> _callback;
+            private readonly bool _shouldExecuteCallback;


Rather than having a bool indicating whether to execute the callback, consider moving the check to the callback itself or set the callback to null or timeSpan => { } for the cases where we're not timing.

cston · 2021-09-01T23:39:06Z

src/Compilers/Core/Portable/SourceGeneration/RunResults.cs

@@ -108,6 +115,11 @@ internal GeneratorRunResult(ISourceGenerator generator, ImmutableArray<Generated
        /// collection will contain a single diagnostic indicating that the generator failed.
        /// </remarks>
        public Exception? Exception { get; }
+
+        /// <summary>
+        /// The wallclock time that elapsed while this generator was running.


Suggested change

/// The wallclock time that elapsed while this generator was running.

/// The wall clock time that elapsed while this generator was running.

cston · 2021-09-01T23:42:01Z

src/Compilers/Core/Portable/SourceGeneration/GeneratorTimerExtensions.cs

+                _callback = callback;
+                _shouldExecuteCallback = shouldExecuteCallback;
+
+                // start twice to improve accuracy. See AnalyzerExecutor::ExecuteAndCatchIfThrows for more details 


Suggested change

// start twice to improve accuracy. See AnalyzerExecutor::ExecuteAndCatchIfThrows for more details

// start twice to improve accuracy. See AnalyzerExecutor.ExecuteAndCatchIfThrows for more details

cston

One suggestion to drop the bool RunTimer._shouldExecuteCallback field if possible, but not blocking.

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

Co-authored-by: Jared Parsons <[email protected]>

dotnet-issue-labeler bot added the Area-Compilers label Aug 25, 2021

chsienki force-pushed the source-generators/timing branch from 208eb44 to d5aeab6 Compare August 25, 2021 18:56

chsienki added the Feature - Source Generators Source Generators label Aug 25, 2021

chsienki commented Aug 25, 2021

View reviewed changes

chsienki marked this pull request as ready for review August 25, 2021 20:25

chsienki requested a review from a team as a code owner August 25, 2021 20:25

chsienki commented Aug 25, 2021

View reviewed changes

eerhardt reviewed Aug 25, 2021

View reviewed changes

This was referenced Aug 25, 2021

Incremental Generator Work Tracking APIs #54832

Closed

Roslyn should have an ETW/EventPipe source that we can use to report data #54770

Closed

eerhardt reviewed Aug 25, 2021

View reviewed changes

src/Compilers/Core/Portable/CodeAnalysisEventSource.cs Outdated Show resolved Hide resolved

eerhardt approved these changes Aug 26, 2021

View reviewed changes

jasonmalinowski previously approved these changes Aug 26, 2021

View reviewed changes

jaredpar reviewed Aug 26, 2021

View reviewed changes

jaredpar approved these changes Aug 27, 2021

View reviewed changes

chsienki force-pushed the source-generators/timing branch from df25032 to 47a230e Compare August 31, 2021 22:08

chsienki changed the base branch from main to release/dev17.0 September 1, 2021 22:44

cston reviewed Sep 1, 2021

View reviewed changes

chsienki force-pushed the source-generators/timing branch from 47a230e to 0d3943a Compare September 1, 2021 23:27

cston reviewed Sep 1, 2021

View reviewed changes

cston approved these changes Sep 2, 2021

View reviewed changes

chsienki and others added 11 commits September 2, 2021 13:12

Add logging event source

96e5355

Track timing information in the generator driver

a14616b

Expose via runrunresult and ETW

Whitespace

93ebfaf

PR Feedback

17802a0

Make events start / stop:

008d954

- Extract out helper from event source - Add extension methods to create a start/stop pair of events the driver can use

Emit generator name on start event too

912cf63

Apply suggestions from code review

5db2f35

Co-authored-by: Jared Parsons <[email protected]>

Make elapsedtime internal for now

b28777f

Public api

9516f60

PR Feedback

c6eae59

PR Feedback

2bfa9cb

chsienki force-pushed the source-generators/timing branch from 0d3943a to 2bfa9cb Compare September 2, 2021 20:13

chsienki enabled auto-merge (squash) September 2, 2021 20:14

Update DefaultAnalyzerAssemblyLoader.CompilerAssemblySimpleNames

2d7127a

chsienki merged commit d1ba282 into dotnet:release/dev17.0 Sep 3, 2021

eerhardt mentioned this pull request Sep 8, 2021

Issue diagnostic warnings when context types don't indicate serializable types dotnet/runtime#58768

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Source generators/timing #55892

Source generators/timing #55892

chsienki commented Aug 25, 2021 •

edited

Loading

chsienki Aug 25, 2021

chsienki Aug 25, 2021

chsienki commented Aug 25, 2021

chsienki Aug 25, 2021

chsienki commented Aug 25, 2021

NTaylorMullen commented Aug 25, 2021

eerhardt left a comment

eerhardt Aug 25, 2021

josalem Aug 25, 2021

chsienki Aug 25, 2021

eerhardt Aug 25, 2021

eerhardt left a comment

eerhardt commented Aug 26, 2021

chsienki commented Aug 26, 2021

jasonmalinowski left a comment

jaredpar Aug 26, 2021

chsienki Aug 27, 2021

jasonmalinowski commented Aug 30, 2021

chsienki commented Aug 31, 2021

jasonmalinowski commented Aug 31, 2021

chsienki commented Aug 31, 2021

jasonmalinowski commented Aug 31, 2021

chsienki commented Aug 31, 2021

chsienki commented Aug 31, 2021

cston Sep 1, 2021 •

edited

Loading

chsienki Sep 1, 2021

cston Sep 1, 2021 •

edited

Loading

cston Sep 1, 2021 •

edited

Loading

chsienki commented Sep 1, 2021

cston Sep 1, 2021

cston Sep 1, 2021

cston Sep 1, 2021

cston left a comment

		@@ -78,6 +79,8 @@ private GeneratorState(GeneratorInfo info, ImmutableArray<GeneratedSyntaxTree> p

		internal Exception? Exception { get; }

		internal TimeSpan RunTime { get; }

	/// The wallclock time that elapsed while this generator was running.
	/// The wall clock time that elapsed while this generator was running.

	// start twice to improve accuracy. See AnalyzerExecutor::ExecuteAndCatchIfThrows for more details
	// start twice to improve accuracy. See AnalyzerExecutor.ExecuteAndCatchIfThrows for more details

Source generators/timing #55892

Source generators/timing #55892

Conversation

chsienki commented Aug 25, 2021 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

chsienki commented Aug 25, 2021

Choose a reason for hiding this comment

chsienki commented Aug 25, 2021

NTaylorMullen commented Aug 25, 2021

eerhardt left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

eerhardt left a comment

Choose a reason for hiding this comment

eerhardt commented Aug 26, 2021

chsienki commented Aug 26, 2021

jasonmalinowski left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jasonmalinowski commented Aug 30, 2021

chsienki commented Aug 31, 2021

jasonmalinowski commented Aug 31, 2021

chsienki commented Aug 31, 2021

jasonmalinowski commented Aug 31, 2021

chsienki commented Aug 31, 2021

chsienki commented Aug 31, 2021

cston Sep 1, 2021 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

cston Sep 1, 2021 • edited Loading

Choose a reason for hiding this comment

cston Sep 1, 2021 • edited Loading

Choose a reason for hiding this comment

chsienki commented Sep 1, 2021

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

cston left a comment

Choose a reason for hiding this comment

chsienki commented Aug 25, 2021 •

edited

Loading

cston Sep 1, 2021 •

edited

Loading

cston Sep 1, 2021 •

edited

Loading

cston Sep 1, 2021 •

edited

Loading