diff --git a/src/Cli/dotnet/Commands/MSBuild/MSBuildForwardingLogger.cs b/src/Cli/dotnet/Commands/MSBuild/MSBuildForwardingLogger.cs index fc7c6488b910..fef3e251bedc 100644 --- a/src/Cli/dotnet/Commands/MSBuild/MSBuildForwardingLogger.cs +++ b/src/Cli/dotnet/Commands/MSBuild/MSBuildForwardingLogger.cs @@ -26,11 +26,14 @@ public void Initialize(IEventSource eventSource) eventSource4.IncludeEvaluationPropertiesAndItems(); } - // Only forward telemetry events + // Forward telemetry events if (eventSource is IEventSource2 eventSource2) { eventSource2.TelemetryLogged += (sender, args) => BuildEventRedirector.ForwardEvent(args); } + + // Forward build finished events. Is used for logging the aggregated build events. + eventSource.BuildFinished += (sender, args) => BuildEventRedirector.ForwardEvent(args); } public void Initialize(IEventSource eventSource, int nodeCount) diff --git a/src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs b/src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs index 4f4f03506e15..bff8934b1a53 100644 --- a/src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs +++ b/src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs @@ -1,4 +1,4 @@ -// Licensed to the .NET Foundation under one or more agreements. +// Licensed to the .NET Foundation under one or more agreements. // The .NET Foundation licenses this file to you under the MIT license. using System.Globalization; @@ -13,7 +13,7 @@ public sealed class MSBuildLogger : INodeLogger { private readonly IFirstTimeUseNoticeSentinel _sentinel = new FirstTimeUseNoticeSentinel(); - private readonly ITelemetry? _telemetry = null; + private readonly ITelemetry? _telemetry; internal const string TargetFrameworkTelemetryEventName = "targetframeworkeval"; internal const string BuildTelemetryEventName = "build"; @@ -22,6 +22,10 @@ public sealed class MSBuildLogger : INodeLogger internal const string BuildcheckRunEventName = "buildcheck/run"; internal const string BuildcheckRuleStatsEventName = "buildcheck/rule"; + // These two events are aggregated and sent at the end of the build. + internal const string TaskFactoryTelemetryAggregatedEventName = "build/tasks/taskfactory"; + internal const string TasksTelemetryAggregatedEventName = "build/tasks"; + internal const string SdkTaskBaseCatchExceptionTelemetryEventName = "taskBaseCatchException"; internal const string PublishPropertiesTelemetryEventName = "PublishProperties"; internal const string WorkloadPublishPropertiesTelemetryEventName = "WorkloadPublishProperties"; @@ -48,6 +52,15 @@ public sealed class MSBuildLogger : INodeLogger /// internal const string SdkContainerPublishErrorEventName = "sdk/container/publish/error"; + /// + /// Stores aggregated telemetry data by event name and property name. + /// + /// + /// Key: event name, Value: property name to aggregated count. + /// Aggregation is very basic. Only integer properties are aggregated by summing values. Non-integer properties are ignored. + /// + private Dictionary> _aggregatedEvents = new(); + public MSBuildLogger() { try @@ -73,6 +86,14 @@ public MSBuildLogger() } } + /// + /// Constructor for testing purposes. + /// + internal MSBuildLogger(ITelemetry telemetry) + { + _telemetry = telemetry; + } + public void Initialize(IEventSource eventSource, int nodeCount) { Initialize(eventSource); @@ -95,6 +116,8 @@ public void Initialize(IEventSource eventSource) { eventSource2.TelemetryLogged += OnTelemetryLogged; } + + eventSource.BuildFinished += OnBuildFinished; } } catch (Exception) @@ -103,37 +126,103 @@ public void Initialize(IEventSource eventSource) } } + private void OnBuildFinished(object sender, BuildFinishedEventArgs e) + { + SendAggregatedEventsOnBuildFinished(_telemetry); + } + + internal void SendAggregatedEventsOnBuildFinished(ITelemetry? telemetry) + { + if (_aggregatedEvents.TryGetValue(TaskFactoryTelemetryAggregatedEventName, out var taskFactoryData)) + { + var taskFactoryProperties = ConvertToStringDictionary(taskFactoryData); + + TrackEvent(telemetry, $"msbuild/{TaskFactoryTelemetryAggregatedEventName}", taskFactoryProperties, toBeHashed: [], toBeMeasured: []); + _aggregatedEvents.Remove(TaskFactoryTelemetryAggregatedEventName); + } + + if (_aggregatedEvents.TryGetValue(TasksTelemetryAggregatedEventName, out var tasksData)) + { + var tasksProperties = ConvertToStringDictionary(tasksData); + + TrackEvent(telemetry, $"msbuild/{TasksTelemetryAggregatedEventName}", tasksProperties, toBeHashed: [], toBeMeasured: []); + _aggregatedEvents.Remove(TasksTelemetryAggregatedEventName); + } + } + + private static Dictionary ConvertToStringDictionary(Dictionary properties) + { + Dictionary stringProperties = new(); + foreach (var kvp in properties) + { + stringProperties[kvp.Key] = kvp.Value.ToString(CultureInfo.InvariantCulture); + } + + return stringProperties; + } + + internal void AggregateEvent(TelemetryEventArgs args) + { + if (args.EventName is null) + { + return; + } + + if (!_aggregatedEvents.TryGetValue(args.EventName, out var eventData)) + { + eventData = []; + _aggregatedEvents[args.EventName] = eventData; + } + + foreach (var kvp in args.Properties) + { + if (int.TryParse(kvp.Value, CultureInfo.InvariantCulture, out int count)) + { + if (!eventData.ContainsKey(kvp.Key)) + { + eventData[kvp.Key] = count; + } + else + { + eventData[kvp.Key] += count; + } + } + } + } + internal static void FormatAndSend(ITelemetry? telemetry, TelemetryEventArgs args) { switch (args.EventName) { case TargetFrameworkTelemetryEventName: - TrackEvent(telemetry, $"msbuild/{TargetFrameworkTelemetryEventName}", args.Properties, [], []); + TrackEvent(telemetry, $"msbuild/{TargetFrameworkTelemetryEventName}", args.Properties); break; case BuildTelemetryEventName: TrackEvent(telemetry, $"msbuild/{BuildTelemetryEventName}", args.Properties, toBeHashed: ["ProjectPath", "BuildTarget"], - toBeMeasured: ["BuildDurationInMilliseconds", "InnerBuildDurationInMilliseconds"]); + toBeMeasured: ["BuildDurationInMilliseconds", "InnerBuildDurationInMilliseconds"] + ); break; case LoggingConfigurationTelemetryEventName: TrackEvent(telemetry, $"msbuild/{LoggingConfigurationTelemetryEventName}", args.Properties, - toBeHashed: [], - toBeMeasured: ["FileLoggersCount"]); + toBeMeasured: ["FileLoggersCount"] + ); break; case BuildcheckAcquisitionFailureEventName: TrackEvent(telemetry, $"msbuild/{BuildcheckAcquisitionFailureEventName}", args.Properties, - toBeHashed: ["AssemblyName", "ExceptionType", "ExceptionMessage"], - toBeMeasured: []); + toBeHashed: ["AssemblyName", "ExceptionType", "ExceptionMessage"] + ); break; case BuildcheckRunEventName: TrackEvent(telemetry, $"msbuild/{BuildcheckRunEventName}", args.Properties, - toBeHashed: [], - toBeMeasured: ["TotalRuntimeInMilliseconds"]); + toBeMeasured: ["TotalRuntimeInMilliseconds"] + ); break; case BuildcheckRuleStatsEventName: TrackEvent(telemetry, $"msbuild/{BuildcheckRuleStatsEventName}", args.Properties, toBeHashed: ["RuleId", "CheckFriendlyName"], - toBeMeasured: ["TotalRuntimeInMilliseconds"]); + toBeMeasured: ["TotalRuntimeInMilliseconds"] + ); break; // Pass through events that don't need special handling case SdkTaskBaseCatchExceptionTelemetryEventName: @@ -143,7 +232,7 @@ internal static void FormatAndSend(ITelemetry? telemetry, TelemetryEventArgs arg case SdkContainerPublishBaseImageInferenceEventName: case SdkContainerPublishSuccessEventName: case SdkContainerPublishErrorEventName: - TrackEvent(telemetry, args.EventName, args.Properties, [], []); + TrackEvent(telemetry, args.EventName, args.Properties); break; default: // Ignore unknown events @@ -151,7 +240,7 @@ internal static void FormatAndSend(ITelemetry? telemetry, TelemetryEventArgs arg } } - private static void TrackEvent(ITelemetry? telemetry, string eventName, IDictionary eventProperties, string[]? toBeHashed, string[]? toBeMeasured) + private static void TrackEvent(ITelemetry? telemetry, string eventName, IDictionary eventProperties, string[]? toBeHashed = null, string[]? toBeMeasured = null) { if (telemetry == null || !telemetry.Enabled) { @@ -168,7 +257,7 @@ private static void TrackEvent(ITelemetry? telemetry, string eventName, IDiction if (eventProperties.TryGetValue(propertyToBeHashed, out var value)) { // Lets lazy allocate in case there is tons of telemetry - properties ??= new Dictionary(eventProperties); + properties ??= new(eventProperties); properties[propertyToBeHashed] = Sha256Hasher.HashWithNormalizedCasing(value!); } } @@ -178,10 +267,10 @@ private static void TrackEvent(ITelemetry? telemetry, string eventName, IDiction { foreach (var propertyToBeMeasured in toBeMeasured) { - if (eventProperties.TryGetValue(propertyToBeMeasured, out string? value)) + if (eventProperties.TryGetValue(propertyToBeMeasured, out var value)) { // Lets lazy allocate in case there is tons of telemetry - properties ??= new Dictionary(eventProperties); + properties ??= new(eventProperties); properties.Remove(propertyToBeMeasured); if (double.TryParse(value, CultureInfo.InvariantCulture, out double realValue)) { @@ -198,7 +287,14 @@ private static void TrackEvent(ITelemetry? telemetry, string eventName, IDiction private void OnTelemetryLogged(object sender, TelemetryEventArgs args) { - FormatAndSend(_telemetry, args); + if (args.EventName == TaskFactoryTelemetryAggregatedEventName || args.EventName == TasksTelemetryAggregatedEventName) + { + AggregateEvent(args); + } + else + { + FormatAndSend(_telemetry, args); + } } public void Shutdown() @@ -214,5 +310,6 @@ public void Shutdown() } public LoggerVerbosity Verbosity { get; set; } + public string? Parameters { get; set; } } diff --git a/src/Resolvers/Microsoft.DotNet.MSBuildSdkResolver/MSBuildSdkResolver.cs b/src/Resolvers/Microsoft.DotNet.MSBuildSdkResolver/MSBuildSdkResolver.cs index 6b891c586a23..ae38c8e2f61c 100644 --- a/src/Resolvers/Microsoft.DotNet.MSBuildSdkResolver/MSBuildSdkResolver.cs +++ b/src/Resolvers/Microsoft.DotNet.MSBuildSdkResolver/MSBuildSdkResolver.cs @@ -32,7 +32,7 @@ public sealed class DotNetMSBuildSdkResolver : SdkResolver private readonly Func _getMsbuildRuntime; private readonly NETCoreSdkResolver _netCoreSdkResolver; - private const string DOTNET_HOST = nameof(DOTNET_HOST); + private const string DOTNET_HOST_PATH = nameof(DOTNET_HOST_PATH); private const string DotnetHostExperimentalKey = "DOTNET_EXPERIMENTAL_HOST_PATH"; private const string MSBuildTaskHostRuntimeVersion = "SdkResolverMSBuildTaskHostRuntimeVersion"; private const string SdkResolverHonoredGlobalJson = "SdkResolverHonoredGlobalJson"; @@ -245,12 +245,12 @@ private sealed class CachedState // this is the future-facing implementation. environmentVariablesToAdd ??= new Dictionary(1) { - [DOTNET_HOST] = fullPathToMuxer + [DOTNET_HOST_PATH] = fullPathToMuxer }; } else { - logger?.LogMessage($"Could not set '{DOTNET_HOST}' environment variable because dotnet executable '{fullPathToMuxer}' does not exist."); + logger?.LogMessage($"Could not set '{DOTNET_HOST_PATH}' environment variable because dotnet executable '{fullPathToMuxer}' does not exist."); } string? runtimeVersion = dotnetRoot != null ? diff --git a/test/Microsoft.NET.Publish.Tests/GivenThatWeWantToPublishAnAotApp.cs b/test/Microsoft.NET.Publish.Tests/GivenThatWeWantToPublishAnAotApp.cs index a4cfbcb6d1f6..20afab0e873f 100644 --- a/test/Microsoft.NET.Publish.Tests/GivenThatWeWantToPublishAnAotApp.cs +++ b/test/Microsoft.NET.Publish.Tests/GivenThatWeWantToPublishAnAotApp.cs @@ -546,7 +546,8 @@ private void OverrideKnownILCompilerPackRuntimeIdentifiers(XDocument project, st project.Root.Add(new XElement(ns + "ItemGroup", new XElement(ns + "KnownILCompilerPack", new XAttribute("Update", "@(KnownILCompilerPack)"), - new XElement(ns + "ILCompilerRuntimeIdentifiers", runtimeIdentifiers)))); + new XElement(ns + "ILCompilerRuntimeIdentifiers", runtimeIdentifiers), + new XElement(ns + "ILCompilerPortableRuntimeIdentifiers", runtimeIdentifiers)))); } [RequiresMSBuildVersionTheory("17.0.0.32901")] diff --git a/test/Microsoft.NET.Publish.Tests/GivenThatWeWantToPublishIncrementally.cs b/test/Microsoft.NET.Publish.Tests/GivenThatWeWantToPublishIncrementally.cs index c47c60089692..9cd038e21ff5 100644 --- a/test/Microsoft.NET.Publish.Tests/GivenThatWeWantToPublishIncrementally.cs +++ b/test/Microsoft.NET.Publish.Tests/GivenThatWeWantToPublishIncrementally.cs @@ -134,7 +134,7 @@ public void It_cleans_between_single_file_publishes() CheckPublishOutput(publishDir, expectedSingleExeFiles.Append(testProject.Name + ".dll"), null); } - [Fact] + [Fact(Skip = "https://github.com/dotnet/sdk/issues/50784")] public void It_cleans_before_trimmed_single_file_publish() { var testProject = new TestProject() diff --git a/test/dotnet.Tests/CommandTests/MSBuild/FakeTelemetry.cs b/test/dotnet.Tests/CommandTests/MSBuild/FakeTelemetry.cs index 2f131031b24e..bcb6a6dbfde1 100644 --- a/test/dotnet.Tests/CommandTests/MSBuild/FakeTelemetry.cs +++ b/test/dotnet.Tests/CommandTests/MSBuild/FakeTelemetry.cs @@ -11,10 +11,12 @@ public class FakeTelemetry : ITelemetry { public bool Enabled { get; set; } = true; + private readonly List _logEntries = new List(); + public void TrackEvent(string eventName, IDictionary properties, IDictionary measurements) { - LogEntry = new LogEntry { EventName = eventName, Properties = properties, Measurement = measurements }; - + var entry = new LogEntry { EventName = eventName, Properties = properties, Measurement = measurements }; + _logEntries.Add(entry); } public void Flush() @@ -25,8 +27,8 @@ public void Dispose() { } - public LogEntry LogEntry { get; private set; } + public LogEntry LogEntry => _logEntries.Count > 0 ? _logEntries[_logEntries.Count - 1] : null; + public IReadOnlyList LogEntries => _logEntries.AsReadOnly(); } - } diff --git a/test/dotnet.Tests/CommandTests/MSBuild/GivenMSBuildLogger.cs b/test/dotnet.Tests/CommandTests/MSBuild/GivenMSBuildLogger.cs index dc0ca30e12f8..12a75b9493ee 100644 --- a/test/dotnet.Tests/CommandTests/MSBuild/GivenMSBuildLogger.cs +++ b/test/dotnet.Tests/CommandTests/MSBuild/GivenMSBuildLogger.cs @@ -118,5 +118,101 @@ public void ItCanSendProperties() fakeTelemetry.LogEntry.Properties.Should().BeEquivalentTo(telemetryEventArgs.Properties); } + + [Fact] + public void ItAggregatesEvents() + { + var fakeTelemetry = new FakeTelemetry(); + fakeTelemetry.Enabled = true; + var logger = new MSBuildLogger(fakeTelemetry); + + var event1 = new TelemetryEventArgs + { + EventName = MSBuildLogger.TaskFactoryTelemetryAggregatedEventName, + Properties = new Dictionary + { + { "AssemblyTaskFactoryTasksExecutedCount", "2" }, + { "RoslynCodeTaskFactoryTasksExecutedCount", "1" } + } + }; + + var event2 = new TelemetryEventArgs + { + EventName = MSBuildLogger.TaskFactoryTelemetryAggregatedEventName, + Properties = new Dictionary + { + { "AssemblyTaskFactoryTasksExecutedCount", "3" }, + { "CustomTaskFactoryTasksExecutedCount", "2" } + } + }; + + var event3 = new TelemetryEventArgs + { + EventName = MSBuildLogger.TasksTelemetryAggregatedEventName, + Properties = new Dictionary + { + { "TasksExecutedCount", "3" }, + { "TaskHostTasksExecutedCount", "2" } + } + }; + + var event4 = new TelemetryEventArgs + { + EventName = MSBuildLogger.TasksTelemetryAggregatedEventName, + Properties = new Dictionary + { + { "TasksExecutedCount", "5" } + } + }; + + logger.AggregateEvent(event1); + logger.AggregateEvent(event2); + logger.AggregateEvent(event3); + logger.AggregateEvent(event4); + + logger.SendAggregatedEventsOnBuildFinished(fakeTelemetry); + + fakeTelemetry.LogEntries.Should().HaveCount(2); + + var taskFactoryEntry = fakeTelemetry.LogEntries.FirstOrDefault(e => e.EventName == $"msbuild/{MSBuildLogger.TaskFactoryTelemetryAggregatedEventName}"); + taskFactoryEntry.Should().NotBeNull(); + taskFactoryEntry.Properties["AssemblyTaskFactoryTasksExecutedCount"].Should().Be("5"); // 2 + 3 + taskFactoryEntry.Properties["RoslynCodeTaskFactoryTasksExecutedCount"].Should().Be("1"); // 1 + 0 + taskFactoryEntry.Properties["CustomTaskFactoryTasksExecutedCount"].Should().Be("2"); // 0 + 2 + + var tasksEntry = fakeTelemetry.LogEntries.FirstOrDefault(e => e.EventName == $"msbuild/{MSBuildLogger.TasksTelemetryAggregatedEventName}"); + tasksEntry.Should().NotBeNull(); + tasksEntry.Properties["TasksExecutedCount"].Should().Be("8"); // 3 + 5 + tasksEntry.Properties["TaskHostTasksExecutedCount"].Should().Be("2"); // 2 + 0 + } + + [Fact] + public void ItIgnoresNonIntegerPropertiesDuringAggregation() + { + var fakeTelemetry = new FakeTelemetry(); + fakeTelemetry.Enabled = true; + var logger = new MSBuildLogger(fakeTelemetry); + + var eventArgs = new TelemetryEventArgs + { + EventName = MSBuildLogger.TaskFactoryTelemetryAggregatedEventName, + Properties = new Dictionary + { + { "AssemblyTaskFactoryTasksExecutedCount", "3" }, + { "InvalidProperty", "not-a-number" }, + { "InvalidProperty2", "1.234" }, + } + }; + + logger.AggregateEvent(eventArgs); + + logger.SendAggregatedEventsOnBuildFinished(fakeTelemetry); + + fakeTelemetry.LogEntry.Should().NotBeNull(); + fakeTelemetry.LogEntry.EventName.Should().Be($"msbuild/{MSBuildLogger.TaskFactoryTelemetryAggregatedEventName}"); + fakeTelemetry.LogEntry.Properties["AssemblyTaskFactoryTasksExecutedCount"].Should().Be("3"); + fakeTelemetry.LogEntry.Properties.Should().NotContainKey("InvalidProperty"); + fakeTelemetry.LogEntry.Properties.Should().NotContainKey("InvalidProperty2"); + } } }