Introduce TaskParameterEventArgs (#6155)

Instead of just logging a BuildMessageEventArgs with a list of all items and metadata concatenated into a large string (often 5 MB in size or more) it keeps a structured representation of items and metadata. TaskParameterEventArgs inherits from BuildMessageEventArgs and the Message implementation materializes the large string on demand. However when only the BinaryLogger is present the Message is never accessed, thus saving on allocations. The Message is also never sent across the nodes nor written into the binlog.

TaskParameterEventArgs is instantiated in 5 locations: ItemGroup Include and Remove inside targets, task inputs, and two cases for task outputs.

Storing smaller strings in the binlog results in very significant savings from string deduplication. A 22 MB binlog goes down to 3.5 MB in size. We're also seeing build speed improvements from 33 seconds to 30 seconds. Significant reduction in memory allocations since we no longer need to allocate the large strings and send them across the nodes.

Author: KirillOsenkov

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

@@ -38,6 +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 { } }
         public string SenderName { get { throw null; } }
         public int ThreadId { get { throw null; } }
         public System.DateTime Timestamp { get { throw null; } }
@@ -589,6 +590,22 @@ public TaskFinishedEventArgs(string message, string helpKeyword, string projectF
         public string TaskName { get { throw null; } }
     }
     public delegate void TaskFinishedEventHandler(object sender, Microsoft.Build.Framework.TaskFinishedEventArgs e);
+    public partial class TaskParameterEventArgs : Microsoft.Build.Framework.BuildMessageEventArgs
+    {
+        public TaskParameterEventArgs(Microsoft.Build.Framework.TaskParameterMessageKind kind, string itemType, System.Collections.IList items, bool logItemMetadata, System.DateTime eventTimestamp) { }
+        public System.Collections.IList Items { get { throw null; } }
+        public string ItemType { get { throw null; } }
+        public Microsoft.Build.Framework.TaskParameterMessageKind Kind { get { throw null; } }
+        public bool LogItemMetadata { get { throw null; } }
+        public override string Message { get { throw null; } }
+    }
+    public enum TaskParameterMessageKind
+    {
+        TaskInput = 0,
+        TaskOutput = 1,
+        AddItem = 2,
+        RemoveItem = 3,
+    }
     public partial class TaskPropertyInfo
     {
         public TaskPropertyInfo(string name, System.Type typeOfParameter, bool output, bool required) { }

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

@@ -38,6 +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 { } }
         public string SenderName { get { throw null; } }
         public int ThreadId { get { throw null; } }
         public System.DateTime Timestamp { get { throw null; } }
@@ -588,6 +589,22 @@ public TaskFinishedEventArgs(string message, string helpKeyword, string projectF
         public string TaskName { get { throw null; } }
     }
     public delegate void TaskFinishedEventHandler(object sender, Microsoft.Build.Framework.TaskFinishedEventArgs e);
+    public partial class TaskParameterEventArgs : Microsoft.Build.Framework.BuildMessageEventArgs
+    {
+        public TaskParameterEventArgs(Microsoft.Build.Framework.TaskParameterMessageKind kind, string itemType, System.Collections.IList items, bool logItemMetadata, System.DateTime eventTimestamp) { }
+        public System.Collections.IList Items { get { throw null; } }
+        public string ItemType { get { throw null; } }
+        public Microsoft.Build.Framework.TaskParameterMessageKind Kind { get { throw null; } }
+        public bool LogItemMetadata { get { throw null; } }
+        public override string Message { get { throw null; } }
+    }
+    public enum TaskParameterMessageKind
+    {
+        TaskInput = 0,
+        TaskOutput = 1,
+        AddItem = 2,
+        RemoveItem = 3,
+    }
     public partial class TaskPropertyInfo
     {
         public TaskPropertyInfo(string name, System.Type typeOfParameter, bool output, bool required) { }

src/Build.UnitTests/BackEnd/EventSourceSink_Tests.cs

@@ -68,6 +68,7 @@ public void ConsumeEventsGoodEventsNoHandlers()
             eventHelper.RaiseBuildEvent(RaiseEventHelper.NormalMessage);
             eventHelper.RaiseBuildEvent(RaiseEventHelper.TaskFinished);
             eventHelper.RaiseBuildEvent(RaiseEventHelper.CommandLine);
+            eventHelper.RaiseBuildEvent(RaiseEventHelper.TaskParameter);
             eventHelper.RaiseBuildEvent(RaiseEventHelper.Warning);
             eventHelper.RaiseBuildEvent(RaiseEventHelper.Error);
             eventHelper.RaiseBuildEvent(RaiseEventHelper.TargetStarted);
@@ -99,6 +100,7 @@ public void LoggerExceptionInEventHandler()
                 RaiseExceptionInEventHandler(RaiseEventHelper.NormalMessage, exception);
                 RaiseExceptionInEventHandler(RaiseEventHelper.TaskFinished, exception);
                 RaiseExceptionInEventHandler(RaiseEventHelper.CommandLine, exception);
+                RaiseExceptionInEventHandler(RaiseEventHelper.TaskParameter, exception);
                 RaiseExceptionInEventHandler(RaiseEventHelper.Warning, exception);
                 RaiseExceptionInEventHandler(RaiseEventHelper.Error, exception);
                 RaiseExceptionInEventHandler(RaiseEventHelper.TargetStarted, exception);
@@ -733,6 +735,11 @@ internal class RaiseEventHelper
             /// </summary>
             private static TaskCommandLineEventArgs s_taskCommandLine = new TaskCommandLineEventArgs("commandLine", "taskName", MessageImportance.Low);
 
+            /// <summary>
+            /// Task Parameter Event
+            /// </summary>
+            private static TaskParameterEventArgs s_taskParameter = new TaskParameterEventArgs(TaskParameterMessageKind.TaskInput, "ItemName", null, true, DateTime.MinValue);
+
             /// <summary>
             /// Build Warning Event
             /// </summary>
@@ -883,6 +890,11 @@ internal static TaskCommandLineEventArgs CommandLine
                 }
             }
 
+            /// <summary>
+            /// Event which can be raised in multiple tests.
+            /// </summary>
+            internal static TaskParameterEventArgs TaskParameter => s_taskParameter;
+
             /// <summary>
             /// Event which can be raised in multiple tests.
             /// </summary>

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.Linq;
 using Microsoft.Build.Framework;
 using Microsoft.Build.BackEnd;
 using Microsoft.Build.Shared;
@@ -44,6 +45,7 @@ public void VerifyEventType()
             TaskStartedEventArgs taskStarted = new TaskStartedEventArgs("message", "help", "projectFile", "taskFile", "taskName");
             TaskFinishedEventArgs taskFinished = new TaskFinishedEventArgs("message", "help", "projectFile", "taskFile", "taskName", true);
             TaskCommandLineEventArgs commandLine = new TaskCommandLineEventArgs("commandLine", "taskName", MessageImportance.Low);
+            TaskParameterEventArgs taskParameter = CreateTaskParameter();
             BuildWarningEventArgs warning = new BuildWarningEventArgs("SubCategoryForSchemaValidationErrors", "MSB4000", "file", 1, 2, 3, 4, "message", "help", "sender");
             BuildErrorEventArgs error = new BuildErrorEventArgs("SubCategoryForSchemaValidationErrors", "MSB4000", "file", 1, 2, 3, 4, "message", "help", "sender");
             TargetStartedEventArgs targetStarted = new TargetStartedEventArgs("message", "help", "targetName", "ProjectFile", "targetFile");
@@ -58,6 +60,7 @@ public void VerifyEventType()
             VerifyLoggingPacket(taskStarted, LoggingEventType.TaskStartedEvent);
             VerifyLoggingPacket(taskFinished, LoggingEventType.TaskFinishedEvent);
             VerifyLoggingPacket(commandLine, LoggingEventType.TaskCommandLineEvent);
+            VerifyLoggingPacket(taskParameter, LoggingEventType.TaskParameterEvent);
             VerifyLoggingPacket(warning, LoggingEventType.BuildWarningEvent);
             VerifyLoggingPacket(error, LoggingEventType.BuildErrorEvent);
             VerifyLoggingPacket(targetStarted, LoggingEventType.TargetStartedEvent);
@@ -67,12 +70,41 @@ public void VerifyEventType()
             VerifyLoggingPacket(externalStartedEvent, LoggingEventType.CustomEvent);
         }
 
+        private static TaskParameterEventArgs CreateTaskParameter()
+        {
+            var items = new TaskItemData[]
+            {
+                new TaskItemData("ItemSpec1", null),
+                new TaskItemData("ItemSpec2", Enumerable.Range(1,3).ToDictionary(i => i.ToString(), i => i.ToString() + "value"))
+            };
+            var result = new TaskParameterEventArgs(
+                TaskParameterMessageKind.TaskInput,
+                "ItemName",
+                items,
+                logItemMetadata: true,
+                DateTime.MinValue);
+
+            // normalize line endings as we can't rely on the line endings of NodePackets_Tests.cs
+            Assert.Equal(@"Task Parameter:
+    ItemName=
+        ItemSpec1
+        ItemSpec2
+                1=1value
+                2=2value
+                3=3value".Replace("\r\n", "\n"), result.Message);
+
+            return result;
+        }
+
         /// <summary>
         /// Tests serialization of LogMessagePacket with each kind of event type.
         /// </summary>
         [Fact]
         public void TestTranslation()
         {
+            // need to touch the type so that the static constructor runs
+            _ = ItemGroupLoggingHelper.OutputItemParameterMessagePrefix;
+
             TaskItem item = new TaskItem("Hello", "my.proj");
             List<TaskItem> targetOutputs = new List<TaskItem>();
             targetOutputs.Add(item);
@@ -88,6 +120,7 @@ public void TestTranslation()
                     new TaskStartedEventArgs("message", "help", "projectFile", "taskFile", "taskName"),
                     new TaskFinishedEventArgs("message", "help", "projectFile", "taskFile", "taskName", true),
                     new TaskCommandLineEventArgs("commandLine", "taskName", MessageImportance.Low),
+                    CreateTaskParameter(),
                     new BuildWarningEventArgs("SubCategoryForSchemaValidationErrors", "MSB4000", "file", 1, 2, 3, 4, "message", "help", "sender"),
                     new BuildErrorEventArgs("SubCategoryForSchemaValidationErrors", "MSB4000", "file", 1, 2, 3, 4, "message", "help", "sender"),
                     new TargetStartedEventArgs("message", "help", "targetName", "ProjectFile", "targetFile"),
@@ -281,6 +314,19 @@ private void CompareLogMessagePackets(LogMessagePacket left, LogMessagePacket ri
                     Assert.Equal(leftCommand.TaskName, rightCommand.TaskName);
                     break;
 
+                case LoggingEventType.TaskParameterEvent:
+                    var leftTaskParameter = left.NodeBuildEvent.Value.Value as TaskParameterEventArgs;
+                    var rightTaskParameter = right.NodeBuildEvent.Value.Value as TaskParameterEventArgs;
+                    Assert.NotNull(leftTaskParameter);
+                    Assert.NotNull(rightTaskParameter);
+                    Assert.Equal(leftTaskParameter.Kind, rightTaskParameter.Kind);
+                    Assert.Equal(leftTaskParameter.ItemType, rightTaskParameter.ItemType);
+                    Assert.Equal(leftTaskParameter.Items.Count, rightTaskParameter.Items.Count);
+                    Assert.Equal(leftTaskParameter.Message, rightTaskParameter.Message);
+                    Assert.Equal(leftTaskParameter.BuildEventContext, rightTaskParameter.BuildEventContext);
+                    Assert.Equal(leftTaskParameter.Timestamp, rightTaskParameter.Timestamp);
+                    break;
+
                 case LoggingEventType.TaskFinishedEvent:
                     TaskFinishedEventArgs leftTaskFinished = left.NodeBuildEvent.Value.Value as TaskFinishedEventArgs;
                     TaskFinishedEventArgs rightTaskFinished = right.NodeBuildEvent.Value.Value as TaskFinishedEventArgs;

src/Build.UnitTests/BinaryLogger_Tests.cs

@@ -7,7 +7,7 @@ namespace Microsoft.Build.UnitTests
 {
     public class BinaryLoggerTests : IDisposable
     {
-        private static string s_testProject = @"
+        private const string s_testProject = @"
          <Project xmlns='http://schemas.microsoft.com/developer/msbuild/2003'>
             <PropertyGroup>
                <TestProperty>Test</TestProperty>
@@ -22,6 +22,38 @@ public class BinaryLoggerTests : IDisposable
                <Exec Command='echo a'/>
             </Target>
          </Project>";
+
+        private const string s_testProject2 = @"
+        <Project>
+            <ItemGroup>
+            <Compile Include=""0.cs"" />
+            </ItemGroup>
+            <ItemDefinitionGroup>
+            <Compile>
+                <MetadataFromItemDefinition>fromItemDefinition%61%62%63&lt;&gt;</MetadataFromItemDefinition>
+            </Compile>
+            </ItemDefinitionGroup>
+            <Target Name=""Build"" Outputs=""@(CombinedOutput)"">
+            <ItemGroup>
+                <Compile Include=""1.cs"">
+                <MetadataName>MetadataValue1%61%62%63&lt;&gt;</MetadataName>
+                </Compile>
+                <Compile Remove=""1.cs"" />
+                <Compile Include=""2.cs"" />
+                <Compile Include=""3.cs"">
+                <CustomMetadata>custom%61%62%63&lt;&gt;</CustomMetadata>
+                </Compile>
+            </ItemGroup>
+            <Message Importance=""High"" Condition=""$(Test) != true"" Text=""Hello"" />
+            <CombinePath BasePath=""base"" Paths=""@(Compile)"">
+                <Output TaskParameter=""CombinedPaths"" ItemName=""CombinedOutput""/>
+            </CombinePath>
+            <ItemGroup>
+                <Compile Remove=""2.cs"" />
+            </ItemGroup>
+            </Target>
+        </Project>";
+
         private readonly TestEnvironment _env;
         private string _logFile;
 
@@ -35,8 +67,10 @@ public BinaryLoggerTests(ITestOutputHelper output)
             _logFile = _env.ExpectFile(".binlog").Path;
         }
 
-        [Fact]
-        public void TestBinaryLoggerRoundtrip()
+        [Theory]
+        [InlineData(s_testProject)]
+        [InlineData(s_testProject2)]
+        public void TestBinaryLoggerRoundtrip(string projectText)
         {
             var binaryLogger = new BinaryLogger();
 
@@ -45,14 +79,14 @@ public void TestBinaryLoggerRoundtrip()
             var mockLogFromBuild = new MockLogger();
 
             // build and log into binary logger and mockLogger1
-            ObjectModelHelpers.BuildProjectExpectSuccess(s_testProject, binaryLogger, mockLogFromBuild);
+            ObjectModelHelpers.BuildProjectExpectSuccess(projectText, binaryLogger, mockLogFromBuild);
 
             var mockLogFromPlayback = new MockLogger();
 
             var binaryLogReader = new BinaryLogReplayEventSource();
             mockLogFromPlayback.Initialize(binaryLogReader);
 
-            // read the binary log and replay into mockLogger2testassembly
+            // read the binary log and replay into mockLogger2
             binaryLogReader.Replay(_logFile);
 
             // the binlog will have more information than recorded by the text log

src/Build.UnitTests/BuildEventArgsSerialization_Tests.cs

@@ -1,9 +1,10 @@
-using System;
+using System;
 using System.Collections;
 using System.Collections.Generic;
 using System.IO;
 using System.Linq;
 using System.Text;
+using Microsoft.Build.BackEnd;
 using Microsoft.Build.Framework;
 using Microsoft.Build.Framework.Profiler;
 using Microsoft.Build.Logging;
@@ -70,21 +71,39 @@ public void RoundtripProjectStartedEventArgs()
                 toolsVersion: "Current");
             args.BuildEventContext = new BuildEventContext(1, 2, 3, 4, 5, 6);
 
-            Roundtrip(args,
+            Roundtrip<ProjectStartedEventArgs>(args,
                 e => ToString(e.BuildEventContext),
                 e => ToString(e.GlobalProperties),
-                e => ToString(e.Items.OfType<DictionaryEntry>().ToDictionary(d => d.Key.ToString(), d => ((ITaskItem)d.Value).ItemSpec)),
+                e => GetItemsString(e.Items),
                 e => e.Message,
                 e => ToString(e.ParentProjectBuildEventContext),
                 e => e.ProjectFile,
                 e => e.ProjectId.ToString(),
-                e => ToString(e.Properties.OfType<DictionaryEntry>().ToDictionary(d => d.Key.ToString(), d => d.Value.ToString())),
+                e => ToString(e.Properties.OfType<DictionaryEntry>().ToDictionary((Func<DictionaryEntry, string>)(d => d.Key.ToString()), (Func<DictionaryEntry, string>)(d => d.Value.ToString()))),
                 e => e.TargetNames,
                 e => e.ThreadId.ToString(),
                 e => e.Timestamp.ToString(),
                 e => e.ToolsVersion);
         }
 
+        private string GetItemsString(IEnumerable items)
+        {
+            return ToString(items.OfType<DictionaryEntry>().ToDictionary(d => d.Key.ToString(), d => GetTaskItemString((ITaskItem)d.Value)));
+        }
+
+        private string GetTaskItemString(ITaskItem taskItem)
+        {
+            var sb = new StringBuilder();
+            sb.Append(taskItem.ItemSpec);
+            foreach (string name in taskItem.MetadataNames)
+            {
+                var value = taskItem.GetMetadata(name);
+                sb.Append($";{name}={value}");
+            }
+
+            return sb.ToString();
+        }
+
         [Fact]
         public void RoundtripProjectFinishedEventArgs()
         {
@@ -309,6 +328,23 @@ public void RoundtripTaskCommandLineEventArgs()
                 e => e.Subcategory);
         }
 
+        [Fact]
+        public void RoundtripTaskParameterEventArgs()
+        {
+            var items = new TaskItemData[]
+            {
+                new TaskItemData("ItemSpec1", null),
+                new TaskItemData("ItemSpec2", Enumerable.Range(1,3).ToDictionary(i => i.ToString(), i => i.ToString() + "value"))
+            };
+            var args = new TaskParameterEventArgs(TaskParameterMessageKind.TaskOutput, "ItemName", items, true, DateTime.MinValue);
+
+            Roundtrip(args,
+                e => e.Kind.ToString(),
+                e => e.ItemType,
+                e => e.LogItemMetadata.ToString(),
+                e => GetItemsString(e.Items));
+        }
+
         [Fact]
         public void RoundtripProjectEvaluationStartedEventArgs()
         {