85% of pre-Main startup with VS open is Runtime/Native EventSource constructors

[benaadams]

If Visual Studio is open on a .NET project; it registers for verbose .NET events #45059 (comment), causing all .NET programs system-wide to take additional time to start-up due to the additional Windows Etw time in the EventSource constructors.

For this minimal program it takes 282ms to start running Main and 300ms to get to Console.ReadKey (current 6.0 main branch)

using System;

Console.WriteLine("Press a key to exit");
Console.ReadKey();

86% (246ms) of that is the RuntimeEventSource constructor.

Data

Analysis

The majority of the time is RuntimeEventSource activating NativeEventSource and in there the majority is creating Manifests, Descriptors and Pipe Events.

All three are fixed data; however generated using reflection, StringBuilder and Encoding.UTF8 during startup.

The manifests and pipe events are byte arrays so could be created as ReadOnlySpan<byte> data sections by source generators.

The Event Descriptors also could be generated as regular new statements with source generators rather than using runtime reflection.

[ghost]

Tagging subscribers to this area: @tarekgh, @tommcdon, @pjanotti
See info in area-owners.md if you want to be subscribed.

Issue Details

---

For this minimal program it takes 282ms to start running Main and 300ms to get to Console.ReadKey (current 6.0 main branch)

using System;

Console.WriteLine("Press a key to exit");
Console.ReadKey();

86% (246ms) of that is the RuntimeEventSource constructor.

Data

Analysis

The majority of the time is RuntimeEventSource activating NativeEventSource and in there the majority is creating Manifests, Descriptors and Pipe Events.

All three are fixed data; however generated using reflection, StringBuilder and Encoding.UTF8 during startup.

The manifests and pipe events are byte arrays so could be created as ReadOnlySpan<byte> data sections by source generators.

The Event Descriptors also could be generated as regular new statements with source generators rather than using runtime reflection.

Author:	benaadams
Assignees:	-
Labels:	area-System.Diagnostics.Tracing, tenet-performance, untriaged
Milestone:	-

[stephentoub]

@benaadams, I realize it's a catch-22 from a measurement perspective, but the times you've cited are only when profiling, right? On my machine, a console app .exe created from dotnet new console takes ~90ms to run.

[benaadams]

created from dotnet new console takes ~90ms to run.

85% of that is probably still the EventSource constructors, so ~76ms? 🤔

[stephentoub]

85% of that is probably still the EventSource constructors, so ~76ms?

I suspect not. I think the EventSource times are significantly increased with the profiler attached because it's forcing them to do work they wouldn't otherwise do if the events weren't enabled.

[benaadams]

Does also depend if DoCommand is run; which does the manifest initialization, however... we've also established just having VS open on a .NET project will trigger that #45059 (comment), don't need to profile or have a debugger attached; so fits with "developer's inner loop startup" #44598?

[benaadams]

Either VS shouldn't register a system-wide event listener from just having a .NET project open (it adds two more when debugging #45059 (comment) so isn't that); or it should be much faster since it effects the activation of every .NET (5?) app regardless of whether its the one open in VS.

[benaadams]

Using sampling, which is less invasive and definitely doesn't trigger DoCommand

VS not open

VS open in background on a .NET project

As dotnet build -c Release for an exe project with 2 .csproj libs will spawn 4 .NET exes it starts to add up?

[benaadams]

Running dotnet build -c Release in runtime\src\libraries\System.Text.Json creates 66 dotnet processes; if its adding 167ms to each one (from above); that's 11 secs of extra time?

[AraHaan]

why so many dotnet.exe's 🤔

[benaadams]

why so many dotnet.exe's

dependencies in the project tree its building/checking to build

[brianrob]

@benaadams, question for you. Did you happen to have the VS performance tools open when you saw this, or was this just the result of having a VS window open?

[benaadams]

Did you happen to have the VS performance tools open when you saw this, or was this just the result of having a VS window open?

Just VS open; must also have a .NET project loaded however, doesn't register if its just open

[benaadams]

More specifically it looks to be "Microsoft-VisualStudio-Telemetry-PerfWatson2"

Logger Name:            Microsoft-VisualStudio-Telemetry-PerfWatson2-16356
Logger Id:              0x1d
Logger Thread Id:       000000000000421C
Guid:                   522e1583-3cbe-11eb-ad29-982cbc21eb61
Session Security:       ...
Buffer Size:            512 Kb
Maximum Buffers:        160
Minimum Buffers:        40
Number of Buffers:      40
Free Buffers:           34
Buffers Written:        162
Events Lost:            0
Log Buffers Lost:       0
Real Time Buffers Lost: 0
Real Time Consumers:    1
ClockType:              PerfCounter
Log Mode:               Sequential Realtime 
Hybrid Shutdown:        Stop
Maximum File Size:      not set
Buffer Flush Timer:     1 secs
Log Filename:           

Enabled Providers:
Guid                                  Level  Flags               Enable Properties
----------------------------------------------------------------------------------
641d7f6c-481c-42e8-ab7e-d18dc5e5cb9e      5  0xffffffffffffffff  EnableKeywordZero 
4e17e413-3c0c-4c2a-a531-c1799a05ad7c      5  0x0000000000000067  EnableKeywordZero 
e13c0d23-ccbc-4e12-931b-d9cc2eee27e4      5  0x0000000000000099  EnableKeywordZero 
589491ba-4f15-53fe-c376-db7f020f5204      5  0xffffffffffffffff  EnableKeywordZero 
a669021c-c450-4609-a035-5af59af4df18      5  0x0000000000000098  EnableKeywordZero 
ee328c6f-4c94-45f7-acaf-640c6a447654      5  0x0000000000000004  EnableKeywordZero 
Total of 6 providers

3rd provider e13c0d23-ccbc-4e12-931b-d9cc2eee27e4

[benaadams]

Does look like I could opt out of the "Visual Studio Customer Experience Improvement Program" to disable it; but I'd assume its preferred to stay in... 😉

[brianrob]

Totally. Reaching out to the VS folks on this, and will report back.

[stephentoub]

We're working with the VS folks to reduce the scope of the tracing from PerfWatson to just the devenv process.

@sywhang is also working on a source generator for EventSource, though the initial scope of that will just be for the ones in System.Private.CoreLib. That's covered by #49659, and builds on the work you did, @benaadams.

Is there anything further highlighted in this issue to be addressed?

Thanks!

[benaadams]

Is there anything further highlighted in this issue to be addressed?

No, those should address it

[tommcdon]

Closing this issue since the outstanding runtime work is tracked #49659, and the VS PerfWatson investigation is being tracked internally. Please feel free to let us know if we should re-activate.