Add more events to SDK resolution

[jeffkl]

Fixes #7136

Context

Second attempt at adding more ETW events for SDK resolution.

Changes Made

• Add events around the CachingSdkResolverService
• Add flag tracking whether or not an SDK resolution came from cache
• Add note to MSBuildEventSource reminding us that you must rev the version of an event when changing the method signature

Testing

Ran locally built msbuild.exe with perfview and verified the events show up properly.

Notes

[rainersigwald]

Overall looks fine to me, but I wonder: should we expose an IsEnabled that wraps our own functionality there? We use that internally when building the objects to send to ETW is nontrivial, as it will likely be to assemble these single strings (since that's the only way to customize the messages).

For example,

msbuild/src/Build/BackEnd/Components/RequestBuilder/RequestBuilder.cs

Lines 1169 to 1172 in 09bdfae

	if (MSBuildEventSource.Log.IsEnabled())
	{
	MSBuildEventSource.Log.BuildProjectStop(_requestEntry.RequestConfiguration.ProjectFullPath, string.Join(", ", allTargets));
	}

[jeffkl]

I wonder: should we expose an IsEnabled that wraps our own functionality there?

The couple of new events just end up logging the same data (project name, solution path, etc), do you see one that is of particular concern to be expensive?

I am not 100% happy with how I'm tracking whether or not a particular resolution is cached. I'm introducing a new bool and setting it in the Lazy<T> which will capture context and potentially be slower. But I really want to know how many SDKs are actually looked up vs cached. Does anyone have any bright ideas? I thought about just not firing the Stop event for a cached result and only for actual look ups, but then we can't measure how long it took to get a cached result in the case where a thread is waiting for a lock due to simultaneous SDK resolutions. My current implementation works but it smells fishy to me...

[rainersigwald]

The couple of new events just end up logging the same data (project name, solution path, etc), do you see one that is of particular concern to be expensive?

Constructing the single string will create garbage, but presumably not all that much. It's just concatenation of a bunch of already-existing stuff?

[jeffkl]

Constructing the single string will create garbage, but presumably not all that much. It's just concatenation of a bunch of already-existing stuff?

I'm confused, where is the code constructing a string out of other data? Its just passing properties that come in from the SDK resolution APIs. I'm assuming if tracing is off, the ETW APIs just no-op so we don't have to avoid calling them if tracing is off? Or am completely wrong about all that? 😕

[rainersigwald]

Its just passing properties that come in from the SDK resolution APIs. I'm assuming if tracing is off, the ETW APIs just no-op so we don't have to avoid calling them if tracing is off?

That's true, the ETW APIs are very lightweight if the events are disabled. However, the .NET runtime doesn't know about that, so it has to fully realize arguments

The case I'm trying to avoid is:

// In SDK resolver

WriteEvent(s1 + s2 + s3);

// or

WriteEvent($"Some formatting string with {holes} that {get} {filled}");

// or worst case

WriteEvent(ExpensiveMethodThatDoesABunchOfWork());

[jeffkl]

Yeah okay I totally understand, we don't want to do string formatting of any kind that will allocate just to call a method that no-ops. I don't think any of the code paths I'm adding here are doing that, they all take existing objects and pass them directly to ETW APIs.

[rainersigwald]

Ah, I've been unclear: none of the APIs in this PR are bad on this front. My question is: does this encourage/require bad behavior in the resolvers because of the API shape we're exposing?

[jeffkl]

Ah, I've been unclear: none of the APIs in this PR are bad on this front. My question is: does this encourage/require bad behavior in the resolvers because of the API shape we're exposing?

Okay I finally understand what you mean. That's a valid concern, callers could end up building expensive strings that aren't actually used. My original implementation tried to accept params object[] args but that caused ETW schema errors. I tried using string[] instead but that didn't work either. I read through the documentation to see if there was any guidance and then I came to this realization:

The ETW API is not designed to allow external code to contribute to your events!

So I'm removing all of the code around allowing SDK resolvers to contribute their own events. Instead, I'll just add my own EventSource to the NuGet-based SDK resolver. Events will still show up in the same trace as long as you specify the correct provider name. And then I'll get to specify whatever data I want :)

[rainersigwald]

Is this still a thing?