Implement source generator timing APIs #60267

chsienki · 2022-03-18T23:14:25Z

Implements timing APIs as approved here: #59398

Also fixes a long standing problem where syntax time was misattributed to whichever generator first updated its syntax nodes. This was less of a problem when it was only ETW events, but now we're exposing it via API it needs to be correct.

Closes #59398

chsienki · 2022-03-21T20:35:12Z

@dotnet/roslyn-compiler for review please

jasonmalinowski · 2022-03-29T03:02:22Z

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

@@ -51,6 +53,8 @@ public IStateTable GetSyntaxInputTable(SyntaxInputNode syntaxInputNode, NodeStat
                // when we don't have a value for this node, we update all the syntax inputs at once
                if (!_tableBuilder.Contains(syntaxInputNode))
                {
+                    _causedUpdate = syntaxInputNode;


For generators that don't consume syntax at all, they'll still be updated or do we need other methods updated too? A generator that consumes nothing but is still stupidly expensive will get flagged? This is a question from the perspective of me not quite knowing the implementation here of this type or what it's for.

Yes, this offset calculation only affects generators that touch syntax. Basically first generator to hit a syntax input updates all the others. That means the wall clock time calculated in GeneratorDriver here https://github.com/dotnet/roslyn/pull/60267/files#diff-d19793306af7a0ed1d42db723b6eba037523b35a290799c83402e854d7e5917dR261 incorrectly includes syntax timings for other generators.

Regular generators that don't use syntax will just have an offset adjustment of 0. The 'victim' that ran all the updates gets a negative offset to remove the extra time. Everything else gets the time spend calculating its nodes to ensure its accurate.

jasonmalinowski · 2022-03-29T03:08:38Z

src/Compilers/CSharp/Test/Semantic/SourceGeneration/SyntaxAwareGeneratorTests.cs

+            Assert.NotEqual(TimeSpan.Zero, timing.ElapsedTime);
+            Assert.Equal(2, timing.GeneratorTimes.Length);
+
+            // check generator one took at least 'sleepTimeInMs'


Is there a guarantee that Thread.Sleep(50) ensures that underlying timer will advance far enough? I'm always paranoid with mixing different types of timers. The Win32 Sleep call at least:

The system clock "ticks" at a constant rate. If dwMilliseconds is less than the resolution of the system clock, the thread may sleep for less than the specified length of time. If dwMilliseconds is greater than one tick but less than two, the wait can be anywhere between one and two ticks, and so on.

Yeah, I agonized over this as I really don't like relying on timing information, but couldn't really think of a better way to test it. Anecdotally 50ms seemed a good balance between not slowing down tests too much, but always passing.

Did you consider the following pattern:

using var mre = new ManualResetEvent(initialState: false); ... var testGenerator = new PipelineCallbackGenerator(ctx => { ctx.RegisterSourceOutput(ctx.SyntaxProvider.CreateSyntaxProvider<object>((s, _) => s is AssignmentExpressionSyntax, (c, _) => { mre.WaitOne(); return true; }), (spc, s) => { }); }).AsSourceGenerator(); ... while (!<did timer elapse fare enough>) { Thread.Sleep(1); } mre.Set();

src/Compilers/CSharp/Test/Semantic/SourceGeneration/GeneratorDriverTests.cs

azure-pipelines · 2022-04-05T21:02:49Z

Azure Pipelines successfully started running 4 pipeline(s).

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

cston · 2022-04-06T18:47:38Z

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

+        }
+
+        /// <summary>
+        /// The Generator that was running during the recorded time.


Generator

Consider using "generator" (lowercase) for consistency with other comments, or use <see cref="Generator"/>. #Closed

cston · 2022-04-06T18:50:04Z

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

+        /// <remarks>
+        /// This can be more than the sum of times in <see cref="GeneratorTimes"/> as it includes other costs such as setup.
+        /// </remarks>
+        public TimeSpan ElapsedTime { get; }


{ get; }

In the API proposal, these were fields rather than properties. Is the change expected?

Yes, it should have always been properties to match the other *Result[s] structs. I'll run it by API review in email to double check before merging though.

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

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

cston · 2022-04-06T23:09:16Z

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

+                        {
+                            if (kvp.Key != node)
+                            {
+                                result = result.Subtract(kvp.Value);


Subtract

Could we have subtracted off these times when calculating the time for _causedUpdate originally in GetSyntaxInputTable()?

Ooh, that's a really nice way to do it. Done.

src/Compilers/CSharp/Test/Semantic/SourceGeneration/GeneratorDriverTests.cs

src/Compilers/CSharp/Test/Semantic/SourceGeneration/SyntaxAwareGeneratorTests.cs

chsienki · 2022-04-25T19:00:59Z

/azp run

azure-pipelines · 2022-04-25T19:01:18Z

Azure Pipelines successfully started running 4 pipeline(s).

chsienki · 2022-04-25T20:39:36Z

@dotnet/roslyn-compiler for reviews please

cston · 2022-04-25T20:50:19Z

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

+                foreach (var node in inputNodes)
+                {
+                    // only add if this node ran at all during this pass
+                    if (_syntaxTimes.ContainsKey(node))


_syntaxTimes.ContainsKey(node)

Consider using _syntaxTimes.TryGetValue(out var value) to avoid two lookups. #Resolved

cston · 2022-04-25T21:24:40Z

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

+                                        var elapsed = sw.Elapsed;
+
+                                        // if this node isn't the one that caused the update, ensure we remember it and remove the time it took from the requester
+                                        if (syntaxInputBuilders[i].node != syntaxInputNode)


syntaxInputBuilders[i].node

Consider extracting a local. (If the local is created at the start of the for (...) body, it can be used in the catch below as well.) #Closed

cston · 2022-04-25T21:27:52Z

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

+                                        // if this node isn't the one that caused the update, ensure we remember it and remove the time it took from the requester
+                                        if (syntaxInputBuilders[i].node != syntaxInputNode)
+                                        {
+                                            _syntaxTimes[syntaxInputNode] = _syntaxTimes[syntaxInputNode].Subtract(elapsed);


_syntaxTimes[syntaxInputNode].Subtract(elapsed)

We're subtracting from _syntaxTimes[syntaxInputNode] but where did we add time for that node? #Closed

It gets set to TimeSpan.Zero on line 73. This is the node that actually asked for the update, and so got unfairly attributed all the time of the other nodes. We remove the other nodes time from zero, so its offset is actually negative (the sum of all the time we recorded for it that was actually processing other nodes) so that it gets its time reduced and every other node gets its time increased.

so its offset is actually negative

Does that mean _syntaxTimes[i] is actually an offset rather than the elapsed time for node i? If so, where is the elapsed time calculated? (Sorry if I'm misunderstanding.)

Yes, its an offset that gets applied to calculate the correct elapsed time. We do the actual timing in the generator driver here:

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

Line 261 in ab190e4

using var generatorTimer = CodeAnalysisEventSource.Log.CreateSingleGeneratorRunTimer(state.Generators[i], (t) => t.Add(syntaxStoreBuilder.GetRuntimeAdjustment(stateBuilder[i].InputNodes)));

That sits around the entire graph calculation operation for a given generator, but because we do the syntax nodes in parallel whenever the first one is requested, we have to adjust via the offset to ensure we actually have the correct times for each generator, and we don't unfairly claim that one generator was responsible for all the time taken to calculate syntax nodes, and the others took no time.

This integrates the source generator timing work, dotnet#60267, into the `/reportAnalyzer` framework. A sample of the new output from a simple `net7.0` console app is as follows: ``` Microsoft (R) Visual C# Compiler version 4.3.0-dev (<developer build>) Copyright (C) Microsoft Corporation. All rights reserved. warning CS2023: Ignoring /noconfig option because it was specified in a response file NOTE: Elapsed time may be less than analyzer execution time because analyzers can run concurrently. Total analyzer execution time: 0.303 seconds. Time (s) % Analyzer 0.248 81 Microsoft.CodeAnalysis.CSharp.NetAnalyzers, Version=7.0.6.21701, Culture=neutral, PublicKeyToken=31bf3856ad364e35 0.246 81 Microsoft.NetCore.CSharp.Analyzers.Runtime.CSharpDetectPreviewFeatureAnalyzer (CA2252) // trimmed output <0.001 <1 Microsoft.NetFramework.CSharp.Analyzers.CSharpSpecifyMessageBoxOptionsAnalyzer () 0.055 18 Microsoft.CodeAnalysis.NetAnalyzers, Version=7.0.6.21701, Culture=neutral, PublicKeyToken=31bf3856ad364e35 0.034 11 Microsoft.NetCore.Analyzers.InteropServices.PlatformCompatibilityAnalyzer (CA1416) // trimmed output <0.001 <1 Microsoft.CodeQuality.Analyzers.ApiDesignGuidelines.TypeNamesShouldNotMatchNamespacesAnalyzer (CA1724) Total generator execution time: 0.088 seconds. Time (s) % Generators 0.054 60 System.Text.Json.SourceGeneration, Version=7.0.6.22904, Culture=neutral, PublicKeyToken=cc7b13ffcd2ddd51 0.054 60 System.Text.Json.SourceGeneration.JsonSourceGenerator 0.016 18 System.Text.RegularExpressions.Generator, Version=7.0.6.22904, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a 0.016 18 System.Text.RegularExpressions.Generator.RegexGenerator ```

* Integrate generator times into /reportAnalyzer This integrates the source generator timing work, #60267, into the `/reportAnalyzer` framework. A sample of the new output from a simple `net7.0` console app is as follows: ``` Microsoft (R) Visual C# Compiler version 4.3.0-dev (<developer build>) Copyright (C) Microsoft Corporation. All rights reserved. warning CS2023: Ignoring /noconfig option because it was specified in a response file NOTE: Elapsed time may be less than analyzer execution time because analyzers can run concurrently. Total analyzer execution time: 0.303 seconds. Time (s) % Analyzer 0.248 81 Microsoft.CodeAnalysis.CSharp.NetAnalyzers, Version=7.0.6.21701, Culture=neutral, PublicKeyToken=31bf3856ad364e35 0.246 81 Microsoft.NetCore.CSharp.Analyzers.Runtime.CSharpDetectPreviewFeatureAnalyzer (CA2252) // trimmed output <0.001 <1 Microsoft.NetFramework.CSharp.Analyzers.CSharpSpecifyMessageBoxOptionsAnalyzer () 0.055 18 Microsoft.CodeAnalysis.NetAnalyzers, Version=7.0.6.21701, Culture=neutral, PublicKeyToken=31bf3856ad364e35 0.034 11 Microsoft.NetCore.Analyzers.InteropServices.PlatformCompatibilityAnalyzer (CA1416) // trimmed output <0.001 <1 Microsoft.CodeQuality.Analyzers.ApiDesignGuidelines.TypeNamesShouldNotMatchNamespacesAnalyzer (CA1724) Total generator execution time: 0.088 seconds. Time (s) % Generators 0.054 60 System.Text.Json.SourceGeneration, Version=7.0.6.22904, Culture=neutral, PublicKeyToken=cc7b13ffcd2ddd51 0.054 60 System.Text.Json.SourceGeneration.JsonSourceGenerator 0.016 18 System.Text.RegularExpressions.Generator, Version=7.0.6.22904, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a 0.016 18 System.Text.RegularExpressions.Generator.RegexGenerator ``` * PR feedback * PR feedback * PR feedback * Test failure * Fixed shared project file error The missing .projitems entries in the .shproj was causing solution explorer to not display the files in the shared projects. The SLN file changes are just VS reacting to the updates to the shared project files. * Fixup tests

chsienki added Area-Compilers New Feature - Source Generators Source Generators labels Mar 18, 2022

chsienki requested review from a team as code owners March 18, 2022 23:14

runfoapp bot mentioned this pull request Mar 21, 2022

Timeout on Microsoft.VisualStudio.LanguageServices.CSharp.UnitTests.dll tests #55638

Open

jasonmalinowski mentioned this pull request Mar 23, 2022

Detect SourceGenerator slowness and notify users to disable #55580

Open

chsienki mentioned this pull request Mar 23, 2022

Binlogs / cmdline should include generator timing info #60347

Closed

jasonmalinowski reviewed Mar 29, 2022

View reviewed changes

jasonmalinowski reviewed Apr 4, 2022

View reviewed changes

src/Compilers/CSharp/Test/Semantic/SourceGeneration/GeneratorDriverTests.cs Outdated Show resolved Hide resolved

chsienki mentioned this pull request Apr 6, 2022

Capture source generator statistics #59176

Open

cston reviewed Apr 6, 2022

View reviewed changes

src/Compilers/Core/Portable/SourceGeneration/RunResults.cs Outdated Show resolved Hide resolved

cston reviewed Apr 6, 2022

View reviewed changes

src/Compilers/Core/Portable/SourceGeneration/GeneratorTimerExtensions.cs Outdated Show resolved Hide resolved

cston reviewed Apr 6, 2022

View reviewed changes

src/Compilers/Core/Portable/SourceGeneration/SyntaxStore.cs Outdated Show resolved Hide resolved

cston reviewed Apr 6, 2022

View reviewed changes

src/Compilers/CSharp/Test/Semantic/SourceGeneration/GeneratorDriverTests.cs Show resolved Hide resolved

cston reviewed Apr 6, 2022

View reviewed changes

src/Compilers/CSharp/Test/Semantic/SourceGeneration/SyntaxAwareGeneratorTests.cs Outdated Show resolved Hide resolved

cston reviewed Apr 25, 2022

View reviewed changes

cston approved these changes Apr 26, 2022

View reviewed changes

RikkiGibson self-assigned this Apr 29, 2022

RikkiGibson approved these changes Apr 30, 2022

View reviewed changes

Add timing APIs

45db142

chsienki added 5 commits May 2, 2022 11:55

Correctly attribute syntax timing

1c9674a

Add extra test

1860d79

Fix overal generator time

f0c56ab

PR feedback

b703356

PR feedback

9a101dc

chsienki force-pushed the source-generators/timing-apis branch from ab190e4 to 9a101dc Compare May 2, 2022 18:55

chsienki enabled auto-merge (squash) May 2, 2022 20:06

chsienki merged commit 80814bf into dotnet:main May 2, 2022

ghost added this to the Next milestone May 2, 2022

Cosifne modified the milestones: Next, 17.3 P2 May 31, 2022

jaredpar mentioned this pull request Jun 2, 2022

Integrate generator times into /reportAnalyzer #61661

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Implement source generator timing APIs #60267

Implement source generator timing APIs #60267

chsienki commented Mar 18, 2022

chsienki commented Mar 21, 2022

jasonmalinowski Mar 29, 2022

chsienki Mar 29, 2022

jasonmalinowski Mar 29, 2022

chsienki Mar 29, 2022

jaredpar Mar 29, 2022

azure-pipelines bot commented Apr 5, 2022

cston Apr 6, 2022 •

edited

Loading

cston Apr 6, 2022

chsienki Apr 22, 2022

cston Apr 6, 2022

chsienki Apr 8, 2022

chsienki commented Apr 25, 2022

azure-pipelines bot commented Apr 25, 2022

chsienki commented Apr 25, 2022

cston Apr 25, 2022 •

edited

Loading

cston Apr 25, 2022 •

edited

Loading

cston Apr 25, 2022 •

edited

Loading

chsienki Apr 26, 2022

cston Apr 26, 2022

chsienki Apr 26, 2022

Implement source generator timing APIs #60267

Implement source generator timing APIs #60267

Conversation

chsienki commented Mar 18, 2022

chsienki commented Mar 21, 2022

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

azure-pipelines bot commented Apr 5, 2022

cston Apr 6, 2022 • edited Loading

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

chsienki commented Apr 25, 2022

azure-pipelines bot commented Apr 25, 2022

chsienki commented Apr 25, 2022

cston Apr 25, 2022 • edited Loading

Choose a reason for hiding this comment

cston Apr 25, 2022 • edited Loading

Choose a reason for hiding this comment

cston Apr 25, 2022 • edited Loading

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

cston Apr 6, 2022 •

edited

Loading

cston Apr 25, 2022 •

edited

Loading

cston Apr 25, 2022 •

edited

Loading

cston Apr 25, 2022 •

edited

Loading