Log properties and items on ProjectEvaluationFinished (#6287)

Add an option to log global properties, properties and items on ProjectEvaluationFinishedEventArgs instead of ProjectStartedEventArgs. This option is currently only turned on by the BinaryLogger.

This has several advantages. Currently only the projects that are built by the central node log their properties and items (properties are translated across nodes only if a special flag is set, and items are never translated). This resulted in properties and items not being available for projects built on other nodes. Now we log them after every evaluation and translate across nodes if needed. Together with the fact that we now log EvaluationId for each ProjectStarted, we can now recover properties and items for all project started events. This is the main purpose of this PR - to not lose properties and items like we currently do. We will still not log for project results that are satisfied by cache, because we don't keep track of evaluation for these. Presumably it will have already been logged previously.

In addition, if more than one project are built from the same evaluation, we do not duplicate properties and items, only logging them once. This results in logging more information, but storing it more efficiently. Together with string and dictionary deduplication we see very significant savings in binlog size and some reduction in build time.

This change has several large parts:

 1. add a way to enumerate evaluation properties and items directly at the end of Evaluate() for PropertyDictionary<ProjectPropertyInstance> and ItemDictionary<ProjectItemInstance>
 2. manual translation logic for ProjectEvaluationStarted and ProjectEvaluationFinished (instead of relying on TranslateDotNet/BinaryFormatter)
 3. reading and writing ProjectEvaluationFinished GlobalProperties, Properties and Items in BuildEventArgsReader/Writer (used by BinaryLogger)
 4. adding IEventSource4 with IncludeEvaluationPropertiesAndItems, to propagate this setting across nodes and threading it through the LoggingService
 5. update the ParallelConsoleLogger and SerialConsoleLogger to print the new data, if present
 6. tests

One controversial design decision here is storing a reference to live evaluation data in ProjectEvaluationFinishedEventArgs. It does not make a snapshot of the data to avoid very significant allocations. It does take the lock on the PropertyDictionary<T>/ItemDictionary<T> when enumerating, because logging is asynchronous and the logging consumer (BinaryLogger) will enumerate the data potentially after the build has already started and the data is being mutated. I did see exceptions when enumerating without the lock. We had the same problem when the data was logged on ProjectStartedEventArgs though. In addition, there's a slight risk of logging not the exact data as it was at the end of evaluation, but the mutated data after some target has modified it. However given that the previous behavior was to not log anything for out-of-proc projects, and given the very significant allocation reduction, I think it's worth it.

To mitigate, we could capture a snapshot at the end of evaluation, so we don't hold a reference to live data. This won't need a lock to enumerate. Ideally we also rely on the immutable collections to avoid allocations, but I didn't see an easy way to do that currently. We can investigate this in a future change.

For items, it doesn't concatenate items of different types into a single large item stream, but keeps multiple lists, one per item type, to reflect the internal representation. Not flattening item types results in savings because we don't have to mention the item type for each item.

This change increments the BinaryLogger file format to 12, to serialize GlobalProperties, Properties and Items on ProjectEvaluationFinishedEventArgs. It also stores items more efficiently, without having to know the number of item types in advance and enumerate in a single pass. It writes the item type and all items of that type, and it writes 0 to signal there are no more item types. It also no longer writes the Message for args as it can be recovered upon reading.

New EnumerateProperties() and EnumerateItems() methods are added to Utilities, to consolidate the logic to enumerate the new data structures in a single location, used by packet translation logic, binary logger and the console loggers.

Perf wise, I'm seeing no significant change on binlog size for small builds (it's a wash, because we log properties/items for all projects now, but they are no longer duplicated). For large projects I expect very significant savings though, as ProjectStarted is the most heavy-weight event in large binlogs.
Build performance with /bl on small-ish builds is improved 27 s -> 24 s for single-core and 18 s -> 17 s for parallel. No observable change without /bl.

Fixes #5316
Fixes #3616

eng/Packages.props

@@ -2,7 +2,7 @@
   <ItemGroup>
     <PackageReference Update="BenchmarkDotNet" Version="0.12.1" />
     <PackageReference Update="jnm2.ReferenceAssemblies.net35" Version="1.0.1" />
-    <PackageReference Update="LargeAddressAware" Version="1.0.3" />
+    <PackageReference Update="LargeAddressAware" Version="1.0.5" />
     <PackageReference Update="Microsoft.Build.NuGetSdkResolver" Version="$(NuGetBuildTasksVersion)" />
     <PackageReference Update="Microsoft.CodeAnalysis.Build.Tasks" Version="$(MicrosoftNetCompilersToolsetVersion)" />
     <PackageReference Update="Microsoft.DotNet.GenAPI" Version="2.1.0-prerelease-02404-02" />

ref/Microsoft.Build.Framework/net/Microsoft.Build.Framework.cs

@@ -38,7 +38,7 @@ protected BuildEventArgs(string message, string helpKeyword, string senderName,
         public Microsoft.Build.Framework.BuildEventContext BuildEventContext { get { throw null; } set { } }
         public string HelpKeyword { get { throw null; } }
         public virtual string Message { get { throw null; } protected set { } }
-        protected System.DateTime RawTimestamp { get { throw null; } set { } }
+        protected internal System.DateTime RawTimestamp { get { throw null; } set { } }
         public string SenderName { get { throw null; } }
         public int ThreadId { get { throw null; } }
         public System.DateTime Timestamp { get { throw null; } }
@@ -258,6 +258,10 @@ public partial interface IEventSource3 : Microsoft.Build.Framework.IEventSource,
         void IncludeEvaluationProfiles();
         void IncludeTaskInputs();
     }
+    public partial interface IEventSource4 : Microsoft.Build.Framework.IEventSource, Microsoft.Build.Framework.IEventSource2, Microsoft.Build.Framework.IEventSource3
+    {
+        void IncludeEvaluationPropertiesAndItems();
+    }
     public partial interface IForwardingLogger : Microsoft.Build.Framework.ILogger, Microsoft.Build.Framework.INodeLogger
     {
         Microsoft.Build.Framework.IEventRedirector BuildEventRedirector { get; set; }
@@ -387,8 +391,11 @@ public sealed partial class ProjectEvaluationFinishedEventArgs : Microsoft.Build
     {
         public ProjectEvaluationFinishedEventArgs() { }
         public ProjectEvaluationFinishedEventArgs(string message, params object[] messageArgs) { }
+        public System.Collections.IEnumerable GlobalProperties { get { throw null; } set { } }
+        public System.Collections.IEnumerable Items { get { throw null; } set { } }
         public Microsoft.Build.Framework.Profiler.ProfilerResult? ProfilerResult { get { throw null; } set { } }
         public string ProjectFile { get { throw null; } set { } }
+        public System.Collections.IEnumerable Properties { get { throw null; } set { } }
     }
     public partial class ProjectEvaluationStartedEventArgs : Microsoft.Build.Framework.BuildStatusEventArgs
     {

ref/Microsoft.Build.Framework/netstandard/Microsoft.Build.Framework.cs

@@ -38,7 +38,7 @@ protected BuildEventArgs(string message, string helpKeyword, string senderName,
         public Microsoft.Build.Framework.BuildEventContext BuildEventContext { get { throw null; } set { } }
         public string HelpKeyword { get { throw null; } }
         public virtual string Message { get { throw null; } protected set { } }
-        protected System.DateTime RawTimestamp { get { throw null; } set { } }
+        protected internal System.DateTime RawTimestamp { get { throw null; } set { } }
         public string SenderName { get { throw null; } }
         public int ThreadId { get { throw null; } }
         public System.DateTime Timestamp { get { throw null; } }
@@ -258,6 +258,10 @@ public partial interface IEventSource3 : Microsoft.Build.Framework.IEventSource,
         void IncludeEvaluationProfiles();
         void IncludeTaskInputs();
     }
+    public partial interface IEventSource4 : Microsoft.Build.Framework.IEventSource, Microsoft.Build.Framework.IEventSource2, Microsoft.Build.Framework.IEventSource3
+    {
+        void IncludeEvaluationPropertiesAndItems();
+    }
     public partial interface IForwardingLogger : Microsoft.Build.Framework.ILogger, Microsoft.Build.Framework.INodeLogger
     {
         Microsoft.Build.Framework.IEventRedirector BuildEventRedirector { get; set; }
@@ -386,8 +390,11 @@ public sealed partial class ProjectEvaluationFinishedEventArgs : Microsoft.Build
     {
         public ProjectEvaluationFinishedEventArgs() { }
         public ProjectEvaluationFinishedEventArgs(string message, params object[] messageArgs) { }
+        public System.Collections.IEnumerable GlobalProperties { get { throw null; } set { } }
+        public System.Collections.IEnumerable Items { get { throw null; } set { } }
         public Microsoft.Build.Framework.Profiler.ProfilerResult? ProfilerResult { get { throw null; } set { } }
         public string ProjectFile { get { throw null; } set { } }
+        public System.Collections.IEnumerable Properties { get { throw null; } set { } }
     }
     public partial class ProjectEvaluationStartedEventArgs : Microsoft.Build.Framework.BuildStatusEventArgs
     {

ref/Microsoft.Build.Utilities.Core/net/Microsoft.Build.Utilities.Core.cs

@@ -227,6 +227,7 @@ public partial class MuxLogger : Microsoft.Build.Framework.ILogger, Microsoft.Bu
         public MuxLogger() { }
         public bool IncludeEvaluationMetaprojects { get { throw null; } set { } }
         public bool IncludeEvaluationProfiles { get { throw null; } set { } }
+        public bool IncludeEvaluationPropertiesAndItems { get { throw null; } set { } }
         public bool IncludeTaskInputs { get { throw null; } set { } }
         public string Parameters { get { throw null; } set { } }
         public Microsoft.Build.Framework.LoggerVerbosity Verbosity { get { throw null; } set { } }

ref/Microsoft.Build.Utilities.Core/netstandard/Microsoft.Build.Utilities.Core.cs

@@ -72,6 +72,7 @@ public partial class MuxLogger : Microsoft.Build.Framework.ILogger, Microsoft.Bu
         public MuxLogger() { }
         public bool IncludeEvaluationMetaprojects { get { throw null; } set { } }
         public bool IncludeEvaluationProfiles { get { throw null; } set { } }
+        public bool IncludeEvaluationPropertiesAndItems { get { throw null; } set { } }
         public bool IncludeTaskInputs { get { throw null; } set { } }
         public string Parameters { get { throw null; } set { } }
         public Microsoft.Build.Framework.LoggerVerbosity Verbosity { get { throw null; } set { } }

src/Build.UnitTests/BackEnd/MockLoggingService.cs

@@ -5,6 +5,7 @@
 using System.Collections;
 using System.Collections.Generic;
 using Microsoft.Build.Framework;
+using Microsoft.Build.Framework.Profiler;
 using Microsoft.Build.BackEnd.Logging;
 using Microsoft.Build.Logging;
 using Microsoft.Build.Shared;
@@ -203,6 +204,16 @@ public bool IncludeEvaluationProfile
             set { }
         }
 
+        /// <summary>
+        /// Log properties and items on ProjectEvaluationFinishedEventArgs
+        /// instead of ProjectStartedEventArgs.
+        /// </summary>
+        public bool IncludeEvaluationPropertiesAndItems
+        {
+            get => false;
+            set { }
+        }
+
         /// <summary>
         /// Should task events include task inputs?
         /// </summary>
@@ -459,7 +470,13 @@ public void LogProjectEvaluationStarted(BuildEventContext eventContext, string p
         /// <summary>
         /// Logs a project evaluation finished event
         /// </summary>
-        public void LogProjectEvaluationFinished(BuildEventContext projectEvaluationEventContext, string projectFile)
+        public void LogProjectEvaluationFinished(
+            BuildEventContext projectEvaluationEventContext,
+            string projectFile,
+            IEnumerable globalProperties,
+            IEnumerable properties,
+            IEnumerable items,
+            ProfilerResult? profilerResult)
         {
         }
 

src/Build.UnitTests/BackEnd/NodePackets_Tests.cs

@@ -2,6 +2,7 @@
 // Licensed under the MIT license. See LICENSE file in the project root for full license information.
 
 using System;
+using System.Collections;
 using System.Linq;
 using Microsoft.Build.Framework;
 using Microsoft.Build.BackEnd;
@@ -32,6 +33,7 @@ public void LogMessageConstructorNullBuildEvent()
             }
            );
         }
+
         /// <summary>
         /// Verify when creating a LogMessagePacket
         /// that the correct Event Type is set.
@@ -53,6 +55,8 @@ public void VerifyEventType()
             ProjectStartedEventArgs projectStarted = new ProjectStartedEventArgs(-1, "message", "help", "ProjectFile", "targetNames", null, null, null);
             ProjectFinishedEventArgs projectFinished = new ProjectFinishedEventArgs("message", "help", "ProjectFile", true);
             ExternalProjectStartedEventArgs externalStartedEvent = new ExternalProjectStartedEventArgs("message", "help", "senderName", "projectFile", "targetNames");
+            ProjectEvaluationStartedEventArgs evaluationStarted = new ProjectEvaluationStartedEventArgs();
+            ProjectEvaluationFinishedEventArgs evaluationFinished = new ProjectEvaluationFinishedEventArgs();
 
             VerifyLoggingPacket(buildFinished, LoggingEventType.BuildFinishedEvent);
             VerifyLoggingPacket(buildStarted, LoggingEventType.BuildStartedEvent);
@@ -67,16 +71,87 @@ public void VerifyEventType()
             VerifyLoggingPacket(targetFinished, LoggingEventType.TargetFinishedEvent);
             VerifyLoggingPacket(projectStarted, LoggingEventType.ProjectStartedEvent);
             VerifyLoggingPacket(projectFinished, LoggingEventType.ProjectFinishedEvent);
+            VerifyLoggingPacket(evaluationStarted, LoggingEventType.ProjectEvaluationStartedEvent);
+            VerifyLoggingPacket(evaluationFinished, LoggingEventType.ProjectEvaluationFinishedEvent);
             VerifyLoggingPacket(externalStartedEvent, LoggingEventType.CustomEvent);
         }
 
-        private static TaskParameterEventArgs CreateTaskParameter()
+        private static BuildEventContext CreateBuildEventContext()
+        {
+            return new BuildEventContext(1, 2, 3, 4, 5, 6, 7);
+        }
+
+        private static ProjectEvaluationStartedEventArgs CreateProjectEvaluationStarted()
+        {
+            string projectFile = "test.csproj";
+            var result = new ProjectEvaluationStartedEventArgs(
+                ResourceUtilities.GetResourceString("EvaluationStarted"),
+                projectFile)
+            {
+                ProjectFile = projectFile
+            };
+            result.BuildEventContext = CreateBuildEventContext();
+
+            return result;
+        }
+
+        private static ProjectEvaluationFinishedEventArgs CreateProjectEvaluationFinished()
+        {
+            string projectFile = "test.csproj";
+            var result = new ProjectEvaluationFinishedEventArgs(
+                ResourceUtilities.GetResourceString("EvaluationFinished"),
+                projectFile)
+            {
+                ProjectFile = projectFile,
+                GlobalProperties = CreateProperties(),
+                Properties = CreateProperties(),
+                Items = new ArrayList
+                {
+                    new DictionaryEntry("Compile", new TaskItemData("a", null)),
+                    new DictionaryEntry("Compile", new TaskItemData("b", CreateStringDictionary())),
+                    new DictionaryEntry("Reference", new TaskItemData("c", CreateStringDictionary())),
+                }
+            };
+            result.BuildEventContext = CreateBuildEventContext();
+
+            return result;
+        }
+
+        private static IEnumerable CreateProperties()
+        {
+            return new ArrayList
+            {
+                new DictionaryEntry("a", "b"),
+                new DictionaryEntry("c", "d")
+            };
+        }
+
+        private static Dictionary<string, string> CreateStringDictionary()
+        {
+            return new Dictionary<string, string>
+            {
+                { "a", "b" },
+                { "c", "d" }
+            };
+        }
+
+        private static TaskItemData[] CreateTaskItems()
         {
             var items = new TaskItemData[]
             {
                 new TaskItemData("ItemSpec1", null),
-                new TaskItemData("ItemSpec2", Enumerable.Range(1,3).ToDictionary(i => i.ToString(), i => i.ToString() + "value"))
+                new TaskItemData("ItemSpec1", CreateStringDictionary()),
+                new TaskItemData("ItemSpec2", Enumerable.Range(1, 3).ToDictionary(i => i.ToString(), i => i.ToString() + "value"))
             };
+            return items;
+        }
+
+        private static TaskParameterEventArgs CreateTaskParameter()
+        {
+            // touch ItemGroupLoggingHelper to ensure static constructor runs
+            _ = ItemGroupLoggingHelper.ItemGroupIncludeLogMessagePrefix;
+
+            var items = CreateTaskItems();
             var result = new TaskParameterEventArgs(
                 TaskParameterMessageKind.TaskInput,
                 "ItemName",
@@ -88,6 +163,9 @@ private static TaskParameterEventArgs CreateTaskParameter()
             Assert.Equal(@"Task Parameter:
     ItemName=
         ItemSpec1
+        ItemSpec1
+                a=b
+                c=d
         ItemSpec2
                 1=1value
                 2=2value
@@ -127,7 +205,9 @@ public void TestTranslation()
                     new TargetFinishedEventArgs("message", "help", "targetName", "ProjectFile", "targetFile", true, targetOutputs),
                     new ProjectStartedEventArgs(-1, "message", "help", "ProjectFile", "targetNames", null, null, null),
                     new ProjectFinishedEventArgs("message", "help", "ProjectFile", true),
-                    new ExternalProjectStartedEventArgs("message", "help", "senderName", "projectFile", "targetNames")
+                    new ExternalProjectStartedEventArgs("message", "help", "senderName", "projectFile", "targetNames"),
+                    CreateProjectEvaluationStarted(),
+                    CreateProjectEvaluationFinished()
                 };
 
                 foreach (BuildEventArgs arg in testArgs)
@@ -283,6 +363,32 @@ private void CompareLogMessagePackets(LogMessagePacket left, LogMessagePacket ri
                     // Assert.AreEqual(leftProjectStarted.Properties, rightProjectStarted.Properties);
                     break;
 
+                case LoggingEventType.ProjectEvaluationStartedEvent:
+                    ProjectEvaluationStartedEventArgs leftEvaluationStarted = left.NodeBuildEvent.Value.Value as ProjectEvaluationStartedEventArgs;
+                    ProjectEvaluationStartedEventArgs rightEvaluationStarted = right.NodeBuildEvent.Value.Value as ProjectEvaluationStartedEventArgs;
+                    Assert.NotNull(leftEvaluationStarted);
+                    Assert.NotNull(rightEvaluationStarted);
+                    Assert.Equal(leftEvaluationStarted.ProjectFile, rightEvaluationStarted.ProjectFile);
+                    break;
+
+                case LoggingEventType.ProjectEvaluationFinishedEvent:
+                    ProjectEvaluationFinishedEventArgs leftEvaluationFinished = left.NodeBuildEvent.Value.Value as ProjectEvaluationFinishedEventArgs;
+                    ProjectEvaluationFinishedEventArgs rightEvaluationFinished = right.NodeBuildEvent.Value.Value as ProjectEvaluationFinishedEventArgs;
+                    Assert.NotNull(leftEvaluationFinished);
+                    Assert.NotNull(rightEvaluationFinished);
+                    Assert.Equal(leftEvaluationFinished.ProjectFile, rightEvaluationFinished.ProjectFile);
+                    Assert.Equal(leftEvaluationFinished.ProfilerResult, rightEvaluationFinished.ProfilerResult);
+                    Assert.Equal(
+                        TranslationHelpers.GetPropertiesString(leftEvaluationFinished.GlobalProperties),
+                        TranslationHelpers.GetPropertiesString(rightEvaluationFinished.GlobalProperties));
+                    Assert.Equal(
+                        TranslationHelpers.GetPropertiesString(leftEvaluationFinished.Properties),
+                        TranslationHelpers.GetPropertiesString(rightEvaluationFinished.Properties));
+                    Assert.Equal(
+                        TranslationHelpers.GetMultiItemsString(leftEvaluationFinished.Items),
+                        TranslationHelpers.GetMultiItemsString(rightEvaluationFinished.Items));
+                    break;
+
                 case LoggingEventType.TargetFinishedEvent:
                     TargetFinishedEventArgs leftTargetFinished = left.NodeBuildEvent.Value.Value as TargetFinishedEventArgs;
                     TargetFinishedEventArgs rightTargetFinished = right.NodeBuildEvent.Value.Value as TargetFinishedEventArgs;
@@ -292,6 +398,8 @@ private void CompareLogMessagePackets(LogMessagePacket left, LogMessagePacket ri
                     Assert.Equal(leftTargetFinished.Succeeded, rightTargetFinished.Succeeded);
                     Assert.Equal(leftTargetFinished.TargetFile, rightTargetFinished.TargetFile);
                     Assert.Equal(leftTargetFinished.TargetName, rightTargetFinished.TargetName);
+                    //TODO: target output translation is a special case and is done in TranslateTargetFinishedEvent
+                    //Assert.Equal(leftTargetFinished.TargetOutputs, rightTargetFinished.TargetOutputs);
                     break;
 
                 case LoggingEventType.TargetStartedEvent:

src/Build.UnitTests/BackEnd/TranslationHelpers.cs

@@ -2,10 +2,13 @@
 // 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.Linq;
 using System.IO;
+using System.Text;
 using Microsoft.Build.BackEnd;
+using Microsoft.Build.Framework;
 
 namespace Microsoft.Build.UnitTests.BackEnd
 {
@@ -104,5 +107,64 @@ internal static bool CompareExceptions(Exception left, Exception right)
 
             return CompareExceptions(left.InnerException, right.InnerException);
         }
+
+        internal static string GetPropertiesString(IEnumerable properties)
+        {
+            var dictionary = properties
+                .OfType<DictionaryEntry>()
+                .ToDictionary(
+                    (Func<DictionaryEntry, string>)(d => d.Key.ToString()),
+                    (Func<DictionaryEntry, string>)(d => d.Value.ToString()));
+            return ToString(dictionary);
+        }
+
+        internal static string GetMultiItemsString(IEnumerable items)
+        {
+            var list = items
+                .OfType<DictionaryEntry>()
+                .Select(i => i.Key.ToString() + GetTaskItemString(i.Value));
+            var text = string.Join("\n", list);
+            return text;
+        }
+
+        internal static string GetItemsString(IEnumerable items)
+        {
+            var list = items
+                .OfType<object>()
+                .Select(i => GetTaskItemString(i));
+            var text = string.Join("\n", list);
+            return text;
+        }
+
+        internal static string GetTaskItemString(object item)
+        {
+            var sb = new StringBuilder();
+
+            if (item is ITaskItem taskItem)
+            {
+                sb.Append(taskItem.ItemSpec);
+                foreach (string name in taskItem.MetadataNames)
+                {
+                    var value = taskItem.GetMetadata(name);
+                    sb.Append($";{name}={value}");
+                }
+            }
+            else
+            {
+                sb.Append(Convert.ToString(item));
+            }
+
+            return sb.ToString();
+        }
+
+        internal static string ToString(IDictionary<string, string> dictionary)
+        {
+            if (dictionary == null)
+            {
+                return "null";
+            }
+
+            return string.Join(";", dictionary.Select(kvp => kvp.Key + "=" + kvp.Value));
+        }
     }
 }