From 11f08511b253bc0bf37adeaa94ac60d5974d0cfe Mon Sep 17 00:00:00 2001 From: Rainer Sigwald Date: Mon, 2 Aug 2021 15:37:26 -0500 Subject: [PATCH 1/4] 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. --- src/Framework/MSBuildEventSource.cs | 26 +++++++++++++------------- 1 file changed, 13 insertions(+), 13 deletions(-) diff --git a/src/Framework/MSBuildEventSource.cs b/src/Framework/MSBuildEventSource.cs index 859e78fd133..0392569afd8 100644 --- a/src/Framework/MSBuildEventSource.cs +++ b/src/Framework/MSBuildEventSource.cs @@ -112,91 +112,91 @@ public void EvaluateStart(string projectFile) /// Relevant information about where in the run of the progam it is. [Event(12, Keywords = Keywords.All)] - public void EvaluatePass0Start(string projectFile) + public void EvaluateStop(string projectFile) { WriteEvent(12, projectFile); } /// Relevant information about where in the run of the progam it is. [Event(13, Keywords = Keywords.All)] - public void EvaluatePass0Stop(string projectFile) + public void EvaluatePass0Start(string projectFile) { WriteEvent(13, projectFile); } /// Relevant information about where in the run of the progam it is. [Event(14, Keywords = Keywords.All)] - public void EvaluatePass1Start(string projectFile) + public void EvaluatePass0Stop(string projectFile) { WriteEvent(14, projectFile); } /// Relevant information about where in the run of the progam it is. [Event(15, Keywords = Keywords.All)] - public void EvaluatePass1Stop(string projectFile) + public void EvaluatePass1Start(string projectFile) { WriteEvent(15, projectFile); } /// Relevant information about where in the run of the progam it is. [Event(16, Keywords = Keywords.All)] - public void EvaluatePass2Start(string projectFile) + public void EvaluatePass1Stop(string projectFile) { WriteEvent(16, projectFile); } /// Relevant information about where in the run of the progam it is. [Event(17, Keywords = Keywords.All)] - public void EvaluatePass2Stop(string projectFile) + public void EvaluatePass2Start(string projectFile) { WriteEvent(17, projectFile); } /// Relevant information about where in the run of the progam it is. [Event(18, Keywords = Keywords.All)] - public void EvaluatePass3Start(string projectFile) + public void EvaluatePass2Stop(string projectFile) { WriteEvent(18, projectFile); } /// Relevant information about where in the run of the progam it is. [Event(19, Keywords = Keywords.All)] - public void EvaluatePass3Stop(string projectFile) + public void EvaluatePass3Start(string projectFile) { WriteEvent(19, projectFile); } /// Relevant information about where in the run of the progam it is. [Event(20, Keywords = Keywords.All)] - public void EvaluatePass4Start(string projectFile) + public void EvaluatePass3Stop(string projectFile) { WriteEvent(20, projectFile); } /// Relevant information about where in the run of the progam it is. [Event(21, Keywords = Keywords.All)] - public void EvaluatePass4Stop(string projectFile) + public void EvaluatePass4Start(string projectFile) { WriteEvent(21, projectFile); } /// Relevant information about where in the run of the progam it is. [Event(22, Keywords = Keywords.All)] - public void EvaluatePass5Start(string projectFile) + public void EvaluatePass4Stop(string projectFile) { WriteEvent(22, projectFile); } /// Relevant information about where in the run of the progam it is. [Event(23, Keywords = Keywords.All)] - public void EvaluatePass5Stop(string projectFile) + public void EvaluatePass5Start(string projectFile) { WriteEvent(23, projectFile); } /// Relevant information about where in the run of the progam it is. [Event(24, Keywords = Keywords.All)] - public void EvaluateStop(string projectFile) + public void EvaluatePass5Stop(string projectFile) { WriteEvent(24, projectFile); } From b298e8e5a1d666ec4884c0589d514184c01c931c Mon Sep 17 00:00:00 2001 From: Rainer Sigwald Date: Mon, 2 Aug 2021 15:42:49 -0500 Subject: [PATCH 2/4] Update Evaluate* event doc comments --- src/Framework/MSBuildEventSource.cs | 32 ++++++++++++++--------------- 1 file changed, 16 insertions(+), 16 deletions(-) diff --git a/src/Framework/MSBuildEventSource.cs b/src/Framework/MSBuildEventSource.cs index 0392569afd8..64e92106e3d 100644 --- a/src/Framework/MSBuildEventSource.cs +++ b/src/Framework/MSBuildEventSource.cs @@ -103,98 +103,98 @@ public void EvaluateConditionStop(string condition, bool result) /// /// Call this method to notify listeners of how the project data was evaluated. /// - /// Relevant information about where in the run of the progam it is. + /// Filename of the project being evaluated. [Event(11, Keywords = Keywords.All)] public void EvaluateStart(string projectFile) { WriteEvent(11, projectFile); } - /// Relevant information about where in the run of the progam it is. + /// Filename of the project being evaluated. [Event(12, Keywords = Keywords.All)] public void EvaluateStop(string projectFile) { WriteEvent(12, projectFile); } - /// Relevant information about where in the run of the progam it is. + /// Filename of the project being evaluated. [Event(13, Keywords = Keywords.All)] public void EvaluatePass0Start(string projectFile) { WriteEvent(13, projectFile); } - /// Relevant information about where in the run of the progam it is. + /// Filename of the project being evaluated. [Event(14, Keywords = Keywords.All)] public void EvaluatePass0Stop(string projectFile) { WriteEvent(14, projectFile); } - /// Relevant information about where in the run of the progam it is. + /// Filename of the project being evaluated. [Event(15, Keywords = Keywords.All)] public void EvaluatePass1Start(string projectFile) { WriteEvent(15, projectFile); } - /// Relevant information about where in the run of the progam it is. + /// Filename of the project being evaluated. [Event(16, Keywords = Keywords.All)] public void EvaluatePass1Stop(string projectFile) { WriteEvent(16, projectFile); } - /// Relevant information about where in the run of the progam it is. + /// Filename of the project being evaluated. [Event(17, Keywords = Keywords.All)] public void EvaluatePass2Start(string projectFile) { WriteEvent(17, projectFile); } - /// Relevant information about where in the run of the progam it is. + /// Filename of the project being evaluated. [Event(18, Keywords = Keywords.All)] public void EvaluatePass2Stop(string projectFile) { WriteEvent(18, projectFile); } - /// Relevant information about where in the run of the progam it is. + /// Filename of the project being evaluated. [Event(19, Keywords = Keywords.All)] public void EvaluatePass3Start(string projectFile) { WriteEvent(19, projectFile); } - /// Relevant information about where in the run of the progam it is. + /// Filename of the project being evaluated. [Event(20, Keywords = Keywords.All)] public void EvaluatePass3Stop(string projectFile) { WriteEvent(20, projectFile); } - /// Relevant information about where in the run of the progam it is. + /// Filename of the project being evaluated. [Event(21, Keywords = Keywords.All)] public void EvaluatePass4Start(string projectFile) { WriteEvent(21, projectFile); } - /// Relevant information about where in the run of the progam it is. + /// Filename of the project being evaluated. [Event(22, Keywords = Keywords.All)] public void EvaluatePass4Stop(string projectFile) { WriteEvent(22, projectFile); } - /// Relevant information about where in the run of the progam it is. + /// Filename of the project being evaluated. [Event(23, Keywords = Keywords.All)] public void EvaluatePass5Start(string projectFile) { WriteEvent(23, projectFile); } - /// Relevant information about where in the run of the progam it is. + /// Filename of the project being evaluated. [Event(24, Keywords = Keywords.All)] public void EvaluatePass5Stop(string projectFile) { @@ -278,14 +278,14 @@ public void RarLogResultsStop() /// /// Call this method to notify listeners of profiling for the function that parses an XML document into a ProjectRootElement. /// - /// Relevant information about where in the run of the progam it is. + /// Filename of the project being evaluated. [Event(33, Keywords = Keywords.All | Keywords.PerformanceLog)] public void ParseStart(string projectFileName) { WriteEvent(33, projectFileName); } - /// Relevant information about where in the run of the progam it is. + /// Filename of the project being evaluated. [Event(34, Keywords = Keywords.All | Keywords.PerformanceLog)] public void ParseStop(string projectFileName) { From 326fd95183c6f2e2529fd7ca94c1287bdde6ad6c Mon Sep 17 00:00:00 2001 From: Rainer Sigwald Date: Mon, 2 Aug 2021 15:51:32 -0500 Subject: [PATCH 3/4] Include EvaluateStart/Stop in DOTNET_PERFLOG This is a more critical measure than Parse, which is XML->memory, because it includes imports, SDK resolution, and MSBuild logic. --- src/Framework/MSBuildEventSource.cs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/Framework/MSBuildEventSource.cs b/src/Framework/MSBuildEventSource.cs index 64e92106e3d..e9110b437a5 100644 --- a/src/Framework/MSBuildEventSource.cs +++ b/src/Framework/MSBuildEventSource.cs @@ -104,14 +104,14 @@ public void EvaluateConditionStop(string condition, bool result) /// Call this method to notify listeners of how the project data was evaluated. /// /// Filename of the project being evaluated. - [Event(11, Keywords = Keywords.All)] + [Event(11, Keywords = Keywords.All | Keywords.PerformanceLog)] public void EvaluateStart(string projectFile) { WriteEvent(11, projectFile); } /// Filename of the project being evaluated. - [Event(12, Keywords = Keywords.All)] + [Event(12, Keywords = Keywords.All | Keywords.PerformanceLog)] public void EvaluateStop(string projectFile) { WriteEvent(12, projectFile); From 46690ea604ec1a61b87b4efc9e3b8ef04d1515dc Mon Sep 17 00:00:00 2001 From: Rainer Sigwald Date: Mon, 2 Aug 2021 15:52:43 -0500 Subject: [PATCH 4/4] Drop Parse from DOTNET_PERFLOG It's pretty rare that the XML parse phase of project load is a signifcant part of evaluation time; it's usually a tiny fraction of overall evaluation. --- src/Framework/MSBuildEventSource.cs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/Framework/MSBuildEventSource.cs b/src/Framework/MSBuildEventSource.cs index e9110b437a5..28a5833f479 100644 --- a/src/Framework/MSBuildEventSource.cs +++ b/src/Framework/MSBuildEventSource.cs @@ -279,14 +279,14 @@ public void RarLogResultsStop() /// Call this method to notify listeners of profiling for the function that parses an XML document into a ProjectRootElement. /// /// Filename of the project being evaluated. - [Event(33, Keywords = Keywords.All | Keywords.PerformanceLog)] + [Event(33, Keywords = Keywords.All)] public void ParseStart(string projectFileName) { WriteEvent(33, projectFileName); } /// Filename of the project being evaluated. - [Event(34, Keywords = Keywords.All | Keywords.PerformanceLog)] + [Event(34, Keywords = Keywords.All)] public void ParseStop(string projectFileName) { WriteEvent(34, projectFileName);