Add event tracing to NuGet.Common and write events for the NuGet-based MSBuid project SDK resolver

[jeffkl]

Bug

Fixes: NuGet/Home#11445

Regression? Last working version:

Description

This adds a new EventSource to NuGet.Common and writes events for the NuGet-based MSBuild project SDK resolver.

I also implemented the following Keywords:

Keyword	Purpose
Common	Any event coming from a component in the NuGet.Common namespace
Configuration	Any event coming from a component in the NuGet.Configuration namespace
Logging	Any event that is logging a message
Performance	Any event related to measuring performance
SdkResolver	Any event coming from a component in the NuGet-based MSBuild project SDK resolver

This will allow users to filter out potential components that aren't necessary for a particular trace.

Users will be able to enable the tracing with tools like PerfView:

PerfView /OnlyProviders=*Microsoft-NuGet run dotnet restore

The resulting Event Trace Log (.etl) will be useful when diagnosing issues with it. The above command also includes traces from MSBuild and there are additional sources like Visual Studio which include more information.

Here is a sample trace log you can view in tools like PerfView:
PerfViewData.etl.zip

Its also possible to create these traces with Visual Studio and dotnet trace

PR Checklist

• PR has a meaningful title

• PR has a linked issue.

• Described changes

• Tests

  • Automated tests added
  • OR
  • Test exception
  • OR
  • N/A

• Documentation

  • Documentation PR or issue filled
  • OR
  • N/A

[jeffkl]

FYI @ladipro and @lifengl

[jeffkl]

@zivkan and @nkolev92 so if I update this and move the event provider to NuGet.Common, make it public, update the event names, then fire the events where needed, you'll approve?

[nkolev92]

I like that idea.

@zivkan has some experience with the events and he did a lot of work on the VS side with, so he's probably the best person to review it.

[zivkan]

Yes, I'd approve without hesitation. I've been thinking about how we can monitor NuGet better since mid to late 2020, but there's always higher priority work. But adding an EventSource so we can start using it more is very much needed. It probably would have been nice to add some instrumentation into NuGetAudit to get detailed perf & diagnostic data in case someone ends up reporting a difficult to reproduce bug.

The only thing I haven't thought about is naming conventions for events. If we're going to have all NuGet assemblies using one provider, we need event names to include the assembly name, or feature area, so we don't end up with dumb event names like NuGet/ReadFile/Start and we don't know if it's reading a config file, or http cache file, or global.json, or something else. While we can put the filename being read as an event property, if I'm trying to investigate slow or failing nuget.config load errors, I don't want global.json and http cache reads spamming the event list, so I think it's better to have more events. From memory, ETW has a max of 32k events allowed per provider. We're not going to reach that limit.

Since the EventSource will unfortunately need to be in NuGet.Common's public API, my advice is to have a public EventSource instance, which we will call .Write( on. Similar to what I already added in our VS code:

NuGet.Client/src/NuGet.Clients/NuGet.VisualStudio.Common/Etw/NuGetETW.cs

Line 16 in 11a6217

public static EventSource ExtensibilityEventSource { get; } = new EventSource(ExtensibilityEventSourceName);

While this PR's first iteration uses a class that extends EventSource, and adds methods to make emiting the events nicer, since we need to make our common provider part of our client SDK's public API, I don't think we should need to change public APIs every time someone adds/removes/modifies some EventSource event. Not only will it reduce PR workload, but it also makes NuGet much less fragile to mismatched dll versions. While we could argue that anyone using the CLient SDK should use the same package version for all the packages, I'd rather not introduce this as potential failure.

[jeffkl]

This has now been moved to NuGet.Common.

[nkolev92]

LGTM.

The only thing I could think of is whether the EventKeywords need to be defined in common instead maybe in the assemblies themselves.

[jeffkl]

The only thing I could think of is whether the EventKeywords need to be defined in common instead maybe in the assemblies themselves.

Keywords have to be a flags so I was worried that if they weren't declared in one place then we could end up with collisions. I can move them but their just constants that we'll never change so I wasn't as worried about them being part of the public API