Miscellaneous event tweaks

[rainersigwald]

• Make EvaluateStop event adjacent to EvaluateStart

  It's not well documented, but EventSource requires that the start and stop event IDs for a single thing be separated by exactly one. Since this one didn't, we weren't getting DURATION_MSEC computed for overall evaluation time in our traces.

  See https://github.com/dotnet/runtime/blob/f83a9d9689433ce522b91e74a9631c83847e3b64/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs#L3270.

• Update Evaluate* event doc comments

• Include EvaluateStart/Stop in DOTNET_PERFLOG

• Drop Parse from DOTNET_PERFLOG

[Forgind]

LGTM

[Forgind]

I don't think the previous comment was particularly helpful, but I'm not sure this one is either. It just sounds like an English version of "projectFile for Evaluate," which you could get from the parameter's name and the function name. Be nice if we could just drop them, but I'm guessing some style checker would complain.

[ladipro]

Is this why the event names were surfaced inconsistently by tools like PerfView?

Evaluate/Start
EvaluateStop/Stop

Can this change break tools relying on the old names, for example:
https://github.com/dotnet/performance/blob/83f1fa22571b6fc4cd054b6ef07e647f12eb6efe/src/tools/ScenarioMeasurement/Startup/InnerLoopMsBuildParser.cs#L107-L115

[rainersigwald]

Is this why the event names were surfaced inconsistently by tools like PerfView?

Evaluate/Start

EvaluateStop/Stop

That is exactly the case that caused me to ask about this and ask for help from @josalem who figured out the mismatch.

Can this change break tools relying on the old names, for example:

https://github.com/dotnet/performance/blob/83f1fa22571b6fc4cd054b6ef07e647f12eb6efe/src/tools/ScenarioMeasurement/Startup/InnerLoopMsBuildParser.cs#L107-L115

Yes, I think so. Do you or @DrewScoggins have an objection to fixing it here and following up with a fix there? I think we could possibly have a redundant stop event to preserve name compat but ideally not for the long term.

[josalem]

dotnet/performance@83f1fa2/src/tools/ScenarioMeasurement/Startup/InnerLoopMsBuildParser.cs#L107-L115

Yes, that code will break with this change, because the events should now show up as Evaluate/Start and Evaluate/Stop. Other code shouldn't break becuase the event names aren't changing. If code relied on the eventIDs, then you may need to change things. The EventSource will send a manifest along with the events, so you should know in advance which events you will see.

If you make this change, you may need to update any readers to account for the name change in Evaluate/* events, but also still work with the old manifest.

For some clarity here, EventSource:

1. takes all of the methods not decorated with NonEventAttribute
2. iterates them in declaration order
3. creates a task named EventName whenever if finds a method named EventNameStart
4. adds the Stop event IFF the next event is named EventNameStop.

The odd behavior prior to this patch (having an EvaluateStop/Stop event+task) is because EvaluateStop was defined later in the class with an event ID that wasn't EvaluateStart's ID + 1.

Another way to fix this would be to explicitly define your tasks by adding a nested class named Tasks and assigning a task to your events directly, e.g.,

public sealed MySource : EventSource
{
	public class Tasks
	{
		public const EventTask MyTask = (EventTask)1;
	}

	[Event(1, OpCode=OpCode.Start, Task=Tasks.MyTask, ...)]
	public void MyEventStart() => WriteEvent(1);

	// ...

	[Event(N, OpCode=OpCode.Stop, Task=Tasks.MyTask, ...)]
	public void MyEventStop() => WriteEvent(N);
}

[DrewScoggins]

I am happy to make the change on our side, as long as I get a clear list of all of the new names of the events, but I am a little concerned about the breaking change in and of itself.

• What is the extent of the impact to our customers?
• Do we have a good method for communicating this break to our customers?
• Do we plan to backport this change to older versions of MSBuild?

[benvillalobos]

What does Keywords.PerformanceLog do here, and why remove it from ParseStartStop?

[rainersigwald]

Events tagged with PerformanceLog are included in the text perf log emitted when configured (#5861).

As to why remove this, I put this in the commit message

It's pretty rare that the XML parse phase of project load is a significant part of evaluation time; it's usually a tiny fraction of overall evaluation.

[rainersigwald]

Tested this with a fresh build of MSBuild and it looks good to me:

Another way to fix this would be to explicitly define your tasks by adding a nested class named Tasks and assigning a task to your events directly, e.g.,

This would be just as breaking for consumers who have strings like EvaluateStop/Stop, right?

• What is the extent of the impact to our customers?

I am not aware of direct impact to customers; these ETW events are primarily for the dev team's use when investigating and this feels to me like a straightforward bug fix.

• Do we have a good method for communicating this break to our customers?

We can include it in our release notes; I don't think this rises to the level of interest of the overall VS or .NET 6 release notes.

• Do we plan to backport this change to older versions of MSBuild?

I do not, but we conceivably could. Is it important enough to do so?

[DrewScoggins]

• What is the extent of the impact to our customers?

I am not aware of direct impact to customers; these ETW events are primarily for the dev team's use when investigating and this feels to me like a straightforward bug fix.

• Do we have a good method for communicating this break to our customers?

We can include it in our release notes; I don't think this rises to the level of interest of the overall VS or .NET 6 release notes.

• Do we plan to backport this change to older versions of MSBuild?

I do not, but we conceivably could. Is it important enough to do so?

SGTM

[rainersigwald]

@brianrob also pointed out offline that the compat bar would be higher if these events were documented. I don't think we've documented them and couldn't find any evidence of them on docs.microsoft.com, for example searching for "Microsoft-Build" EvaluateCondition.

I think we should go ahead.

[Forgind]

Well...
https://github.com/dotnet/msbuild/blob/main/documentation/specs/event-source.md

It doesn't seem to have been updated for a while, but there is some Microsoft-endorsed documentation on them.

I still agree with going ahead but thought I should throw that out there. I don't think that's even the right folder 😁