From 1b960f4a9fb38263b70b4510eb6b7e948b6eea26 Mon Sep 17 00:00:00 2001 From: Brian Robbins Date: Wed, 26 Aug 2020 14:42:21 -0700 Subject: [PATCH 1/8] Fix inadvertent call to MSBuildExeStop. --- src/MSBuild/XMake.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/MSBuild/XMake.cs b/src/MSBuild/XMake.cs index 749f3a2b681..c7220881a5c 100644 --- a/src/MSBuild/XMake.cs +++ b/src/MSBuild/XMake.cs @@ -525,7 +525,7 @@ string [] commandLine MSBuildEventSource.Log.MSBuildExeStart(commandLine); #else if (MSBuildEventSource.Log.IsEnabled()) { - MSBuildEventSource.Log.MSBuildExeStop(string.Join(" ", commandLine)); + MSBuildEventSource.Log.MSBuildExeStart(string.Join(" ", commandLine)); } #endif Console.CancelKeyPress += cancelHandler; From fca5b3227f86f184160311dbfe96f0ae2d19fb25 Mon Sep 17 00:00:00 2001 From: Brian Robbins Date: Wed, 26 Aug 2020 14:28:05 -0700 Subject: [PATCH 2/8] Implement a text-based performance log. --- src/Framework/MSBuildEventSource.cs | 25 ++-- src/MSBuild/MSBuild.csproj | 1 + src/MSBuild/PerformanceLogEventListener.cs | 161 +++++++++++++++++++++ src/MSBuild/XMake.cs | 23 +-- 4 files changed, 190 insertions(+), 20 deletions(-) create mode 100644 src/MSBuild/PerformanceLogEventListener.cs diff --git a/src/Framework/MSBuildEventSource.cs b/src/Framework/MSBuildEventSource.cs index 5d73b6aa153..2e153fb5cb7 100644 --- a/src/Framework/MSBuildEventSource.cs +++ b/src/Framework/MSBuildEventSource.cs @@ -8,6 +8,11 @@ namespace Microsoft.Build.Eventing [EventSource(Name = "Microsoft-Build")] internal sealed class MSBuildEventSource : EventSource { + public static class Keywords + { + public const EventKeywords PerformanceLog = (EventKeywords)0x1; + } + /// /// define the singleton instance of the event source /// @@ -244,14 +249,14 @@ public void ExpandGlobStop(string rootDirectory, string glob, string excludedPat /// Call this method to notify listeners of timing related to loading an XmlDocumentWithLocation from a path. /// Path to the document to load. /// - [Event(29)] + [Event(29, Keywords = Keywords.PerformanceLog)] public void LoadDocumentStart(string fullPath) { WriteEvent(29, fullPath); } /// Path to the document to load. - [Event(30)] + [Event(30, Keywords = Keywords.PerformanceLog)] public void LoadDocumentStop(string fullPath) { WriteEvent(30, fullPath); @@ -273,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. - [Event(33)] + [Event(33, Keywords = Keywords.PerformanceLog)] public void ParseStart(string projectFileName) { WriteEvent(33, projectFileName); } /// Relevant information about where in the run of the progam it is. - [Event(34)] + [Event(34, Keywords = Keywords.PerformanceLog)] public void ParseStop(string projectFileName) { WriteEvent(34, projectFileName); @@ -301,13 +306,13 @@ public void RarRemoveReferencesMarkedForExclusionStop() WriteEvent(36); } - [Event(37)] + [Event(37, Keywords = Keywords.PerformanceLog)] public void RequestThreadProcStart() { WriteEvent(37); } - [Event(38)] + [Event(38, Keywords = Keywords.PerformanceLog)] public void RequestThreadProcStop() { WriteEvent(38); @@ -328,14 +333,14 @@ public void SaveStop(string fileLocation) } /// The name of the target being executed. - [Event(43)] + [Event(43, Keywords = Keywords.PerformanceLog)] public void TargetStart(string targetName) { WriteEvent(43, targetName); } /// The name of the target being executed. - [Event(44)] + [Event(44, Keywords = Keywords.PerformanceLog)] public void TargetStop(string targetName) { WriteEvent(44, targetName); @@ -345,14 +350,14 @@ public void TargetStop(string targetName) /// Call this method to notify listeners of the start of a build as called from the command line. /// /// The command line used to run MSBuild. - [Event(45)] + [Event(45, Keywords = Keywords.PerformanceLog)] public void MSBuildExeStart(string commandLine) { WriteEvent(45, commandLine); } /// The command line used to run MSBuild. - [Event(46)] + [Event(46, Keywords = Keywords.PerformanceLog)] public void MSBuildExeStop(string commandLine) { WriteEvent(46, commandLine); diff --git a/src/MSBuild/MSBuild.csproj b/src/MSBuild/MSBuild.csproj index 3bf42162617..a6f0873dac4 100644 --- a/src/MSBuild/MSBuild.csproj +++ b/src/MSBuild/MSBuild.csproj @@ -194,6 +194,7 @@ + true diff --git a/src/MSBuild/PerformanceLogEventListener.cs b/src/MSBuild/PerformanceLogEventListener.cs new file mode 100644 index 00000000000..23406bc2195 --- /dev/null +++ b/src/MSBuild/PerformanceLogEventListener.cs @@ -0,0 +1,161 @@ +using System; +using System.Diagnostics; +using System.Diagnostics.Tracing; +using System.IO; +using System.Text; +using Microsoft.Build.Eventing; + +namespace Microsoft.Build.CommandLine +{ + internal sealed class PerformanceLogEventListener : EventListener + { + internal struct ProviderConfiguration + { + internal string Name { get; set; } + internal EventKeywords Keywords { get; set; } + internal EventLevel Level { get; set; } + } + + private static ProviderConfiguration[] s_config = new ProviderConfiguration[] + { + new ProviderConfiguration() + { + Name = "Microsoft-Build", + Keywords = MSBuildEventSource.Keywords.PerformanceLog, + Level = EventLevel.Verbose + } + }; + + private const string PerfLogDirEnvVar = "DOTNET_PERFLOG_DIR"; + private const char EventDelimiter = '\n'; + private string _processIDStr; + private StreamWriter _writer; + + [ThreadStatic] + private static StringBuilder s_builder; + + internal static PerformanceLogEventListener Create() + { + PerformanceLogEventListener eventListener = null; + try + { + // Initialization happens as a separate step and not in the constructor to ensure that + // if an exception is thrown during init, we have the opportunity to dispose of the listener, + // which will disable any EventSources that have been enabled. Any EventSources that existed before + // this EventListener will be passed to OnEventSourceCreated before our constructor is called, so + // we if we do this work in the constructor, and don't get an opportunity to call Dispose, the + // EventSources will remain enabled even if there aren't any consuming EventListeners. + + // Check to see if we should enable the event listener. + string logDirectory = Environment.GetEnvironmentVariable(PerfLogDirEnvVar); + if (Directory.Exists(logDirectory)) + { + eventListener = new PerformanceLogEventListener(); + eventListener.Initialize(logDirectory); + } + } + catch + { + if (eventListener != null) + { + eventListener.Dispose(); + } + } + + return eventListener; + } + + private PerformanceLogEventListener() + { + } + + internal void Initialize(string logDirectory) + { + _processIDStr = Process.GetCurrentProcess().Id.ToString(); + + // Use a GUID disambiguator to make sure that we have a unique file name. + string logFilePath = Path.Combine(logDirectory, $"perf-{_processIDStr}-{Guid.NewGuid().ToString("N")}.log"); + + Stream outputStream = new FileStream( + logFilePath, + FileMode.Create, // Create or overwrite. + FileAccess.Write, // Open for writing. + FileShare.Read, // Allow others to read. + 4096, // Default buffer size. + FileOptions.None); // No hints about how the file will be written. + + _writer = new StreamWriter(outputStream); + } + + public override void Dispose() + { + lock (this) + { + if (_writer != null) + { + _writer.Dispose(); + _writer = null; + } + } + + base.Dispose(); + } + + protected override void OnEventSourceCreated(EventSource eventSource) + { + try + { + // Enable the provider if it matches a requested configuration. + foreach (ProviderConfiguration entry in s_config) + { + if (entry.Name.Equals(eventSource.Name)) + { + EnableEvents(eventSource, entry.Level, entry.Keywords); + } + } + } + catch + { + // If we fail to enable, just skip it and continue. + } + + base.OnEventSourceCreated(eventSource); + } + + protected override void OnEventWritten(EventWrittenEventArgs eventData) + { + try + { + if (s_builder == null) + { + s_builder = new StringBuilder(); + } + else + { + s_builder.Clear(); + } + + s_builder.Append($"[{DateTime.UtcNow.ToString("o")}] Event={eventData.EventSource.Name}/{eventData.EventName} ProcessID={_processIDStr} ThreadID={System.Threading.Thread.CurrentThread.ManagedThreadId}\t "); + for (int i = 0; i < eventData.PayloadNames.Count; i++) + { + s_builder.Append($"{eventData.PayloadNames[i]}=\"{eventData.Payload[i]}\" "); + } + + lock (this) + { + if (_writer != null) + { + _writer.Write(s_builder.ToString()); + _writer.Write(EventDelimiter); + } + } + } + catch + { + // If we fail to log an event, just skip it and continue. + } + + base.OnEventWritten(eventData); + } + } +} diff --git a/src/MSBuild/XMake.cs b/src/MSBuild/XMake.cs index c7220881a5c..2bd594b011c 100644 --- a/src/MSBuild/XMake.cs +++ b/src/MSBuild/XMake.cs @@ -213,13 +213,15 @@ string [] args #endif ) { - if (Environment.GetEnvironmentVariable("MSBUILDDUMPPROCESSCOUNTERS") == "1") + using (PerformanceLogEventListener eventListener = PerformanceLogEventListener.Create()) { - DumpCounters(true /* initialize only */); - } + if (Environment.GetEnvironmentVariable("MSBUILDDUMPPROCESSCOUNTERS") == "1") + { + DumpCounters(true /* initialize only */); + } - // return 0 on success, non-zero on failure - int exitCode = ((s_initialized && Execute( + // return 0 on success, non-zero on failure + int exitCode = ((s_initialized && Execute( #if FEATURE_GET_COMMANDLINE Environment.CommandLine #else @@ -227,12 +229,13 @@ string [] args #endif ) == ExitType.Success) ? 0 : 1); - if (Environment.GetEnvironmentVariable("MSBUILDDUMPPROCESSCOUNTERS") == "1") - { - DumpCounters(false /* log to console */); - } + if (Environment.GetEnvironmentVariable("MSBUILDDUMPPROCESSCOUNTERS") == "1") + { + DumpCounters(false /* log to console */); + } - return exitCode; + return exitCode; + } } #if !FEATURE_GET_COMMANDLINE From 85475c467a8280e2daf26036d3464cbef9931c0c Mon Sep 17 00:00:00 2001 From: Brian Robbins Date: Wed, 4 Nov 2020 20:23:40 -0800 Subject: [PATCH 3/8] Add perf log tests. --- src/MSBuild.UnitTests/PerfLog_Tests.cs | 116 ++++++++++++++++++++++++ src/UnitTests.Shared/RunnerUtilities.cs | 17 +++- 2 files changed, 130 insertions(+), 3 deletions(-) create mode 100644 src/MSBuild.UnitTests/PerfLog_Tests.cs diff --git a/src/MSBuild.UnitTests/PerfLog_Tests.cs b/src/MSBuild.UnitTests/PerfLog_Tests.cs new file mode 100644 index 00000000000..d099cb17854 --- /dev/null +++ b/src/MSBuild.UnitTests/PerfLog_Tests.cs @@ -0,0 +1,116 @@ +// Copyright (c) Microsoft. All rights reserved. +// Licensed under the MIT license. See LICENSE file in the project root for full license information. + +using System; +using System.Collections; +using System.Collections.Generic; +using System.Diagnostics; +using System.Globalization; +using System.IO; +using System.Linq; +using System.Threading; + +using Microsoft.Build.CommandLine; +using Microsoft.Build.Framework; +using Microsoft.Build.Shared; +using Microsoft.Build.UnitTests.Shared; +using Xunit; +using Xunit.Abstractions; +using Shouldly; +using System.IO.Compression; +using System.Reflection; + +namespace Microsoft.Build.UnitTests +{ + public class PerfLogTests + { +#if USE_MSBUILD_DLL_EXTN + private const string MSBuildExeName = "MSBuild.dll"; +#else + private const string MSBuildExeName = "MSBuild.exe"; +#endif + + private readonly ITestOutputHelper _output; + + public PerfLogTests(ITestOutputHelper output) + { + _output = output; + } + + [Fact] + public void TestPerfLogEnabledProducedLogFile() + { + // Setup perf log. + string perfLogDir = Path.Combine(Path.GetTempPath(), Guid.NewGuid().ToString("N")); + Dictionary environmentVariables = new Dictionary(); + environmentVariables["DOTNET_PERFLOG_DIR"] = perfLogDir; + + // Setup project directory. + string projectDir = Path.Combine(Path.GetTempPath(), Guid.NewGuid().ToString("N")); + string projectPath = Path.Combine(projectDir, "my.proj"); + + try + { + Directory.CreateDirectory(perfLogDir); + Directory.CreateDirectory(projectDir); + + string content = ObjectModelHelpers.CleanupFileContents(""); + File.WriteAllText(projectPath, content); + + string msbuildParameters = "\"" + projectPath + "\""; + + bool successfulExit; + RunnerUtilities.ExecMSBuild(RunnerUtilities.PathToCurrentlyRunningMsBuildExe, msbuildParameters, out successfulExit, environmentVariables: environmentVariables); + successfulExit.ShouldBeTrue(); + + // Look for the file. + // NOTE: We don't explicitly look for one file because it's possible that more components will add files that will show up here. + // It's most important to ensure that at least one file shows up because any others that show up will be there because MSBuild properly + // enabled this functionality. + string[] files = Directory.GetFiles(perfLogDir, "perf-*.log"); + Assert.NotEmpty(files); + Assert.All(files, f => Assert.True(new FileInfo(f).Length > 0)); + } + finally + { + Directory.Delete(perfLogDir, true); + Directory.Delete(projectDir, true); + } + } + + [Fact] + public void TestPerfLogDirectoryDoesNotExist() + { + // Setup perf log. + string perfLogDir = Path.Combine(Path.GetTempPath(), Guid.NewGuid().ToString("N")); + Dictionary environmentVariables = new Dictionary(); + environmentVariables["DOTNET_PERFLOG_DIR"] = perfLogDir; + + // Setup project directory. + string projectDir = Path.Combine(Path.GetTempPath(), Guid.NewGuid().ToString("N")); + string projectPath = Path.Combine(projectDir, "my.proj"); + + try + { + Directory.CreateDirectory(projectDir); + + string content = ObjectModelHelpers.CleanupFileContents(""); + File.WriteAllText(projectPath, content); + + string msbuildParameters = "\"" + projectPath + "\""; + + Assert.False(Directory.Exists(perfLogDir)); + + bool successfulExit; + RunnerUtilities.ExecMSBuild(RunnerUtilities.PathToCurrentlyRunningMsBuildExe, msbuildParameters, out successfulExit, environmentVariables: environmentVariables); + successfulExit.ShouldBeTrue(); + + Assert.False(Directory.Exists(perfLogDir)); + } + finally + { + Directory.Delete(projectDir, true); + } + } + } +} diff --git a/src/UnitTests.Shared/RunnerUtilities.cs b/src/UnitTests.Shared/RunnerUtilities.cs index 9dda37aa360..83c47eeb73a 100644 --- a/src/UnitTests.Shared/RunnerUtilities.cs +++ b/src/UnitTests.Shared/RunnerUtilities.cs @@ -1,6 +1,8 @@ using Microsoft.Build.Shared; using Microsoft.Build.Utilities; using System; +using System.Collections; +using System.Collections.Generic; using System.Diagnostics; using Xunit.Abstractions; @@ -23,7 +25,7 @@ public static string ExecMSBuild(string msbuildParameters, out bool successfulEx /// Invoke msbuild.exe with the given parameters and return the stdout, stderr, and process exit status. /// This method may invoke msbuild via other runtimes. /// - public static string ExecMSBuild(string pathToMsBuildExe, string msbuildParameters, out bool successfulExit, bool shellExecute = false, ITestOutputHelper outputHelper = null) + public static string ExecMSBuild(string pathToMsBuildExe, string msbuildParameters, out bool successfulExit, bool shellExecute = false, ITestOutputHelper outputHelper = null, IDictionary environmentVariables = null) { #if FEATURE_RUN_EXE_IN_TESTS var pathToExecutable = pathToMsBuildExe; @@ -32,7 +34,7 @@ public static string ExecMSBuild(string pathToMsBuildExe, string msbuildParamete msbuildParameters = "\"" + pathToMsBuildExe + "\"" + " " + msbuildParameters; #endif - return RunProcessAndGetOutput(pathToExecutable, msbuildParameters, out successfulExit, shellExecute, outputHelper); + return RunProcessAndGetOutput(pathToExecutable, msbuildParameters, out successfulExit, shellExecute, outputHelper, environmentVariables); } private static void AdjustForShellExecution(ref string pathToExecutable, ref string arguments) @@ -68,7 +70,7 @@ private static string ResolveRuntimeExecutableName() /// /// Run the process and get stdout and stderr /// - public static string RunProcessAndGetOutput(string process, string parameters, out bool successfulExit, bool shellExecute = false, ITestOutputHelper outputHelper = null) + public static string RunProcessAndGetOutput(string process, string parameters, out bool successfulExit, bool shellExecute = false, ITestOutputHelper outputHelper = null, IDictionary environmentVariables = null) { if (shellExecute) { @@ -85,6 +87,15 @@ public static string RunProcessAndGetOutput(string process, string parameters, o UseShellExecute = false, Arguments = parameters }; + + if(environmentVariables != null) + { + foreach(KeyValuePair pair in environmentVariables) + { + psi.EnvironmentVariables[pair.Key] = pair.Value; + } + } + var output = string.Empty; using (var p = new Process { EnableRaisingEvents = true, StartInfo = psi }) From e70ae925e1dcbba29062a0703283798bac63be97 Mon Sep 17 00:00:00 2001 From: Brian Robbins Date: Thu, 5 Nov 2020 13:54:06 -0800 Subject: [PATCH 4/8] Skip test on Mono since Mono doesn't implement EventSource. --- src/MSBuild.UnitTests/PerfLog_Tests.cs | 1 + 1 file changed, 1 insertion(+) diff --git a/src/MSBuild.UnitTests/PerfLog_Tests.cs b/src/MSBuild.UnitTests/PerfLog_Tests.cs index d099cb17854..944aa914266 100644 --- a/src/MSBuild.UnitTests/PerfLog_Tests.cs +++ b/src/MSBuild.UnitTests/PerfLog_Tests.cs @@ -38,6 +38,7 @@ public PerfLogTests(ITestOutputHelper output) } [Fact] + [Trait("Category", "mono-osx-failing")] // Disable on Mono OSX, since Mono doesn't implement EventSource. public void TestPerfLogEnabledProducedLogFile() { // Setup perf log. From 05902ba68d1fd0136e4f7da4b200ff65c36b3e92 Mon Sep 17 00:00:00 2001 From: Brian Robbins Date: Thu, 5 Nov 2020 15:40:46 -0800 Subject: [PATCH 5/8] Fix EventSource keywords. --- src/Framework/MSBuildEventSource.cs | 113 ++++++++++++++-------------- 1 file changed, 57 insertions(+), 56 deletions(-) diff --git a/src/Framework/MSBuildEventSource.cs b/src/Framework/MSBuildEventSource.cs index 2e153fb5cb7..f08158ecdcb 100644 --- a/src/Framework/MSBuildEventSource.cs +++ b/src/Framework/MSBuildEventSource.cs @@ -10,7 +10,8 @@ internal sealed class MSBuildEventSource : EventSource { public static class Keywords { - public const EventKeywords PerformanceLog = (EventKeywords)0x1; + public const EventKeywords All = (EventKeywords)0x1; + public const EventKeywords PerformanceLog = (EventKeywords)0x2; } /// @@ -26,14 +27,14 @@ private MSBuildEventSource() { } /// Call this method to notify listeners of information relevant to collecting a set of items, mutating them in a specified way, and saving the results. /// /// The type of the item being mutated. - [Event(1)] + [Event(1, Keywords = Keywords.All)] public void ApplyLazyItemOperationsStart(string itemType) { WriteEvent(1, itemType); } /// The type of the item being mutated. - [Event(2)] + [Event(2, Keywords = Keywords.All)] public void ApplyLazyItemOperationsStop(string itemType) { WriteEvent(2, itemType); @@ -42,13 +43,13 @@ public void ApplyLazyItemOperationsStop(string itemType) /// /// Call this method to notify listeners of information relevant to the setup for a BuildManager to receive build requests. /// - [Event(3)] + [Event(3, Keywords = Keywords.All)] public void BuildStart() { WriteEvent(3); } - [Event(4)] + [Event(4, Keywords = Keywords.All)] public void BuildStop() { WriteEvent(4); @@ -58,7 +59,7 @@ public void BuildStop() /// Call this method to notify listeners of information of how a project file built. /// Filename of the project being built. /// - [Event(5)] + [Event(5, Keywords = Keywords.All)] public void BuildProjectStart(string projectPath) { WriteEvent(5, projectPath); @@ -66,26 +67,26 @@ public void BuildProjectStart(string projectPath) /// Filename of the project being built. /// Names of the targets that built. - [Event(6)] + [Event(6, Keywords = Keywords.All)] public void BuildProjectStop(string projectPath, string targets) { WriteEvent(6, projectPath, targets); } - [Event(7)] + [Event(7, Keywords = Keywords.All)] public void RarComputeClosureStart() { WriteEvent(7); } - [Event(8)] + [Event(8, Keywords = Keywords.All)] public void RarComputeClosureStop() { WriteEvent(8); } /// The condition being evaluated. - [Event(9)] + [Event(9, Keywords = Keywords.All)] public void EvaluateConditionStart(string condition) { WriteEvent(9, condition); @@ -93,7 +94,7 @@ public void EvaluateConditionStart(string condition) /// The condition being evaluated. /// The result of evaluating the condition. - [Event(10)] + [Event(10, Keywords = Keywords.All)] public void EvaluateConditionStop(string condition, bool result) { WriteEvent(10, condition, result); @@ -103,122 +104,122 @@ 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. - [Event(11)] + [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. - [Event(12)] + [Event(12, Keywords = Keywords.All)] public void EvaluatePass0Start(string projectFile) { WriteEvent(12, projectFile); } /// Relevant information about where in the run of the progam it is. - [Event(13)] + [Event(13, Keywords = Keywords.All)] public void EvaluatePass0Stop(string projectFile) { WriteEvent(13, projectFile); } /// Relevant information about where in the run of the progam it is. - [Event(14)] + [Event(14, Keywords = Keywords.All)] public void EvaluatePass1Start(string projectFile) { WriteEvent(14, projectFile); } /// Relevant information about where in the run of the progam it is. - [Event(15)] + [Event(15, Keywords = Keywords.All)] public void EvaluatePass1Stop(string projectFile) { WriteEvent(15, projectFile); } /// Relevant information about where in the run of the progam it is. - [Event(16)] + [Event(16, Keywords = Keywords.All)] public void EvaluatePass2Start(string projectFile) { WriteEvent(16, projectFile); } /// Relevant information about where in the run of the progam it is. - [Event(17)] + [Event(17, Keywords = Keywords.All)] public void EvaluatePass2Stop(string projectFile) { WriteEvent(17, projectFile); } /// Relevant information about where in the run of the progam it is. - [Event(18)] + [Event(18, Keywords = Keywords.All)] public void EvaluatePass3Start(string projectFile) { WriteEvent(18, projectFile); } /// Relevant information about where in the run of the progam it is. - [Event(19)] + [Event(19, Keywords = Keywords.All)] public void EvaluatePass3Stop(string projectFile) { WriteEvent(19, projectFile); } /// Relevant information about where in the run of the progam it is. - [Event(20)] + [Event(20, Keywords = Keywords.All)] public void EvaluatePass4Start(string projectFile) { WriteEvent(20, projectFile); } /// Relevant information about where in the run of the progam it is. - [Event(21)] + [Event(21, Keywords = Keywords.All)] public void EvaluatePass4Stop(string projectFile) { WriteEvent(21, projectFile); } /// Relevant information about where in the run of the progam it is. - [Event(22)] + [Event(22, Keywords = Keywords.All)] public void EvaluatePass5Start(string projectFile) { WriteEvent(22, projectFile); } /// Relevant information about where in the run of the progam it is. - [Event(23)] + [Event(23, Keywords = Keywords.All)] public void EvaluatePass5Stop(string projectFile) { WriteEvent(23, projectFile); } /// Relevant information about where in the run of the progam it is. - [Event(24)] + [Event(24, Keywords = Keywords.All)] public void EvaluateStop(string projectFile) { WriteEvent(24, projectFile); } - [Event(25)] + [Event(25, Keywords = Keywords.All)] public void GenerateResourceOverallStart() { WriteEvent(25); } - [Event(26)] + [Event(26, Keywords = Keywords.All)] public void GenerateResourceOverallStop() { WriteEvent(26); } - [Event(27)] + [Event(27, Keywords = Keywords.All)] public void RarOverallStart() { WriteEvent(27); } - [Event(28)] + [Event(28, Keywords = Keywords.All)] public void RarOverallStop() { WriteEvent(28); @@ -230,7 +231,7 @@ public void RarOverallStop() /// Source of files to glob. /// Pattern, possibly with wildcard(s) to be expanded. /// Patterns not to expand. - [Event(41)] + [Event(41, Keywords = Keywords.All)] public void ExpandGlobStart(string rootDirectory, string glob, string excludedPatterns) { WriteEvent(41, rootDirectory, glob, excludedPatterns); @@ -239,7 +240,7 @@ public void ExpandGlobStart(string rootDirectory, string glob, string excludedPa /// Source of files to glob. /// Pattern, possibly with wildcard(s) to be expanded. /// Patterns not to expand. - [Event(42)] + [Event(42, Keywords = Keywords.All)] public void ExpandGlobStop(string rootDirectory, string glob, string excludedPatterns) { WriteEvent(42, rootDirectory, glob, excludedPatterns); @@ -249,26 +250,26 @@ public void ExpandGlobStop(string rootDirectory, string glob, string excludedPat /// Call this method to notify listeners of timing related to loading an XmlDocumentWithLocation from a path. /// Path to the document to load. /// - [Event(29, Keywords = Keywords.PerformanceLog)] + [Event(29, Keywords = Keywords.All | Keywords.PerformanceLog)] public void LoadDocumentStart(string fullPath) { WriteEvent(29, fullPath); } /// Path to the document to load. - [Event(30, Keywords = Keywords.PerformanceLog)] + [Event(30, Keywords = Keywords.All | Keywords.PerformanceLog)] public void LoadDocumentStop(string fullPath) { WriteEvent(30, fullPath); } - [Event(31)] + [Event(31, Keywords = Keywords.All)] public void RarLogResultsStart() { WriteEvent(31); } - [Event(32)] + [Event(32, Keywords = Keywords.All)] public void RarLogResultsStop() { WriteEvent(32); @@ -278,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. /// /// Relevant information about where in the run of the progam it is. - [Event(33, Keywords = Keywords.PerformanceLog)] + [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. - [Event(34, Keywords = Keywords.PerformanceLog)] + [Event(34, Keywords = Keywords.All | Keywords.PerformanceLog)] public void ParseStop(string projectFileName) { WriteEvent(34, projectFileName); @@ -294,53 +295,53 @@ public void ParseStop(string projectFileName) /// /// Call this method to notify listeners of profiling for the method that removes blacklisted references from the reference table. It puts primary and dependency references in invalid file lists. /// - [Event(35)] + [Event(35, Keywords = Keywords.All)] public void RarRemoveReferencesMarkedForExclusionStart() { WriteEvent(35); } - [Event(36)] + [Event(36, Keywords = Keywords.All)] public void RarRemoveReferencesMarkedForExclusionStop() { WriteEvent(36); } - [Event(37, Keywords = Keywords.PerformanceLog)] + [Event(37, Keywords = Keywords.All | Keywords.PerformanceLog)] public void RequestThreadProcStart() { WriteEvent(37); } - [Event(38, Keywords = Keywords.PerformanceLog)] + [Event(38, Keywords = Keywords.All | Keywords.PerformanceLog)] public void RequestThreadProcStop() { WriteEvent(38); } /// Project file's location. - [Event(39)] + [Event(39, Keywords = Keywords.All)] public void SaveStart(string fileLocation) { WriteEvent(39, fileLocation); } /// Project file's location. - [Event(40)] + [Event(40, Keywords = Keywords.All)] public void SaveStop(string fileLocation) { WriteEvent(40, fileLocation); } /// The name of the target being executed. - [Event(43, Keywords = Keywords.PerformanceLog)] + [Event(43, Keywords = Keywords.All | Keywords.PerformanceLog)] public void TargetStart(string targetName) { WriteEvent(43, targetName); } /// The name of the target being executed. - [Event(44, Keywords = Keywords.PerformanceLog)] + [Event(44, Keywords = Keywords.All | Keywords.PerformanceLog)] public void TargetStop(string targetName) { WriteEvent(44, targetName); @@ -350,68 +351,68 @@ public void TargetStop(string targetName) /// Call this method to notify listeners of the start of a build as called from the command line. /// /// The command line used to run MSBuild. - [Event(45, Keywords = Keywords.PerformanceLog)] + [Event(45, Keywords = Keywords.All | Keywords.PerformanceLog)] public void MSBuildExeStart(string commandLine) { WriteEvent(45, commandLine); } /// The command line used to run MSBuild. - [Event(46, Keywords = Keywords.PerformanceLog)] + [Event(46, Keywords = Keywords.All | Keywords.PerformanceLog)] public void MSBuildExeStop(string commandLine) { WriteEvent(46, commandLine); } - [Event(47)] + [Event(47, Keywords = Keywords.All)] public void ExecuteTaskStart(string taskName, int taskID) { WriteEvent(47, taskName, taskID); } - [Event(48)] + [Event(48, Keywords = Keywords.All)] public void ExecuteTaskStop(string taskName, int taskID) { WriteEvent(48, taskName, taskID); } - [Event(49)] + [Event(49, Keywords = Keywords.All)] public void ExecuteTaskYieldStart(string taskName, int taskID) { WriteEvent(49, taskName, taskID); } - [Event(50)] + [Event(50, Keywords = Keywords.All)] public void ExecuteTaskYieldStop(string taskName, int taskID) { WriteEvent(50, taskName, taskID); } - [Event(51)] + [Event(51, Keywords = Keywords.All)] public void ExecuteTaskReacquireStart(string taskName, int taskID) { WriteEvent(51, taskName, taskID); } - [Event(52)] + [Event(52, Keywords = Keywords.All)] public void ExecuteTaskReacquireStop(string taskName, int taskID) { WriteEvent(52, taskName, taskID); } - [Event(53)] + [Event(53, Keywords = Keywords.All)] public void ProjectGraphConstructionStart(string graphEntryPoints) { WriteEvent(53, graphEntryPoints); } - [Event(54)] + [Event(54, Keywords = Keywords.All)] public void ProjectGraphConstructionStop(string graphEntryPoints) { WriteEvent(54, graphEntryPoints); } - [Event(55)] + [Event(55, Keywords = Keywords.All)] public void PacketReadSize(int size) { WriteEvent(55, size); From bdc4ce71e13e056b22c9fc74954dacab7a370623 Mon Sep 17 00:00:00 2001 From: Brian Robbins Date: Thu, 5 Nov 2020 15:41:07 -0800 Subject: [PATCH 6/8] Address review feedback. --- src/MSBuild.UnitTests/PerfLog_Tests.cs | 20 ++++++++++---------- src/MSBuild/PerformanceLogEventListener.cs | 4 ++++ 2 files changed, 14 insertions(+), 10 deletions(-) diff --git a/src/MSBuild.UnitTests/PerfLog_Tests.cs b/src/MSBuild.UnitTests/PerfLog_Tests.cs index 944aa914266..2f70b42ee17 100644 --- a/src/MSBuild.UnitTests/PerfLog_Tests.cs +++ b/src/MSBuild.UnitTests/PerfLog_Tests.cs @@ -55,13 +55,13 @@ public void TestPerfLogEnabledProducedLogFile() Directory.CreateDirectory(perfLogDir); Directory.CreateDirectory(projectDir); - string content = ObjectModelHelpers.CleanupFileContents(""); + string content = ObjectModelHelpers.CleanupFileContents( + ""); File.WriteAllText(projectPath, content); string msbuildParameters = "\"" + projectPath + "\""; - bool successfulExit; - RunnerUtilities.ExecMSBuild(RunnerUtilities.PathToCurrentlyRunningMsBuildExe, msbuildParameters, out successfulExit, environmentVariables: environmentVariables); + RunnerUtilities.ExecMSBuild(RunnerUtilities.PathToCurrentlyRunningMsBuildExe, msbuildParameters, out bool successfulExit, environmentVariables: environmentVariables); successfulExit.ShouldBeTrue(); // Look for the file. @@ -69,8 +69,8 @@ public void TestPerfLogEnabledProducedLogFile() // It's most important to ensure that at least one file shows up because any others that show up will be there because MSBuild properly // enabled this functionality. string[] files = Directory.GetFiles(perfLogDir, "perf-*.log"); - Assert.NotEmpty(files); - Assert.All(files, f => Assert.True(new FileInfo(f).Length > 0)); + files.ShouldNotBeEmpty(); + files.ShouldAllBe(f => new FileInfo(f).Length > 0); } finally { @@ -95,18 +95,18 @@ public void TestPerfLogDirectoryDoesNotExist() { Directory.CreateDirectory(projectDir); - string content = ObjectModelHelpers.CleanupFileContents(""); + string content = ObjectModelHelpers.CleanupFileContents( + ""); File.WriteAllText(projectPath, content); string msbuildParameters = "\"" + projectPath + "\""; - Assert.False(Directory.Exists(perfLogDir)); + Directory.Exists(perfLogDir).ShouldBeFalse(); - bool successfulExit; - RunnerUtilities.ExecMSBuild(RunnerUtilities.PathToCurrentlyRunningMsBuildExe, msbuildParameters, out successfulExit, environmentVariables: environmentVariables); + RunnerUtilities.ExecMSBuild(RunnerUtilities.PathToCurrentlyRunningMsBuildExe, msbuildParameters, out bool successfulExit, environmentVariables: environmentVariables); successfulExit.ShouldBeTrue(); - Assert.False(Directory.Exists(perfLogDir)); + Directory.Exists(perfLogDir).ShouldBeFalse(); } finally { diff --git a/src/MSBuild/PerformanceLogEventListener.cs b/src/MSBuild/PerformanceLogEventListener.cs index 23406bc2195..a9ffec3aae4 100644 --- a/src/MSBuild/PerformanceLogEventListener.cs +++ b/src/MSBuild/PerformanceLogEventListener.cs @@ -1,3 +1,6 @@ +// Copyright (c) Microsoft. All rights reserved. +// Licensed under the MIT license. See LICENSE file in the project root for full license information. + using System; using System.Diagnostics; using System.Diagnostics.Tracing; @@ -59,6 +62,7 @@ internal static PerformanceLogEventListener Create() if (eventListener != null) { eventListener.Dispose(); + eventListener = null; } } From ad04c828f3e2b0927b42bb11b0544c0f80332ec9 Mon Sep 17 00:00:00 2001 From: Brian Robbins Date: Fri, 6 Nov 2020 11:01:43 -0800 Subject: [PATCH 7/8] Update tests based on code review feedback. --- src/MSBuild.UnitTests/PerfLog_Tests.cs | 85 +++++++++++-------------- src/UnitTests.Shared/RunnerUtilities.cs | 17 +---- 2 files changed, 41 insertions(+), 61 deletions(-) diff --git a/src/MSBuild.UnitTests/PerfLog_Tests.cs b/src/MSBuild.UnitTests/PerfLog_Tests.cs index 2f70b42ee17..b39f192a446 100644 --- a/src/MSBuild.UnitTests/PerfLog_Tests.cs +++ b/src/MSBuild.UnitTests/PerfLog_Tests.cs @@ -41,76 +41,67 @@ public PerfLogTests(ITestOutputHelper output) [Trait("Category", "mono-osx-failing")] // Disable on Mono OSX, since Mono doesn't implement EventSource. public void TestPerfLogEnabledProducedLogFile() { - // Setup perf log. - string perfLogDir = Path.Combine(Path.GetTempPath(), Guid.NewGuid().ToString("N")); - Dictionary environmentVariables = new Dictionary(); - environmentVariables["DOTNET_PERFLOG_DIR"] = perfLogDir; - - // Setup project directory. - string projectDir = Path.Combine(Path.GetTempPath(), Guid.NewGuid().ToString("N")); - string projectPath = Path.Combine(projectDir, "my.proj"); - - try + using (TestEnvironment testEnv = TestEnvironment.Create(_output)) { - Directory.CreateDirectory(perfLogDir); - Directory.CreateDirectory(projectDir); - - string content = ObjectModelHelpers.CleanupFileContents( - ""); - File.WriteAllText(projectPath, content); - + // Setup perf log. + TransientTestFolder perfLogFolder = testEnv.CreateFolder(createFolder: true); + testEnv.SetEnvironmentVariable("DOTNET_PERFLOG_DIR", perfLogFolder.Path); + + // Setup project directory. + TransientTestFolder projectFolder = testEnv.CreateFolder(createFolder: true); + TransientTestFile classLibrary = testEnv.CreateFile(projectFolder, "ClassLibrary.csproj", + @" + + + + + "); + + string projectPath = Path.Combine(projectFolder.Path, "ClassLibrary.csproj"); string msbuildParameters = "\"" + projectPath + "\""; - RunnerUtilities.ExecMSBuild(RunnerUtilities.PathToCurrentlyRunningMsBuildExe, msbuildParameters, out bool successfulExit, environmentVariables: environmentVariables); + RunnerUtilities.ExecMSBuild(msbuildParameters, out bool successfulExit); successfulExit.ShouldBeTrue(); // Look for the file. // NOTE: We don't explicitly look for one file because it's possible that more components will add files that will show up here. // It's most important to ensure that at least one file shows up because any others that show up will be there because MSBuild properly // enabled this functionality. - string[] files = Directory.GetFiles(perfLogDir, "perf-*.log"); + string[] files = Directory.GetFiles(perfLogFolder.Path, "perf-*.log"); files.ShouldNotBeEmpty(); files.ShouldAllBe(f => new FileInfo(f).Length > 0); } - finally - { - Directory.Delete(perfLogDir, true); - Directory.Delete(projectDir, true); - } } [Fact] public void TestPerfLogDirectoryDoesNotExist() { - // Setup perf log. - string perfLogDir = Path.Combine(Path.GetTempPath(), Guid.NewGuid().ToString("N")); - Dictionary environmentVariables = new Dictionary(); - environmentVariables["DOTNET_PERFLOG_DIR"] = perfLogDir; - - // Setup project directory. - string projectDir = Path.Combine(Path.GetTempPath(), Guid.NewGuid().ToString("N")); - string projectPath = Path.Combine(projectDir, "my.proj"); - - try + using (TestEnvironment testEnv = TestEnvironment.Create(_output)) { - Directory.CreateDirectory(projectDir); - - string content = ObjectModelHelpers.CleanupFileContents( - ""); - File.WriteAllText(projectPath, content); - + // Setup invalid perf log directory. + TransientTestFolder perfLogFolder = testEnv.CreateFolder(createFolder: true); + string perfLogPath = Path.Combine(perfLogFolder.Path, "logs"); + testEnv.SetEnvironmentVariable("DOTNET_PERFLOG_DIR", perfLogPath); + + // Setup project directory. + TransientTestFolder projectFolder = testEnv.CreateFolder(createFolder: true); + TransientTestFile classLibrary = testEnv.CreateFile(projectFolder, "ClassLibrary.csproj", + @" + + + + + "); + + string projectPath = Path.Combine(projectFolder.Path, "ClassLibrary.csproj"); string msbuildParameters = "\"" + projectPath + "\""; - Directory.Exists(perfLogDir).ShouldBeFalse(); + Directory.Exists(perfLogPath).ShouldBeFalse(); - RunnerUtilities.ExecMSBuild(RunnerUtilities.PathToCurrentlyRunningMsBuildExe, msbuildParameters, out bool successfulExit, environmentVariables: environmentVariables); + RunnerUtilities.ExecMSBuild(msbuildParameters, out bool successfulExit); successfulExit.ShouldBeTrue(); - Directory.Exists(perfLogDir).ShouldBeFalse(); - } - finally - { - Directory.Delete(projectDir, true); + Directory.Exists(perfLogPath).ShouldBeFalse(); } } } diff --git a/src/UnitTests.Shared/RunnerUtilities.cs b/src/UnitTests.Shared/RunnerUtilities.cs index 83c47eeb73a..9dda37aa360 100644 --- a/src/UnitTests.Shared/RunnerUtilities.cs +++ b/src/UnitTests.Shared/RunnerUtilities.cs @@ -1,8 +1,6 @@ using Microsoft.Build.Shared; using Microsoft.Build.Utilities; using System; -using System.Collections; -using System.Collections.Generic; using System.Diagnostics; using Xunit.Abstractions; @@ -25,7 +23,7 @@ public static string ExecMSBuild(string msbuildParameters, out bool successfulEx /// Invoke msbuild.exe with the given parameters and return the stdout, stderr, and process exit status. /// This method may invoke msbuild via other runtimes. /// - public static string ExecMSBuild(string pathToMsBuildExe, string msbuildParameters, out bool successfulExit, bool shellExecute = false, ITestOutputHelper outputHelper = null, IDictionary environmentVariables = null) + public static string ExecMSBuild(string pathToMsBuildExe, string msbuildParameters, out bool successfulExit, bool shellExecute = false, ITestOutputHelper outputHelper = null) { #if FEATURE_RUN_EXE_IN_TESTS var pathToExecutable = pathToMsBuildExe; @@ -34,7 +32,7 @@ public static string ExecMSBuild(string pathToMsBuildExe, string msbuildParamete msbuildParameters = "\"" + pathToMsBuildExe + "\"" + " " + msbuildParameters; #endif - return RunProcessAndGetOutput(pathToExecutable, msbuildParameters, out successfulExit, shellExecute, outputHelper, environmentVariables); + return RunProcessAndGetOutput(pathToExecutable, msbuildParameters, out successfulExit, shellExecute, outputHelper); } private static void AdjustForShellExecution(ref string pathToExecutable, ref string arguments) @@ -70,7 +68,7 @@ private static string ResolveRuntimeExecutableName() /// /// Run the process and get stdout and stderr /// - public static string RunProcessAndGetOutput(string process, string parameters, out bool successfulExit, bool shellExecute = false, ITestOutputHelper outputHelper = null, IDictionary environmentVariables = null) + public static string RunProcessAndGetOutput(string process, string parameters, out bool successfulExit, bool shellExecute = false, ITestOutputHelper outputHelper = null) { if (shellExecute) { @@ -87,15 +85,6 @@ public static string RunProcessAndGetOutput(string process, string parameters, o UseShellExecute = false, Arguments = parameters }; - - if(environmentVariables != null) - { - foreach(KeyValuePair pair in environmentVariables) - { - psi.EnvironmentVariables[pair.Key] = pair.Value; - } - } - var output = string.Empty; using (var p = new Process { EnableRaisingEvents = true, StartInfo = psi }) From 2fa8afbed0dbc0b972526149d5349fb18fe3a244 Mon Sep 17 00:00:00 2001 From: Brian Robbins Date: Fri, 6 Nov 2020 13:11:39 -0800 Subject: [PATCH 8/8] Enable a few more events. --- src/Framework/MSBuildEventSource.cs | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/src/Framework/MSBuildEventSource.cs b/src/Framework/MSBuildEventSource.cs index f08158ecdcb..abc5fd12d93 100644 --- a/src/Framework/MSBuildEventSource.cs +++ b/src/Framework/MSBuildEventSource.cs @@ -43,13 +43,13 @@ public void ApplyLazyItemOperationsStop(string itemType) /// /// Call this method to notify listeners of information relevant to the setup for a BuildManager to receive build requests. /// - [Event(3, Keywords = Keywords.All)] + [Event(3, Keywords = Keywords.All | Keywords.PerformanceLog)] public void BuildStart() { WriteEvent(3); } - [Event(4, Keywords = Keywords.All)] + [Event(4, Keywords = Keywords.All | Keywords.PerformanceLog)] public void BuildStop() { WriteEvent(4); @@ -59,7 +59,7 @@ public void BuildStop() /// Call this method to notify listeners of information of how a project file built. /// Filename of the project being built. /// - [Event(5, Keywords = Keywords.All)] + [Event(5, Keywords = Keywords.All | Keywords.PerformanceLog)] public void BuildProjectStart(string projectPath) { WriteEvent(5, projectPath); @@ -67,7 +67,7 @@ public void BuildProjectStart(string projectPath) /// Filename of the project being built. /// Names of the targets that built. - [Event(6, Keywords = Keywords.All)] + [Event(6, Keywords = Keywords.All | Keywords.PerformanceLog)] public void BuildProjectStop(string projectPath, string targets) { WriteEvent(6, projectPath, targets); @@ -213,13 +213,13 @@ public void GenerateResourceOverallStop() WriteEvent(26); } - [Event(27, Keywords = Keywords.All)] + [Event(27, Keywords = Keywords.All | Keywords.PerformanceLog)] public void RarOverallStart() { WriteEvent(27); } - [Event(28, Keywords = Keywords.All)] + [Event(28, Keywords = Keywords.All | Keywords.PerformanceLog)] public void RarOverallStop() { WriteEvent(28);