Implement Text-Based Performance Log

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;
+        }
+
         /// <summary>
         /// define the singleton instance of the event source
         /// </summary>
@@ -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.
         /// <param name="fullPath">Path to the document to load.</param>
         /// </summary>
-        [Event(29)]
+        [Event(29, Keywords = Keywords.PerformanceLog)]
         public void LoadDocumentStart(string fullPath)
         {
             WriteEvent(29, fullPath);
         }
 
         /// <param name="fullPath">Path to the document to load.</param>
-        [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.
         /// </summary>
         /// <param name="projectFileName">Relevant information about where in the run of the progam it is.</param>
-        [Event(33)]
+        [Event(33, Keywords = Keywords.PerformanceLog)]
         public void ParseStart(string projectFileName)
         {
             WriteEvent(33, projectFileName);
         }
 
         /// <param name="projectFileName">Relevant information about where in the run of the progam it is.</param>
-        [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)
         }
 
         /// <param name="targetName">The name of the target being executed.</param>
-        [Event(43)]
+        [Event(43, Keywords = Keywords.PerformanceLog)]
         public void TargetStart(string targetName)
         {
             WriteEvent(43, targetName);
         }
 
         /// <param name="targetName">The name of the target being executed.</param>
-        [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.
         /// </summary>
         /// <param name="commandLine">The command line used to run MSBuild.</param>
-        [Event(45)]
+        [Event(45, Keywords = Keywords.PerformanceLog)]
         public void MSBuildExeStart(string commandLine)
         {
             WriteEvent(45, commandLine);
         }
 
         /// <param name="commandLine">The command line used to run MSBuild.</param>
-        [Event(46)]
+        [Event(46, Keywords = Keywords.PerformanceLog)]
         public void MSBuildExeStop(string commandLine)
         {
             WriteEvent(46, commandLine);

src/MSBuild.UnitTests/PerfLog_Tests.cs

@@ -0,0 +1,117 @@
+// 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]
+        [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<string, string> environmentVariables = new Dictionary<string, string>();
+            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("<Project ToolsVersion='msbuilddefaulttoolsversion' xmlns='msbuildnamespace'><Target Name='t'><Warning Text='[A=$(A)]'/></Target></Project>");
+                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<string, string> environmentVariables = new Dictionary<string, string>();
+            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("<Project ToolsVersion='msbuilddefaulttoolsversion' xmlns='msbuildnamespace'><Target Name='t'><Warning Text='[A=$(A)]'/></Target></Project>");
+                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);
+            }
+        }
+    }
+}

src/MSBuild/MSBuild.csproj

@@ -194,6 +194,7 @@
     <Compile Include="OutOfProcTaskHostNode.cs" />
     <Compile Include="OutOfProcTaskAppDomainWrapperBase.cs" />
     <Compile Include="OutOfProcTaskAppDomainWrapper.cs" />
+    <Compile Include="PerformanceLogEventListener.cs" />
     <Compile Include="XMake.cs">
       <ExcludeFromStyleCop>true</ExcludeFromStyleCop>
     </Compile>

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);
+        }
+    }
+}