diff --git a/scripts/Deploy-MSBuild.ps1 b/scripts/Deploy-MSBuild.ps1 index d28cc4646c2..f8b390ac93a 100644 --- a/scripts/Deploy-MSBuild.ps1 +++ b/scripts/Deploy-MSBuild.ps1 @@ -129,6 +129,7 @@ if ($runtime -eq "Desktop") { FileToCopy "$bootstrapBinDirectory\System.Buffers.dll" FileToCopy "$bootstrapBinDirectory\System.Collections.Immutable.dll" + FileToCopy "$bootstrapBinDirectory\System.Diagnostics.DiagnosticSource.dll" FileToCopy "$bootstrapBinDirectory\System.Memory.dll" FileToCopy "$bootstrapBinDirectory\System.Numerics.Vectors.dll" FileToCopy "$bootstrapBinDirectory\System.Reflection.MetadataLoadContext.dll" diff --git a/src/Build.UnitTests/Telemetry/EvaluationMetrics_Tests.cs b/src/Build.UnitTests/Telemetry/EvaluationMetrics_Tests.cs new file mode 100644 index 00000000000..808a73f1589 --- /dev/null +++ b/src/Build.UnitTests/Telemetry/EvaluationMetrics_Tests.cs @@ -0,0 +1,537 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System; +using System.Collections.Concurrent; +using System.Collections.Generic; +using System.Diagnostics.Metrics; +using System.Diagnostics.Tracing; +using System.IO; +using System.Linq; +using System.Xml; +using Microsoft.Build.Construction; +using Microsoft.Build.Definition; +using Microsoft.Build.Engine.UnitTests.BackEnd; +using Microsoft.Build.Evaluation; +using Microsoft.Build.Eventing; +using Microsoft.Build.Exceptions; +using Microsoft.Build.Execution; +using Microsoft.Build.Framework; +using Microsoft.Build.TelemetryInfra; +using Microsoft.Build.UnitTests; +using Microsoft.Build.UnitTests.Shared; +using Shouldly; +using Xunit; + +namespace Microsoft.Build.Engine.UnitTests; + +[CollectionDefinition(CollectionName, DisableParallelization = true)] +public sealed class EvaluationMetricsTestCollection +{ + public const string CollectionName = nameof(EvaluationMetricsTestCollection); +} + +[Collection(EvaluationMetricsTestCollection.CollectionName)] +public sealed class EvaluationMetrics_Tests +{ + private readonly ITestOutputHelper _output; + + public EvaluationMetrics_Tests(ITestOutputHelper output) + { + _output = output; + EvaluationInstrumentation.ResetForTests(); + } + + [Theory] + [InlineData(ProjectEvaluationStage.Properties)] + [InlineData(ProjectEvaluationStage.ItemDefinitions)] + [InlineData(ProjectEvaluationStage.Items)] + [InlineData(ProjectEvaluationStage.UsingTasks)] + [InlineData(ProjectEvaluationStage.Full)] + public void EvaluationEventSourcePassesMatchRequestedStage(ProjectEvaluationStage stage) + { + using EventSourceTestHelper eventSourceListener = new(); + using ProjectCollection collection = new(); + + _ = ProjectInstance.FromProjectRootElement( + CreateRootElement(""), + new ProjectOptions + { + EvaluationStage = stage, + ProjectCollection = collection, + }); + + List events = eventSourceListener.GetEvents(); + events.Count(eventData => eventData.EventName == nameof(MSBuildEventSource.EvaluateStart)).ShouldBe(1); + events.Count(eventData => eventData.EventName == nameof(MSBuildEventSource.EvaluateStop)).ShouldBe(1); + GetCompletedPasses(events).ShouldBe(GetExpectedPasses(stage)); + } + + [Fact] + public void FailedEvaluationPairsTotalEventSourceWithoutCompletingFailedPass() + { + using EventSourceTestHelper eventSourceListener = new(); + using ProjectCollection collection = new(); + + Should.Throw(() => + ProjectInstance.FromProjectRootElement( + CreateRootElement( + """ + + + 1 + + + """), + new ProjectOptions { ProjectCollection = collection })); + + List events = eventSourceListener.GetEvents(); + events.Count(eventData => eventData.EventName == nameof(MSBuildEventSource.EvaluateStart)).ShouldBe(1); + events.Count(eventData => eventData.EventName == nameof(MSBuildEventSource.EvaluateStop)).ShouldBe(1); + events.Count(eventData => eventData.EventName == nameof(MSBuildEventSource.EvaluatePass1Start)).ShouldBe(1); + events.Count(eventData => eventData.EventName == nameof(MSBuildEventSource.EvaluatePass1Stop)).ShouldBe(0); + } + + [Fact] + public void InMemoryEvaluationPreservesPassProjectFilePayloads() + { + using EventSourceTestHelper eventSourceListener = new(); + using ProjectCollection collection = new(); + + _ = ProjectInstance.FromProjectRootElement( + CreateRootElement(""), + new ProjectOptions { ProjectCollection = collection }); + + List events = eventSourceListener.GetEvents(); + GetProjectFilePayload(events, nameof(MSBuildEventSource.EvaluatePass1Start)).ShouldBe("(null)"); + GetProjectFilePayload(events, nameof(MSBuildEventSource.EvaluatePass1Stop)).ShouldBe("(null)"); + GetProjectFilePayload(events, nameof(MSBuildEventSource.EvaluatePass2Start)).ShouldBe("(null)"); + GetProjectFilePayload(events, nameof(MSBuildEventSource.EvaluatePass2Stop)).ShouldBe("(null)"); + GetProjectFilePayload(events, nameof(MSBuildEventSource.EvaluatePass3Start)).ShouldBe("(null)"); + GetProjectFilePayload(events, nameof(MSBuildEventSource.EvaluatePass3Stop)).ShouldBe("(null)"); + GetProjectFilePayload(events, nameof(MSBuildEventSource.EvaluatePass4Start)).ShouldBe("(null)"); + GetProjectFilePayload(events, nameof(MSBuildEventSource.EvaluatePass4Stop)).ShouldBe("(null)"); + GetProjectFilePayload(events, nameof(MSBuildEventSource.EvaluatePass5Start)).ShouldBe("(null)"); + GetProjectFilePayload(events, nameof(MSBuildEventSource.EvaluatePass5Stop)).ShouldBe("(null)"); + } + + [Fact] + public void EvaluationFinishedLoggingPrecedesEventSourceStop() + { + using TestEnvironment env = TestEnvironment.Create(_output); + TransientTestFile projectFile = env.CreateFile("evaluation-ordering.proj", ""); + List ordering = []; + using MetricCollector collector = new(instrument => + { + if (instrument.Name == EvaluationInstrumentation.ProjectEvaluationDurationName) + { + ordering.Add("evaluation-metric"); + } + }); + EvaluationFinishedOrderingLogger logger = new(projectFile.Path, () => ordering.Add("evaluation-finished")); + using EvaluationStopEventListener eventSourceListener = + new(projectFile.Path, () => ordering.Add("event-source-stop")); + using ProjectCollection collection = new( + new Dictionary(), + [logger], + ToolsetDefinitionLocations.Default); + + _ = collection.LoadProject(projectFile.Path); + + ordering.ShouldBe(["evaluation-metric", "evaluation-finished", "event-source-stop"]); + } + + [Theory] + [InlineData(ProjectEvaluationStage.Properties, "properties")] + [InlineData(ProjectEvaluationStage.ItemDefinitions, "item_definitions")] + [InlineData(ProjectEvaluationStage.Items, "items")] + [InlineData(ProjectEvaluationStage.UsingTasks, "using_tasks")] + [InlineData(ProjectEvaluationStage.Full, "full")] + public void EvaluationMetricsCaptureStageAndDuration(ProjectEvaluationStage stage, string expectedStage) + { + using MetricCollector collector = new(); + using ProjectCollection collection = new(); + + _ = ProjectInstance.FromProjectRootElement( + CreateRootElement(""), + new ProjectOptions + { + EvaluationStage = stage, + ProjectCollection = collection, + }); + + List evaluationCounts = collector.Measurements + .Where(measurement => measurement.InstrumentName == EvaluationInstrumentation.ProjectEvaluationCountName) + .ToList(); + evaluationCounts.Count.ShouldBe(1); + evaluationCounts[0].Value.ShouldBe(1); + evaluationCounts[0].HasTag(EvaluationInstrumentation.StageTagName, expectedStage).ShouldBeTrue(); + evaluationCounts[0].HasTag(EvaluationInstrumentation.OriginTagName, EvaluationInstrumentation.OutsideBuildSubmissionOrigin).ShouldBeTrue(); + evaluationCounts[0].HasTag(EvaluationInstrumentation.SucceededTagName, true).ShouldBeTrue(); + + List evaluationDurations = collector.Measurements + .Where(measurement => measurement.InstrumentName == EvaluationInstrumentation.ProjectEvaluationDurationName) + .ToList(); + evaluationDurations.Count.ShouldBe(1); + evaluationDurations[0].Value.ShouldBeGreaterThanOrEqualTo(0); + evaluationDurations[0].HasTag(EvaluationInstrumentation.StageTagName, expectedStage).ShouldBeTrue(); + evaluationDurations[0].HasTag(EvaluationInstrumentation.OriginTagName, EvaluationInstrumentation.OutsideBuildSubmissionOrigin).ShouldBeTrue(); + evaluationDurations[0].HasTag(EvaluationInstrumentation.SucceededTagName, true).ShouldBeTrue(); + + List metricPasses = []; + foreach (MetricMeasurement measurement in collector.Measurements) + { + if (measurement.InstrumentName == EvaluationInstrumentation.ProjectEvaluationPassDurationName) + { + measurement.Value.ShouldBeGreaterThanOrEqualTo(0); + measurement.HasTag(EvaluationInstrumentation.StageTagName, expectedStage).ShouldBeTrue(); + measurement.HasTag(EvaluationInstrumentation.OriginTagName, EvaluationInstrumentation.OutsideBuildSubmissionOrigin).ShouldBeTrue(); + metricPasses.Add(measurement.Tags[EvaluationInstrumentation.PassTagName].ShouldBeOfType()); + } + } + + metricPasses.ShouldBe(GetExpectedPasses(stage)); + } + + [Fact] + public void ItemsMetricCoversDeferredItemRealizationWithoutSeparateSeries() + { + using MetricCollector collector = new(); + using ProjectCollection collection = new(); + + ProjectInstance instance = ProjectInstance.FromProjectRootElement( + CreateRootElement( + """ + + + + + + + """), + new ProjectOptions { ProjectCollection = collection }); + + instance.GetItems("Result").Count.ShouldBe(2); + + List itemPassMeasurements = collector.Measurements + .Where(measurement => + measurement.InstrumentName == EvaluationInstrumentation.ProjectEvaluationPassDurationName && + measurement.HasTag(EvaluationInstrumentation.PassTagName, "items")) + .ToList(); + itemPassMeasurements.Count.ShouldBe(1); + collector.Measurements.ShouldNotContain(measurement => + measurement.InstrumentName == EvaluationInstrumentation.ProjectEvaluationPassDurationName && + measurement.HasTag(EvaluationInstrumentation.PassTagName, "lazy_items")); + } + + [Fact] + public void EvaluationMetricsCaptureBuildSubmissionOrigin() + { + using MetricCollector collector = new(); + using TestEnvironment env = TestEnvironment.Create(_output); + + TransientTestFile buildProject = env.CreateFile( + "evaluation-metrics.proj", + """ + + + + """); + MockLogger logger = new(_output); + using (BuildManager buildManager = new()) + { + BuildResult result = buildManager.Build( + new BuildParameters { Loggers = [logger] }, + new BuildRequestData( + buildProject.Path, + new Dictionary(), + null, + ["Build"], + null)); + result.ShouldHaveSucceeded(); + } + + collector.Measurements.ShouldContain(measurement => + measurement.InstrumentName == EvaluationInstrumentation.ProjectEvaluationCountName && + measurement.HasTag(EvaluationInstrumentation.StageTagName, "full") && + measurement.HasTag(EvaluationInstrumentation.OriginTagName, EvaluationInstrumentation.BuildSubmissionOrigin) && + measurement.HasTag(EvaluationInstrumentation.SucceededTagName, true)); + + collector.Measurements.ShouldContain(measurement => + measurement.InstrumentName == EvaluationInstrumentation.ProjectEvaluationPassDurationName && + measurement.HasTag(EvaluationInstrumentation.PassTagName, "targets") && + measurement.HasTag(EvaluationInstrumentation.StageTagName, "full") && + measurement.HasTag(EvaluationInstrumentation.OriginTagName, EvaluationInstrumentation.BuildSubmissionOrigin)); + } + + [Fact] + public void EvaluationMetricsCaptureFailedEvaluation() + { + using MetricCollector collector = new(); + using ProjectCollection collection = new(); + + Should.Throw(() => + ProjectInstance.FromProjectRootElement( + CreateRootElement( + """ + + + 1 + + + """), + new ProjectOptions { ProjectCollection = collection })); + + collector.Measurements.ShouldContain(measurement => + measurement.InstrumentName == EvaluationInstrumentation.ProjectEvaluationCountName && + measurement.HasTag(EvaluationInstrumentation.StageTagName, "full") && + measurement.HasTag(EvaluationInstrumentation.OriginTagName, EvaluationInstrumentation.OutsideBuildSubmissionOrigin) && + measurement.HasTag(EvaluationInstrumentation.SucceededTagName, false)); + } + + [Fact] + public void ThrowingMetricsListenerDoesNotBreakEvaluation() + { + using ResetMetricsOnDispose reset = new(); + using MeterListener listener = new(); + listener.InstrumentPublished = (instrument, meterListener) => + { + if (instrument.Meter.Name == EvaluationInstrumentation.MeterName && + instrument.Name == EvaluationInstrumentation.ProjectEvaluationCountName) + { + meterListener.EnableMeasurementEvents(instrument); + } + }; + listener.SetMeasurementEventCallback((_, _, _, _) => throw new InvalidOperationException("Test listener failure")); + listener.Start(); + + using ProjectCollection collection = new(); + Should.NotThrow(() => + ProjectInstance.FromProjectRootElement( + CreateRootElement(""), + new ProjectOptions { ProjectCollection = collection })); + } + + [WindowsFullFrameworkOnlyFact] + public void MissingDiagnosticSourceDoesNotBreakEvaluation() + { + using TestEnvironment env = TestEnvironment.Create(_output); + TransientTestFolder isolatedMSBuild = env.CreateFolder(createFolder: true); + string bootstrapDirectory = Path.GetDirectoryName(RunnerUtilities.BootstrapMSBuildExecutablePath).ShouldNotBeNull(); + string diagnosticSourceFileName = "System.Diagnostics.DiagnosticSource.dll"; + + File.Exists(Path.Combine(bootstrapDirectory, diagnosticSourceFileName)).ShouldBeTrue(); + foreach (string file in Directory.EnumerateFiles(bootstrapDirectory)) + { + if (!string.Equals(Path.GetFileName(file), diagnosticSourceFileName, StringComparison.OrdinalIgnoreCase)) + { + File.Copy(file, Path.Combine(isolatedMSBuild.Path, Path.GetFileName(file))); + } + } + + TransientTestFile project = env.CreateFile( + isolatedMSBuild, + "evaluation-metrics.proj", + """ + + + + """); + + string output = RunnerUtilities.ExecMSBuild( + Path.Combine(isolatedMSBuild.Path, "MSBuild.exe"), + $"\"{project.Path}\" -nologo -v:q -m:1 -nr:false", + out bool success, + outputHelper: _output); + + success.ShouldBeTrue(output); + } + + private static List GetCompletedPasses(IEnumerable events) + { + List passes = []; + foreach (EventWrittenEventArgs eventData in events) + { + string? pass = eventData.EventName switch + { + nameof(MSBuildEventSource.EvaluatePass0Stop) => "initial_properties", + nameof(MSBuildEventSource.EvaluatePass1Stop) => "properties", + nameof(MSBuildEventSource.EvaluatePass2Stop) => "item_definitions", + nameof(MSBuildEventSource.EvaluatePass3Stop) => "items", + nameof(MSBuildEventSource.EvaluatePass4Stop) => "using_tasks", + nameof(MSBuildEventSource.EvaluatePass5Stop) => "targets", + _ => null, + }; + + if (pass is not null) + { + passes.Add(pass); + } + } + + return passes; + } + + private static object? GetProjectFilePayload(IEnumerable events, string eventName) => + events.Single(eventData => eventData.EventName == eventName).Payload?[0]; + + private static string[] GetExpectedPasses(ProjectEvaluationStage stage) => stage switch + { + ProjectEvaluationStage.Properties => ["initial_properties", "properties"], + ProjectEvaluationStage.ItemDefinitions => ["initial_properties", "properties", "item_definitions"], + ProjectEvaluationStage.Items => ["initial_properties", "properties", "item_definitions", "items"], + ProjectEvaluationStage.UsingTasks => ["initial_properties", "properties", "item_definitions", "items", "using_tasks"], + ProjectEvaluationStage.Full => ["initial_properties", "properties", "item_definitions", "items", "using_tasks", "targets"], + _ => [], + }; + + private static ProjectRootElement CreateRootElement(string projectXml) + { + using StringReader stringReader = new(projectXml); + using XmlReader xmlReader = XmlReader.Create(stringReader); + return ProjectRootElement.Create(xmlReader); + } + + private sealed class EvaluationFinishedOrderingLogger : ILogger + { + private readonly string _projectFile; + private readonly Action _onEvaluationFinished; + + internal EvaluationFinishedOrderingLogger(string projectFile, Action onEvaluationFinished) + { + _projectFile = projectFile; + _onEvaluationFinished = onEvaluationFinished; + } + + public LoggerVerbosity Verbosity { get; set; } + + public string? Parameters { get; set; } + + public void Initialize(IEventSource eventSource) + { + eventSource.AnyEventRaised += OnAnyEventRaised; + } + + public void Shutdown() + { + } + + private void OnAnyEventRaised(object sender, BuildEventArgs eventArgs) + { + if (eventArgs is ProjectEvaluationFinishedEventArgs evaluationFinished && + string.Equals(evaluationFinished.ProjectFile, _projectFile, StringComparison.OrdinalIgnoreCase)) + { + _onEvaluationFinished(); + } + } + } + + private sealed class EvaluationStopEventListener : EventListener + { + private const string EventSourceName = "Microsoft-Build"; + + private readonly string _projectFile; + private readonly Action _onEvaluationStop; + private EventSource? _eventSource; + + internal EvaluationStopEventListener(string projectFile, Action onEvaluationStop) + { + _projectFile = projectFile; + _onEvaluationStop = onEvaluationStop; + } + + protected override void OnEventSourceCreated(EventSource eventSource) + { + if (eventSource.Name == EventSourceName) + { + EnableEvents(eventSource, EventLevel.LogAlways); + _eventSource = eventSource; + } + } + + protected override void OnEventWritten(EventWrittenEventArgs eventData) + { + if (eventData.EventName == nameof(MSBuildEventSource.EvaluateStop) && + eventData.Payload is not null && + eventData.Payload.Count > 0 && + string.Equals(eventData.Payload[0] as string, _projectFile, StringComparison.OrdinalIgnoreCase)) + { + _onEvaluationStop(); + } + } + + public override void Dispose() + { + if (_eventSource is not null) + { + DisableEvents(_eventSource); + } + + base.Dispose(); + } + } + + private sealed class MetricCollector : IDisposable + { + private readonly MeterListener _listener = new(); + private readonly Action? _onMeasurement; + + public MetricCollector(Action? onMeasurement = null) + { + _onMeasurement = onMeasurement; + _listener.InstrumentPublished = (instrument, listener) => + { + if (instrument.Meter.Name == EvaluationInstrumentation.MeterName) + { + listener.EnableMeasurementEvents(instrument); + } + }; + _listener.SetMeasurementEventCallback((instrument, value, tags, _) => Add(instrument, value, tags)); + _listener.SetMeasurementEventCallback((instrument, value, tags, _) => Add(instrument, value, tags)); + _listener.Start(); + } + + public ConcurrentQueue Measurements { get; } = new(); + + public void Dispose() + { + _listener.Dispose(); + } + + private void Add( + Instrument instrument, + T value, + ReadOnlySpan> tags) + where T : struct + { + Dictionary copiedTags = new(tags.Length, StringComparer.Ordinal); + foreach (KeyValuePair tag in tags) + { + copiedTags.Add(tag.Key, tag.Value); + } + + _onMeasurement?.Invoke(instrument); + Measurements.Enqueue(new MetricMeasurement( + instrument.Name, + Convert.ToDouble(value, System.Globalization.CultureInfo.InvariantCulture), + copiedTags)); + } + } + + private sealed record MetricMeasurement( + string InstrumentName, + double Value, + Dictionary Tags) + { + public bool HasTag(string name, object expected) => + Tags.TryGetValue(name, out object? actual) && Equals(actual, expected); + } + + private sealed class ResetMetricsOnDispose : IDisposable + { + public void Dispose() + { + EvaluationInstrumentation.ResetForTests(); + } + } +} diff --git a/src/Build/Evaluation/Evaluator.cs b/src/Build/Evaluation/Evaluator.cs index 9248639a503..10431111b05 100644 --- a/src/Build/Evaluation/Evaluator.cs +++ b/src/Build/Evaluation/Evaluator.cs @@ -16,7 +16,6 @@ using Microsoft.Build.Collections; using Microsoft.Build.Construction; using Microsoft.Build.Evaluation.Context; -using Microsoft.Build.Eventing; using Microsoft.Build.Execution; using Microsoft.Build.ProjectCache; using Microsoft.Build.FileSystem; @@ -25,6 +24,7 @@ using Microsoft.Build.Internal; using Microsoft.Build.Shared; using Microsoft.Build.Shared.FileSystem; +using Microsoft.Build.TelemetryInfra; using static Microsoft.Build.Execution.ProjectPropertyInstance; using Constants = Microsoft.Build.Framework.Constants; using EngineFileUtilities = Microsoft.Build.Internal.EngineFileUtilities; @@ -348,61 +348,72 @@ internal static void Evaluate( bool interactive = false, ProjectEvaluationStage evaluationStage = ProjectEvaluationStage.Full) { - MSBuildEventSource.Log.EvaluateStart(root.ProjectFileLocation.File); - var profileEvaluation = (loadSettings & ProjectLoadSettings.ProfileEvaluation) != 0 || loggingService.IncludeEvaluationProfile; - var evaluator = new Evaluator( - data, - project, - root, - loadSettings, - maxNodeCount, - environmentProperties, - propertiesFromCommandLine, - itemFactory, - toolsetProvider, - directoryCacheFactory, - projectRootElementCache, - sdkResolverService, - submissionId, - evaluationContext, - profileEvaluation, - interactive, - loggingService, - buildEventContext, - evaluationStage); + using EvaluationInstrumentation.EvaluationScope evaluationInstrumentation = + EvaluationInstrumentation.StartEvaluation(root.ProjectFileLocation.File, evaluationStage, submissionId); + Evaluator evaluator = null; + bool evaluationSucceeded = false; try { - evaluator.Evaluate(); - } - catch (PathTooLongException ex) - { - evaluator._evaluationLoggingContext.LogErrorFromText(null, null, null, new BuildEventFileInfo(root.ProjectFileLocation.File), - ex.Message); + var profileEvaluation = (loadSettings & ProjectLoadSettings.ProfileEvaluation) != 0 || loggingService.IncludeEvaluationProfile; + evaluator = new Evaluator( + data, + project, + root, + loadSettings, + maxNodeCount, + environmentProperties, + propertiesFromCommandLine, + itemFactory, + toolsetProvider, + directoryCacheFactory, + projectRootElementCache, + sdkResolverService, + submissionId, + evaluationContext, + profileEvaluation, + interactive, + loggingService, + buildEventContext, + evaluationStage); + + try + { + evaluator.Evaluate(); + evaluationSucceeded = true; + } + catch (PathTooLongException ex) + { + evaluator._evaluationLoggingContext.LogErrorFromText(null, null, null, new BuildEventFileInfo(root.ProjectFileLocation.File), + ex.Message); + } } finally { - IEnumerable globalProperties = null; - IEnumerable properties = null; - IEnumerable items = null; + evaluationInstrumentation.CompleteEvaluation(evaluationSucceeded); - if (evaluator._evaluationLoggingContext.LoggingService.IncludeEvaluationPropertiesAndItemsInEvaluationFinishedEvent) + if (evaluator is not null) { - globalProperties = evaluator._data.GlobalPropertiesDictionary; - properties = Traits.LogAllEnvironmentVariables ? evaluator._data.Properties : evaluator.FilterOutEnvironmentDerivedProperties(evaluator._data.Properties); - items = evaluator._data.Items; - } + IEnumerable globalProperties = null; + IEnumerable properties = null; + IEnumerable items = null; - string skippedMessage = evaluator._projectRootElementCache.ParserIgnoreConfiguration?.GetSkippedSummaryMessage(); - if (skippedMessage is not null) - { - evaluator._evaluationLoggingContext.LogCommentFromText(MessageImportance.Low, skippedMessage); - } + if (evaluator._evaluationLoggingContext.LoggingService.IncludeEvaluationPropertiesAndItemsInEvaluationFinishedEvent) + { + globalProperties = evaluator._data.GlobalPropertiesDictionary; + properties = Traits.LogAllEnvironmentVariables ? evaluator._data.Properties : evaluator.FilterOutEnvironmentDerivedProperties(evaluator._data.Properties); + items = evaluator._data.Items; + } - evaluator._evaluationLoggingContext.LogProjectEvaluationFinished(globalProperties, properties, items, evaluator._evaluationProfiler.ProfiledResult); - } + string skippedMessage = evaluator._projectRootElementCache.ParserIgnoreConfiguration?.GetSkippedSummaryMessage(); + if (skippedMessage is not null) + { + evaluator._evaluationLoggingContext.LogCommentFromText(MessageImportance.Low, skippedMessage); + } - MSBuildEventSource.Log.EvaluateStop(root.ProjectFileLocation.File); + evaluator._evaluationLoggingContext.LogProjectEvaluationFinished(globalProperties, properties, items, evaluator._evaluationProfiler.ProfiledResult); + } + } } /// @@ -662,7 +673,6 @@ private static ProjectTargetInstance ReadNewTargetElement(ProjectTargetElement t /// private void Evaluate() { - string projectFile = string.IsNullOrEmpty(_projectRootElement.ProjectFileLocation.File) ? "(null)" : _projectRootElement.ProjectFileLocation.File; using (_evaluationProfiler.TrackPass(EvaluationPass.TotalEvaluation)) { Assumed.Equal(_data.EvaluationId, BuildEventContext.InvalidEvaluationId, "There is no prior evaluation ID. The evaluator data needs to be reset at this point"); @@ -683,11 +693,16 @@ private void Evaluate() int globalPropertiesCount; + EvaluationInstrumentation.EvaluationPassScope passInstrumentation; using (_evaluationProfiler.TrackPass(EvaluationPass.InitialProperties)) { // Pass0: load initial properties // Follow the order of precedence so that Global properties overwrite Environment properties - MSBuildEventSource.Log.EvaluatePass0Start(_projectRootElement.ProjectFileLocation.File); + passInstrumentation = EvaluationInstrumentation.StartPass( + _projectRootElement.ProjectFileLocation.File, + EvaluationPass.InitialProperties, + _evaluationStage, + _submissionId); AddBuiltInProperties(); AddEnvironmentProperties(); AddToolsetProperties(); @@ -701,10 +716,14 @@ private void Evaluate() Assumed.NotEqual(_data.EvaluationId, BuildEventContext.InvalidEvaluationId, "Evaluation should produce an evaluation ID"); - MSBuildEventSource.Log.EvaluatePass0Stop(projectFile); + passInstrumentation.Complete(); // Pass1: evaluate properties, load imports, and gather everything else - MSBuildEventSource.Log.EvaluatePass1Start(projectFile); + passInstrumentation = EvaluationInstrumentation.StartPass( + _projectRootElement.ProjectFileLocation.File, + EvaluationPass.Properties, + _evaluationStage, + _submissionId); using (_evaluationProfiler.TrackPass(EvaluationPass.Properties)) { PerformDepthFirstPass(_projectRootElement); @@ -719,7 +738,7 @@ private void Evaluate() } _data.InitialTargets = initialTargets; - MSBuildEventSource.Log.EvaluatePass1Stop(projectFile); + passInstrumentation.Complete(); if (_evaluationStage <= ProjectEvaluationStage.Properties) { @@ -729,7 +748,11 @@ private void Evaluate() // Pass2: evaluate item definitions // Don't box via IEnumerator and foreach; cache count so not to evaluate via interface each iteration - MSBuildEventSource.Log.EvaluatePass2Start(projectFile); + passInstrumentation = EvaluationInstrumentation.StartPass( + _projectRootElement.ProjectFileLocation.File, + EvaluationPass.ItemDefinitionGroups, + _evaluationStage, + _submissionId); using (_evaluationProfiler.TrackPass(EvaluationPass.ItemDefinitionGroups)) { foreach (var itemDefinitionGroupElement in _itemDefinitionGroupElements) @@ -740,7 +763,7 @@ private void Evaluate() } } } - MSBuildEventSource.Log.EvaluatePass2Stop(projectFile); + passInstrumentation.Complete(); if (_evaluationStage <= ProjectEvaluationStage.ItemDefinitions) { @@ -755,8 +778,11 @@ private void Evaluate() lazyEvaluator = new LazyItemEvaluator(_data, _itemFactory, _evaluationLoggingContext, _evaluationProfiler, _evaluationContext); // Pass3: evaluate project items - MSBuildEventSource.Log.EvaluatePass3Start(projectFile); - + passInstrumentation = EvaluationInstrumentation.StartPass( + _projectRootElement.ProjectFileLocation.File, + EvaluationPass.Items, + _evaluationStage, + _submissionId); SynthesizeImportedProjectItems(); DetectItemGlobRequest(); @@ -796,8 +822,7 @@ private void Evaluate() } SynthesizeItemGlobItems(); - - MSBuildEventSource.Log.EvaluatePass3Stop(projectFile); + passInstrumentation.Complete(); if (_evaluationStage <= ProjectEvaluationStage.Items) { @@ -806,7 +831,11 @@ private void Evaluate() } // Pass4: evaluate using-tasks - MSBuildEventSource.Log.EvaluatePass4Start(projectFile); + passInstrumentation = EvaluationInstrumentation.StartPass( + _projectRootElement.ProjectFileLocation.File, + EvaluationPass.UsingTasks, + _evaluationStage, + _submissionId); using (_evaluationProfiler.TrackPass(EvaluationPass.UsingTasks)) { // Evaluate the usingtask and add the result into the data passed in @@ -819,7 +848,7 @@ private void Evaluate() _evaluationContext.FileSystem); } - MSBuildEventSource.Log.EvaluatePass4Stop(projectFile); + passInstrumentation.Complete(); if (_evaluationStage <= ProjectEvaluationStage.UsingTasks) { @@ -849,7 +878,11 @@ private void Evaluate() using (_evaluationProfiler.TrackPass(EvaluationPass.Targets)) { // Pass5: read targets (but don't evaluate them: that happens during build) - MSBuildEventSource.Log.EvaluatePass5Start(projectFile); + passInstrumentation = EvaluationInstrumentation.StartPass( + _projectRootElement.ProjectFileLocation.File, + EvaluationPass.Targets, + _evaluationStage, + _submissionId); for (var i = 0; i < targetElementsCount; i++) { var element = _targetElements[i]; @@ -903,7 +936,7 @@ private void Evaluate() } _data.FinishEvaluation(); - MSBuildEventSource.Log.EvaluatePass5Stop(projectFile); + passInstrumentation.Complete(); } } diff --git a/src/Build/Microsoft.Build.csproj b/src/Build/Microsoft.Build.csproj index 1aa8eef4824..a6eeb2df7ee 100644 --- a/src/Build/Microsoft.Build.csproj +++ b/src/Build/Microsoft.Build.csproj @@ -72,6 +72,7 @@ + @@ -219,6 +220,7 @@ + diff --git a/src/Build/TelemetryInfra/EvaluationInstrumentation.cs b/src/Build/TelemetryInfra/EvaluationInstrumentation.cs new file mode 100644 index 00000000000..b4d8e6776be --- /dev/null +++ b/src/Build/TelemetryInfra/EvaluationInstrumentation.cs @@ -0,0 +1,415 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System; +using System.Diagnostics; +using System.Diagnostics.Metrics; +using System.Runtime.CompilerServices; +using System.Threading; +using Microsoft.Build.Evaluation; +using Microsoft.Build.Eventing; +using Microsoft.Build.Framework; +using Microsoft.Build.Framework.Profiler; + +namespace Microsoft.Build.TelemetryInfra; + +internal static class EvaluationInstrumentation +{ + /// The process-wide MSBuild meter. + internal const string MeterName = "Microsoft.Build"; + + /// Counter incremented once per evaluation. + internal const string ProjectEvaluationCountName = "msbuild.project.evaluations"; + + /// Elapsed seconds for one evaluation. + internal const string ProjectEvaluationDurationName = "msbuild.project.evaluation.duration"; + + /// Elapsed seconds for one evaluation pass. + internal const string ProjectEvaluationPassDurationName = "msbuild.project.evaluation.pass.duration"; + + /// The requested evaluation stopping stage. + internal const string StageTagName = "msbuild.project.evaluation.stage"; + + /// The pass measured by the pass-duration instrument. + internal const string PassTagName = "msbuild.project.evaluation.pass"; + + /// Distinguishes requested-build evaluation from hidden or preflight evaluation. + internal const string OriginTagName = "msbuild.project.evaluation.origin"; + + /// Whether evaluation completed successfully. + internal const string SucceededTagName = "msbuild.project.evaluation.succeeded"; + + /// Marks evaluation performed for an active build request. + internal const string BuildSubmissionOrigin = "build_submission"; + + /// Marks object-model, graph, reevaluation, or discovery work outside a build request. + internal const string OutsideBuildSubmissionOrigin = "outside_build_submission"; + + internal static EvaluationScope StartEvaluation( + string projectFile, + ProjectEvaluationStage stage, + int submissionId) + { + MSBuildEventSource.Log.EvaluateStart(projectFile); + return new EvaluationScope(projectFile, stage, submissionId, StartEvaluationMetrics()); + } + + internal static EvaluationPassScope StartPass( + string projectFile, + EvaluationPass pass, + ProjectEvaluationStage stage, + int submissionId) + { + string projectFileForStop = string.IsNullOrEmpty(projectFile) ? "(null)" : projectFile; + string projectFileForStart = + pass == EvaluationPass.InitialProperties + ? projectFile + : projectFileForStop; + WritePassStart(pass, projectFileForStart); + return new EvaluationPassScope(projectFileForStop, pass, stage, submissionId, StartPassMetrics()); + } + + internal static void ResetForTests() + { + Volatile.Write(ref s_metricsDisabled, 0); + } + + private static void CompletePass( + string projectFile, + EvaluationPass pass, + ProjectEvaluationStage stage, + int submissionId, + long startTimestamp) + { + long endTimestamp = GetMetricsEndTimestamp(startTimestamp); + WritePassStop(pass, projectFile); + RecordPassMetrics(startTimestamp, endTimestamp, pass, stage, submissionId); + } + + private static void WritePassStart(EvaluationPass pass, string projectFile) + { + switch (pass) + { + case EvaluationPass.InitialProperties: + MSBuildEventSource.Log.EvaluatePass0Start(projectFile); + break; + case EvaluationPass.Properties: + MSBuildEventSource.Log.EvaluatePass1Start(projectFile); + break; + case EvaluationPass.ItemDefinitionGroups: + MSBuildEventSource.Log.EvaluatePass2Start(projectFile); + break; + case EvaluationPass.Items: + MSBuildEventSource.Log.EvaluatePass3Start(projectFile); + break; + case EvaluationPass.UsingTasks: + MSBuildEventSource.Log.EvaluatePass4Start(projectFile); + break; + case EvaluationPass.Targets: + MSBuildEventSource.Log.EvaluatePass5Start(projectFile); + break; + default: + throw new ArgumentOutOfRangeException(nameof(pass), pass, "Unsupported instrumented evaluation pass."); + } + } + + private static void WritePassStop(EvaluationPass pass, string projectFile) + { + switch (pass) + { + case EvaluationPass.InitialProperties: + MSBuildEventSource.Log.EvaluatePass0Stop(projectFile); + break; + case EvaluationPass.Properties: + MSBuildEventSource.Log.EvaluatePass1Stop(projectFile); + break; + case EvaluationPass.ItemDefinitionGroups: + MSBuildEventSource.Log.EvaluatePass2Stop(projectFile); + break; + case EvaluationPass.Items: + MSBuildEventSource.Log.EvaluatePass3Stop(projectFile); + break; + case EvaluationPass.UsingTasks: + MSBuildEventSource.Log.EvaluatePass4Stop(projectFile); + break; + case EvaluationPass.Targets: + MSBuildEventSource.Log.EvaluatePass5Stop(projectFile); + break; + default: + throw new ArgumentOutOfRangeException(nameof(pass), pass, "Unsupported instrumented evaluation pass."); + } + } + + internal readonly struct EvaluationScope : IDisposable + { + private readonly string _projectFile; + private readonly ProjectEvaluationStage _stage; + private readonly int _submissionId; + private readonly long _metricsStartTimestamp; + + internal EvaluationScope( + string projectFile, + ProjectEvaluationStage stage, + int submissionId, + long metricsStartTimestamp) + { + _projectFile = projectFile; + _stage = stage; + _submissionId = submissionId; + _metricsStartTimestamp = metricsStartTimestamp; + } + + internal void CompleteEvaluation(bool succeeded) + { + long endTimestamp = GetMetricsEndTimestamp(_metricsStartTimestamp); + RecordEvaluationMetrics(_metricsStartTimestamp, endTimestamp, _stage, _submissionId, succeeded); + } + + public void Dispose() => MSBuildEventSource.Log.EvaluateStop(_projectFile); + } + + internal readonly struct EvaluationPassScope + { + private readonly string _projectFile; + private readonly EvaluationPass _pass; + private readonly ProjectEvaluationStage _stage; + private readonly int _submissionId; + private readonly long _metricsStartTimestamp; + + internal EvaluationPassScope( + string projectFile, + EvaluationPass pass, + ProjectEvaluationStage stage, + int submissionId, + long metricsStartTimestamp) + { + _projectFile = projectFile; + _pass = pass; + _stage = stage; + _submissionId = submissionId; + _metricsStartTimestamp = metricsStartTimestamp; + } + + internal void Complete() => + CompletePass(_projectFile, _pass, _stage, _submissionId, _metricsStartTimestamp); + } + + /// Disables Metrics after an instrumentation failure so evaluation can continue safely. + private static int s_metricsDisabled; + + private static long StartEvaluationMetrics() + { + if (Volatile.Read(ref s_metricsDisabled) != 0) + { + return 0; + } + + try + { + return StartEvaluationMetricsCore(); + } + catch (Exception ex) when (!ExceptionHandling.IsCriticalException(ex)) + { + DisableMetrics(); + return 0; + } + } + + // Keep Metrics type resolution inside the catch boundary. + [MethodImpl(MethodImplOptions.NoInlining)] + private static long StartEvaluationMetricsCore() => + Instruments.ProjectEvaluationDuration.Enabled ? Stopwatch.GetTimestamp() : 0; + + private static long StartPassMetrics() + { + if (Volatile.Read(ref s_metricsDisabled) != 0) + { + return 0; + } + + try + { + return StartPassMetricsCore(); + } + catch (Exception ex) when (!ExceptionHandling.IsCriticalException(ex)) + { + DisableMetrics(); + return 0; + } + } + + // Keep Metrics type resolution inside the catch boundary. + [MethodImpl(MethodImplOptions.NoInlining)] + private static long StartPassMetricsCore() => + Instruments.ProjectEvaluationPassDuration.Enabled ? Stopwatch.GetTimestamp() : 0; + + private static long GetMetricsEndTimestamp(long startTimestamp) + { + if (startTimestamp == 0 || Volatile.Read(ref s_metricsDisabled) != 0) + { + return 0; + } + + try + { + return Stopwatch.GetTimestamp(); + } + catch (Exception ex) when (!ExceptionHandling.IsCriticalException(ex)) + { + DisableMetrics(); + return 0; + } + } + + private static void RecordEvaluationMetrics( + long startTimestamp, + long endTimestamp, + ProjectEvaluationStage stage, + int submissionId, + bool succeeded) + { + if (Volatile.Read(ref s_metricsDisabled) != 0) + { + return; + } + + try + { + RecordEvaluationMetricsCore(startTimestamp, endTimestamp, stage, submissionId, succeeded); + } + catch (Exception ex) when (!ExceptionHandling.IsCriticalException(ex)) + { + DisableMetrics(); + } + } + + // Keep Metrics type resolution inside the catch boundary. + [MethodImpl(MethodImplOptions.NoInlining)] + private static void RecordEvaluationMetricsCore( + long startTimestamp, + long endTimestamp, + ProjectEvaluationStage stage, + int submissionId, + bool succeeded) + { + bool countEnabled = Instruments.ProjectEvaluationCount.Enabled; + bool durationEnabled = + startTimestamp != 0 && + endTimestamp != 0 && + Instruments.ProjectEvaluationDuration.Enabled; + if (!countEnabled && !durationEnabled) + { + return; + } + + TagList tags = default; + tags.Add(StageTagName, GetStageName(stage)); + tags.Add(OriginTagName, GetOriginName(submissionId)); + tags.Add(SucceededTagName, succeeded); + + if (countEnabled) + { + Instruments.ProjectEvaluationCount.Add(1, in tags); + } + + if (durationEnabled) + { + Instruments.ProjectEvaluationDuration.Record(GetElapsedSeconds(startTimestamp, endTimestamp), in tags); + } + } + + private static void RecordPassMetrics( + long startTimestamp, + long endTimestamp, + EvaluationPass pass, + ProjectEvaluationStage stage, + int submissionId) + { + if (startTimestamp == 0 || endTimestamp == 0 || Volatile.Read(ref s_metricsDisabled) != 0) + { + return; + } + + try + { + RecordPassMetricsCore(startTimestamp, endTimestamp, pass, stage, submissionId); + } + catch (Exception ex) when (!ExceptionHandling.IsCriticalException(ex)) + { + DisableMetrics(); + } + } + + // Keep Metrics type resolution inside the catch boundary. + [MethodImpl(MethodImplOptions.NoInlining)] + private static void RecordPassMetricsCore( + long startTimestamp, + long endTimestamp, + EvaluationPass pass, + ProjectEvaluationStage stage, + int submissionId) + { + if (!Instruments.ProjectEvaluationPassDuration.Enabled) + { + return; + } + + TagList tags = default; + tags.Add(StageTagName, GetStageName(stage)); + tags.Add(PassTagName, GetPassName(pass)); + tags.Add(OriginTagName, GetOriginName(submissionId)); + + Instruments.ProjectEvaluationPassDuration.Record(GetElapsedSeconds(startTimestamp, endTimestamp), in tags); + } + + private static void DisableMetrics() => Volatile.Write(ref s_metricsDisabled, 1); + + private static string GetOriginName(int submissionId) => + submissionId != BuildEventContext.InvalidSubmissionId + ? BuildSubmissionOrigin + : OutsideBuildSubmissionOrigin; + + private static double GetElapsedSeconds(long startTimestamp, long endTimestamp) => + (endTimestamp - startTimestamp) / (double)Stopwatch.Frequency; + + private static string GetStageName(ProjectEvaluationStage stage) => stage switch + { + ProjectEvaluationStage.Properties => "properties", + ProjectEvaluationStage.ItemDefinitions => "item_definitions", + ProjectEvaluationStage.Items => "items", + ProjectEvaluationStage.UsingTasks => "using_tasks", + ProjectEvaluationStage.Full => "full", + _ => "unknown", + }; + + private static string GetPassName(EvaluationPass pass) => pass switch + { + EvaluationPass.InitialProperties => "initial_properties", + EvaluationPass.Properties => "properties", + EvaluationPass.ItemDefinitionGroups => "item_definitions", + EvaluationPass.Items => "items", + EvaluationPass.UsingTasks => "using_tasks", + EvaluationPass.Targets => "targets", + _ => "unknown", + }; + + private static class Instruments + { + private static readonly Meter s_meter = new(MeterName); + + internal static readonly Counter ProjectEvaluationCount = s_meter.CreateCounter( + ProjectEvaluationCountName, + unit: "{evaluation}", + description: "Number of MSBuild project evaluations."); + + internal static readonly Histogram ProjectEvaluationDuration = s_meter.CreateHistogram( + ProjectEvaluationDurationName, + unit: "s", + description: "Duration of MSBuild project evaluations."); + + internal static readonly Histogram ProjectEvaluationPassDuration = s_meter.CreateHistogram( + ProjectEvaluationPassDurationName, + unit: "s", + description: "Duration of MSBuild project evaluation passes."); + } +} diff --git a/src/MSBuild/app.amd64.config b/src/MSBuild/app.amd64.config index cca0e0084f3..abd202239b8 100644 --- a/src/MSBuild/app.amd64.config +++ b/src/MSBuild/app.amd64.config @@ -106,6 +106,11 @@ + + + + + diff --git a/src/MSBuild/app.config b/src/MSBuild/app.config index b11f4058767..7137f609a8e 100644 --- a/src/MSBuild/app.config +++ b/src/MSBuild/app.config @@ -60,6 +60,10 @@ + + + + diff --git a/src/Package/MSBuild.VSSetup/files.swr b/src/Package/MSBuild.VSSetup/files.swr index 8f90cdca0a7..61bf5b75fc8 100644 --- a/src/Package/MSBuild.VSSetup/files.swr +++ b/src/Package/MSBuild.VSSetup/files.swr @@ -43,6 +43,7 @@ folder InstallDir:\MSBuild\Current\Bin file source=$(X86BinPath)Microsoft.VisualStudio.SolutionPersistence.dll vs.file.ngenApplications="[installDir]\MSBuild\Current\Bin\amd64\MSBuild.exe" vs.file.ngenArchitecture=all vs.file.ngenPriority=3 file source=$(X86BinPath)RuntimeContracts.dll file source=$(X86BinPath)System.Buffers.dll vs.file.ngenApplications="[installDir]\MSBuild\Current\Bin\MSBuild.exe" vs.file.ngenArchitecture=all vs.file.ngenPriority=2 + file source=$(X86BinPath)System.Diagnostics.DiagnosticSource.dll vs.file.ngenApplications="[installDir]\MSBuild\Current\Bin\MSBuild.exe" vs.file.ngenApplications="[installDir]\MSBuild\Current\Bin\amd64\MSBuild.exe" vs.file.ngenArchitecture=all vs.file.ngenPriority=3 file source=$(X86BinPath)System.Formats.Nrbf.dll vs.file.ngenApplications="[installDir]\MSBuild\Current\Bin\MSBuild.exe" vs.file.ngenArchitecture=all vs.file.ngenPriority=2 file source=$(X86BinPath)System.IO.Pipelines.dll vs.file.ngenApplications="[installDir]\MSBuild\Current\Bin\MSBuild.exe" vs.file.ngenArchitecture=all vs.file.ngenPriority=2 file source=$(X86BinPath)System.Memory.dll vs.file.ngenApplications="[installDir]\MSBuild\Current\Bin\MSBuild.exe" vs.file.ngenArchitecture=all vs.file.ngenPriority=2 @@ -209,6 +210,7 @@ folder InstallDir:\MSBuild\Current\Bin\amd64 file source=$(X86BinPath)Microsoft.Build.Tasks.Core.dll vs.file.ngenArchitecture=all file source=$(X86BinPath)Microsoft.Build.Utilities.Core.dll vs.file.ngenArchitecture=all file source=$(X86BinPath)System.Buffers.dll vs.file.ngenArchitecture=all + file source=$(X86BinPath)System.Diagnostics.DiagnosticSource.dll vs.file.ngenArchitecture=all file source=$(X86BinPath)System.Formats.Nrbf.dll vs.file.ngenArchitecture=all file source=$(X86BinPath)System.IO.Pipelines.dll vs.file.ngenArchitecture=all file source=$(X86BinPath)System.Memory.dll vs.file.ngenArchitecture=all