|
// 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.Generic;
using System.Diagnostics;
using System.Linq;
using System.Threading;
using Microsoft.Build.Execution;
using Microsoft.Build.Framework;
using Microsoft.Build.Framework.Telemetry;
using Microsoft.Build.TelemetryInfra;
using Microsoft.Build.UnitTests;
using Shouldly;
using Xunit;
using Xunit.Abstractions;
using static Microsoft.Build.Framework.Telemetry.BuildInsights;
using static Microsoft.Build.Framework.Telemetry.TelemetryDataUtils;
namespace Microsoft.Build.Engine.UnitTests
{
[Collection("TelemetryManagerTests")]
public class Telemetry_Tests
{
private readonly ITestOutputHelper _output;
public Telemetry_Tests(ITestOutputHelper output)
{
_output = output;
}
[Fact]
public void WorkerNodeTelemetryCollection_BasicTarget()
{
WorkerNodeTelemetryData? workerNodeTelemetryData = null;
InternalTelemetryConsumingLogger.TestOnly_InternalTelemetryAggregted += dt => workerNodeTelemetryData = dt;
var testProject = """
<Project>
<Target Name="Build">
<Message Text="Hello World"/>
<CreateItem Include="foo.bar">
<Output TaskParameter="Include" ItemName="I" />
</CreateItem>
<Message Text="Bye World"/>
</Target>
</Project>
""";
MockLogger logger = new MockLogger(_output);
Helpers.BuildProjectContentUsingBuildManager(testProject, logger,
new BuildParameters() { IsTelemetryEnabled = true }).OverallResult.ShouldBe(BuildResultCode.Success);
workerNodeTelemetryData!.ShouldNotBeNull();
var buildTargetKey = new TaskOrTargetTelemetryKey("Build", true, false);
workerNodeTelemetryData.TargetsExecutionData.ShouldContainKey(buildTargetKey);
workerNodeTelemetryData.TargetsExecutionData[buildTargetKey].WasExecuted.ShouldBeTrue();
workerNodeTelemetryData.TargetsExecutionData.Keys.Count.ShouldBe(1);
workerNodeTelemetryData.TasksExecutionData.Keys.Count.ShouldBeGreaterThan(2);
workerNodeTelemetryData.TasksExecutionData[(TaskOrTargetTelemetryKey)"Microsoft.Build.Tasks.Message"].ExecutionsCount.ShouldBe(2);
workerNodeTelemetryData.TasksExecutionData[(TaskOrTargetTelemetryKey)"Microsoft.Build.Tasks.Message"].CumulativeExecutionTime.ShouldBeGreaterThan(TimeSpan.Zero);
workerNodeTelemetryData.TasksExecutionData[(TaskOrTargetTelemetryKey)"Microsoft.Build.Tasks.CreateItem"].ExecutionsCount.ShouldBe(1);
workerNodeTelemetryData.TasksExecutionData[(TaskOrTargetTelemetryKey)"Microsoft.Build.Tasks.CreateItem"].CumulativeExecutionTime.ShouldBeGreaterThan(TimeSpan.Zero);
workerNodeTelemetryData.TasksExecutionData.Keys.ShouldAllBe(k => !k.IsCustom && !k.IsNuget);
workerNodeTelemetryData.TasksExecutionData.Values
.Count(v => v.CumulativeExecutionTime > TimeSpan.Zero || v.ExecutionsCount > 0).ShouldBe(2);
}
[Fact]
public void WorkerNodeTelemetryCollection_CustomTargetsAndTasks()
{
WorkerNodeTelemetryData? workerNodeData = null;
InternalTelemetryConsumingLogger.TestOnly_InternalTelemetryAggregted += dt => workerNodeData = dt;
var testProject = """
<Project>
<UsingTask
TaskName="Task01"
TaskFactory="RoslynCodeTaskFactory"
AssemblyFile="$(MSBuildToolsPath)\Microsoft.Build.Tasks.Core.dll" >
<ParameterGroup />
<Task>
<Code Type="Fragment" Language="cs">
Log.LogMessage(MessageImportance.Low, "Hello, world!");
</Code>
</Task>
</UsingTask>
<UsingTask
TaskName="Task02"
TaskFactory="RoslynCodeTaskFactory"
AssemblyFile="$(MSBuildToolsPath)\Microsoft.Build.Tasks.Core.dll" >
<ParameterGroup />
<Task>
<Code Type="Fragment" Language="cs">
Log.LogMessage(MessageImportance.High, "Hello, world!");
</Code>
</Task>
</UsingTask>
<Target Name="Build" DependsOnTargets="BeforeBuild">
<Message Text="Hello World"/>
<CreateItem Include="foo.bar">
<Output TaskParameter="Include" ItemName="I" />
</CreateItem>
<Task01 />
<Message Text="Bye World"/>
</Target>
<Target Name="BeforeBuild">
<Message Text="Hello World"/>
<Task01 />
</Target>
<Target Name="NotExecuted">
<Message Text="Hello World"/>
</Target>
</Project>
""";
MockLogger logger = new MockLogger(_output);
Helpers.BuildProjectContentUsingBuildManager(
testProject,
logger,
new BuildParameters() { IsTelemetryEnabled = true }).OverallResult.ShouldBe(BuildResultCode.Success);
workerNodeData!.ShouldNotBeNull();
workerNodeData.TargetsExecutionData.ShouldContainKey(new TaskOrTargetTelemetryKey("Build", true, false));
workerNodeData.TargetsExecutionData[new TaskOrTargetTelemetryKey("Build", true, false)].WasExecuted.ShouldBeTrue();
workerNodeData.TargetsExecutionData.ShouldContainKey(new TaskOrTargetTelemetryKey("BeforeBuild", true, false));
workerNodeData.TargetsExecutionData[new TaskOrTargetTelemetryKey("BeforeBuild", true, false)].WasExecuted.ShouldBeTrue();
workerNodeData.TargetsExecutionData.ShouldContainKey(new TaskOrTargetTelemetryKey("NotExecuted", true, false));
workerNodeData.TargetsExecutionData[new TaskOrTargetTelemetryKey("NotExecuted", true, false)].WasExecuted.ShouldBeFalse();
workerNodeData.TargetsExecutionData.Keys.Count.ShouldBe(3);
workerNodeData.TasksExecutionData.Keys.Count.ShouldBeGreaterThan(2);
workerNodeData.TasksExecutionData[(TaskOrTargetTelemetryKey)"Microsoft.Build.Tasks.Message"].ExecutionsCount.ShouldBe(3);
workerNodeData.TasksExecutionData[(TaskOrTargetTelemetryKey)"Microsoft.Build.Tasks.Message"].CumulativeExecutionTime.ShouldBeGreaterThan(TimeSpan.Zero);
workerNodeData.TasksExecutionData[(TaskOrTargetTelemetryKey)"Microsoft.Build.Tasks.CreateItem"].ExecutionsCount.ShouldBe(1);
workerNodeData.TasksExecutionData[(TaskOrTargetTelemetryKey)"Microsoft.Build.Tasks.CreateItem"].CumulativeExecutionTime.ShouldBeGreaterThan(TimeSpan.Zero);
workerNodeData.TasksExecutionData[new TaskOrTargetTelemetryKey("Task01", true, false)].ExecutionsCount.ShouldBe(2);
workerNodeData.TasksExecutionData[new TaskOrTargetTelemetryKey("Task01", true, false)].CumulativeExecutionTime.ShouldBeGreaterThan(TimeSpan.Zero);
workerNodeData.TasksExecutionData[new TaskOrTargetTelemetryKey("Task02", true, false)].ExecutionsCount.ShouldBe(0);
workerNodeData.TasksExecutionData[new TaskOrTargetTelemetryKey("Task02", true, false)].CumulativeExecutionTime.ShouldBe(TimeSpan.Zero);
workerNodeData.TasksExecutionData.Values.Count(v => v.CumulativeExecutionTime > TimeSpan.Zero || v.ExecutionsCount > 0).ShouldBe(3);
workerNodeData.TasksExecutionData.Keys.ShouldAllBe(k => !k.IsNuget);
}
[Fact]
public void WorkerNodeTelemetryCollection_TaskFactoryName()
{
WorkerNodeTelemetryData? workerNodeData = null;
InternalTelemetryConsumingLogger.TestOnly_InternalTelemetryAggregted += dt => workerNodeData = dt;
var testProject = """
<Project>
<UsingTask
TaskName="InlineTask01"
TaskFactory="RoslynCodeTaskFactory"
AssemblyFile="$(MSBuildToolsPath)\Microsoft.Build.Tasks.Core.dll" >
<ParameterGroup />
<Task>
<Code Type="Fragment" Language="cs">
Log.LogMessage(MessageImportance.Low, "Hello from inline task!");
</Code>
</Task>
</UsingTask>
<Target Name="Build">
<Message Text="Hello World"/>
<InlineTask01 />
</Target>
</Project>
""";
MockLogger logger = new MockLogger(_output);
Helpers.BuildProjectContentUsingBuildManager(
testProject,
logger,
new BuildParameters() { IsTelemetryEnabled = true }).OverallResult.ShouldBe(BuildResultCode.Success);
workerNodeData!.ShouldNotBeNull();
// Verify built-in task has AssemblyTaskFactory
var messageTaskKey = (TaskOrTargetTelemetryKey)"Microsoft.Build.Tasks.Message";
workerNodeData.TasksExecutionData.ShouldContainKey(messageTaskKey);
workerNodeData.TasksExecutionData[messageTaskKey].TaskFactoryName.ShouldBe("AssemblyTaskFactory");
// Verify inline task has RoslynCodeTaskFactory
var inlineTaskKey = new TaskOrTargetTelemetryKey("InlineTask01", true, false);
workerNodeData.TasksExecutionData.ShouldContainKey(inlineTaskKey);
workerNodeData.TasksExecutionData[inlineTaskKey].TaskFactoryName.ShouldBe("RoslynCodeTaskFactory");
workerNodeData.TasksExecutionData[inlineTaskKey].ExecutionsCount.ShouldBe(1);
}
[Fact]
public void TelemetryDataUtils_HashesCustomFactoryName()
{
// Create telemetry data with a custom factory name
var tasksData = new Dictionary<TaskOrTargetTelemetryKey, TaskExecutionStats>
{
{ new TaskOrTargetTelemetryKey("CustomTask", true, false), new TaskExecutionStats(TimeSpan.FromMilliseconds(100), 1, 1000, "MyCompany.CustomTaskFactory", null) },
{ new TaskOrTargetTelemetryKey("BuiltInTask", false, false), new TaskExecutionStats(TimeSpan.FromMilliseconds(50), 2, 500, "AssemblyTaskFactory", null) },
{ new TaskOrTargetTelemetryKey("InlineTask", true, false), new TaskExecutionStats(TimeSpan.FromMilliseconds(75), 1, 750, "RoslynCodeTaskFactory", "CLR4") }
};
var targetsData = new Dictionary<TaskOrTargetTelemetryKey, TargetExecutionStats>();
var telemetryData = new WorkerNodeTelemetryData(tasksData, targetsData);
var activityData = telemetryData.AsActivityDataHolder(includeTasksDetails: true, includeTargetDetails: false);
activityData.ShouldNotBeNull();
var properties = activityData.GetActivityProperties();
properties.ShouldContainKey("Tasks");
var taskDetails = properties["Tasks"] as List<TaskDetailInfo>;
taskDetails.ShouldNotBeNull();
// Custom factory name should be hashed
var customTask = taskDetails!.FirstOrDefault(t => t.IsCustom && t.Name != GetHashed("InlineTask"));
customTask.ShouldNotBeNull();
customTask!.FactoryName.ShouldBe(GetHashed("MyCompany.CustomTaskFactory"));
// Known factory names should NOT be hashed
var builtInTask = taskDetails.FirstOrDefault(t => !t.IsCustom);
builtInTask.ShouldNotBeNull();
builtInTask!.FactoryName.ShouldBe("AssemblyTaskFactory");
var inlineTask = taskDetails.FirstOrDefault(t => t.FactoryName == "RoslynCodeTaskFactory");
inlineTask.ShouldNotBeNull();
inlineTask!.FactoryName.ShouldBe("RoslynCodeTaskFactory");
inlineTask.TaskHostRuntime.ShouldBe("CLR4");
}
#if NET
// test in .net core with telemetry opted in to avoid sending it but enable listening to it
[Fact]
public void NodeTelemetryE2E()
{
using TestEnvironment env = TestEnvironment.Create();
env.SetEnvironmentVariable("MSBUILD_TELEMETRY_OPTOUT", null);
env.SetEnvironmentVariable("DOTNET_CLI_TELEMETRY_OPTOUT", null);
var capturedActivities = new List<Activity>();
using var activityStoppedEvent = new ManualResetEventSlim(false);
using var listener = new ActivityListener
{
ShouldListenTo = source => source.Name.StartsWith(TelemetryConstants.DefaultActivitySourceNamespace),
Sample = (ref ActivityCreationOptions<ActivityContext> _) => ActivitySamplingResult.AllDataAndRecorded,
ActivityStarted = a => { lock (capturedActivities) { capturedActivities.Add(a); } },
ActivityStopped = a =>
{
if (a.DisplayName == "VS/MSBuild/Build")
{
activityStoppedEvent.Set();
}
},
};
ActivitySource.AddActivityListener(listener);
// Reset TelemetryManager to force re-initialization with our listener active
TelemetryManager.ResetForTest();
var testProject = @"
<Project>
<Target Name='Build'>
<Message Text='Start'/>
<CreateItem Include='test.txt'>
<Output TaskParameter='Include' ItemName='TestItem' />
</CreateItem>
<Message Text='End'/>
</Target>
<Target Name='Clean'>
<Message Text='Cleaning...'/>
</Target>
</Project>";
using var testEnv = TestEnvironment.Create(_output);
var projectFile = testEnv.CreateFile("test.proj", testProject).Path;
// Set up loggers
var projectFinishedLogger = new ProjectFinishedCapturingLogger();
var buildParameters = new BuildParameters
{
Loggers = new ILogger[] { projectFinishedLogger },
IsTelemetryEnabled = true
};
// Act
using (var buildManager = new BuildManager())
{
// Phase 1: Begin Build - This initializes telemetry infrastructure
buildManager.BeginBuild(buildParameters);
// Phase 2: Execute build requests
var buildRequestData1 = new BuildRequestData(
projectFile,
new Dictionary<string, string?>(),
null,
new[] { "Build" },
null);
buildManager.BuildRequest(buildRequestData1);
var buildRequestData2 = new BuildRequestData(
projectFile,
new Dictionary<string, string?>(),
null,
new[] { "Clean" },
null);
buildManager.BuildRequest(buildRequestData2);
// Phase 3: End Build - This puts telemetry to an system.diagnostics activity
buildManager.EndBuild();
}
// Wait for the activity to be fully processed
activityStoppedEvent.Wait(TimeSpan.FromSeconds(10)).ShouldBeTrue("Timed out waiting for build activity to stop");
// Verify build activity were captured by the listener and contain task and target info
capturedActivities.ShouldNotBeEmpty();
var activity = capturedActivities.FindLast(a => a.DisplayName == "VS/MSBuild/Build").ShouldNotBeNull();
var tags = activity.Tags.ToDictionary(t => t.Key, t => t.Value);
tags.ShouldNotBeNull();
tags.ShouldContainKey("VS.MSBuild.BuildTarget");
tags["VS.MSBuild.BuildTarget"].ShouldNotBeNullOrEmpty();
// Verify task data
var tasks = activity.TagObjects.FirstOrDefault(to => to.Key == "VS.MSBuild.Tasks");
var tasksData = tasks.Value as List<TaskDetailInfo>;
var messageTaskData = tasksData!.FirstOrDefault(t => t.Name == "Microsoft.Build.Tasks.Message");
messageTaskData.ShouldNotBeNull();
// Verify Message task execution metrics
messageTaskData.ExecutionsCount.ShouldBe(3);
messageTaskData.TotalMilliseconds.ShouldBeGreaterThan(0);
messageTaskData.TotalMemoryBytes.ShouldBeGreaterThanOrEqualTo(0);
messageTaskData.IsCustom.ShouldBe(false);
// Verify CreateItem task execution metrics
var createItemTaskData = tasksData!.FirstOrDefault(t => t.Name == "Microsoft.Build.Tasks.CreateItem");
createItemTaskData.ShouldNotBeNull();
createItemTaskData.ExecutionsCount.ShouldBe(1);
createItemTaskData.TotalMilliseconds.ShouldBeGreaterThan(0);
createItemTaskData.TotalMemoryBytes.ShouldBeGreaterThanOrEqualTo(0);
// Verify TaskFactoryName is populated for built-in tasks
messageTaskData.FactoryName.ShouldBe("AssemblyTaskFactory");
createItemTaskData.FactoryName.ShouldBe("AssemblyTaskFactory");
// Verify Targets summary information
var targetsSummaryTagObject = activity.TagObjects.FirstOrDefault(to => to.Key.Contains("VS.MSBuild.TargetsSummary"));
var targetsSummary = targetsSummaryTagObject.Value as TargetsSummaryInfo;
targetsSummary.ShouldNotBeNull();
targetsSummary.Loaded.Total.ShouldBe(2);
targetsSummary.Executed.Total.ShouldBe(2);
// Verify Tasks summary information
var tasksSummaryTagObject = activity.TagObjects.FirstOrDefault(to => to.Key.Contains("VS.MSBuild.TasksSummary"));
var tasksSummary = tasksSummaryTagObject.Value as TasksSummaryInfo;
tasksSummary.ShouldNotBeNull();
tasksSummary.Microsoft.ShouldNotBeNull();
tasksSummary.Microsoft!.Total!.ExecutionsCount.ShouldBe(4);
tasksSummary.Microsoft!.Total!.TotalMilliseconds.ShouldBeGreaterThan(0);
// Allowing 0 for TotalMemoryBytes as it is possible for tasks to allocate no memory in certain scenarios.
tasksSummary.Microsoft.Total.TotalMemoryBytes.ShouldBeGreaterThanOrEqualTo(0);
}
#endif
private sealed class ProjectFinishedCapturingLogger : ILogger
{
private readonly List<ProjectFinishedEventArgs> _projectFinishedEventArgs = [];
public LoggerVerbosity Verbosity { get; set; }
public string? Parameters { get; set; }
public IReadOnlyList<ProjectFinishedEventArgs> ProjectFinishedEventArgsReceived => _projectFinishedEventArgs;
public void Initialize(IEventSource eventSource) => eventSource.ProjectFinished += EventSource_ProjectFinished;
private void EventSource_ProjectFinished(object sender, ProjectFinishedEventArgs e) => _projectFinishedEventArgs.Add(e);
public void Shutdown() { }
}
[Fact]
public void BuildIncrementalityInfo_AllTargetsExecuted_ClassifiedAsFull()
{
// Arrange: All targets were executed (none skipped)
var targetsData = new Dictionary<TaskOrTargetTelemetryKey, TargetExecutionStats>
{
{ new TaskOrTargetTelemetryKey("Build", false, false), TargetExecutionStats.Executed() },
{ new TaskOrTargetTelemetryKey("Compile", false, false), TargetExecutionStats.Executed() },
{ new TaskOrTargetTelemetryKey("Link", false, false), TargetExecutionStats.Executed() },
{ new TaskOrTargetTelemetryKey("Pack", false, false), TargetExecutionStats.Executed() },
};
var tasksData = new Dictionary<TaskOrTargetTelemetryKey, TaskExecutionStats>();
var telemetryData = new WorkerNodeTelemetryData(tasksData, targetsData);
// Act
var activityData = telemetryData.AsActivityDataHolder(includeTasksDetails: false, includeTargetDetails: false);
var properties = activityData!.GetActivityProperties();
// Assert
properties.ShouldContainKey("Incrementality");
var incrementality = properties["Incrementality"] as BuildInsights.BuildIncrementalityInfo;
incrementality.ShouldNotBeNull();
incrementality!.Classification.ShouldBe(BuildInsights.BuildType.Full);
incrementality.TotalTargetsCount.ShouldBe(4);
incrementality.ExecutedTargetsCount.ShouldBe(4);
incrementality.SkippedTargetsCount.ShouldBe(0);
incrementality.IncrementalityRatio.ShouldBe(0.0);
}
[Fact]
public void BuildIncrementalityInfo_MostTargetsSkipped_ClassifiedAsIncremental()
{
// Arrange: Most targets were skipped (>70%)
var targetsData = new Dictionary<TaskOrTargetTelemetryKey, TargetExecutionStats>
{
{ new TaskOrTargetTelemetryKey("Build", false, false), TargetExecutionStats.Skipped(TargetSkipReason.OutputsUpToDate) },
{ new TaskOrTargetTelemetryKey("Compile", false, false), TargetExecutionStats.Skipped(TargetSkipReason.OutputsUpToDate) },
{ new TaskOrTargetTelemetryKey("Link", false, false), TargetExecutionStats.Skipped(TargetSkipReason.ConditionWasFalse) },
{ new TaskOrTargetTelemetryKey("Pack", false, false), TargetExecutionStats.Executed() }, // Only one executed
};
var tasksData = new Dictionary<TaskOrTargetTelemetryKey, TaskExecutionStats>();
var telemetryData = new WorkerNodeTelemetryData(tasksData, targetsData);
// Act
var activityData = telemetryData.AsActivityDataHolder(includeTasksDetails: false, includeTargetDetails: false);
var properties = activityData!.GetActivityProperties();
// Assert
properties.ShouldContainKey("Incrementality");
var incrementality = properties["Incrementality"] as BuildInsights.BuildIncrementalityInfo;
incrementality.ShouldNotBeNull();
incrementality!.Classification.ShouldBe(BuildInsights.BuildType.Incremental);
incrementality.TotalTargetsCount.ShouldBe(4);
incrementality.ExecutedTargetsCount.ShouldBe(1);
incrementality.SkippedTargetsCount.ShouldBe(3);
incrementality.SkippedDueToUpToDateCount.ShouldBe(2);
incrementality.SkippedDueToConditionCount.ShouldBe(1);
incrementality.SkippedDueToPreviouslyBuiltCount.ShouldBe(0);
incrementality.IncrementalityRatio.ShouldBe(0.75);
}
[Fact]
public void BuildIncrementalityInfo_NoTargets_ClassifiedAsUnknown()
{
// Arrange: No targets
var targetsData = new Dictionary<TaskOrTargetTelemetryKey, TargetExecutionStats>();
var tasksData = new Dictionary<TaskOrTargetTelemetryKey, TaskExecutionStats>();
var telemetryData = new WorkerNodeTelemetryData(tasksData, targetsData);
// Act
var activityData = telemetryData.AsActivityDataHolder(includeTasksDetails: false, includeTargetDetails: false);
var properties = activityData!.GetActivityProperties();
// Assert
properties.ShouldContainKey("Incrementality");
var incrementality = properties["Incrementality"] as BuildInsights.BuildIncrementalityInfo;
incrementality.ShouldNotBeNull();
incrementality!.Classification.ShouldBe(BuildInsights.BuildType.Unknown);
incrementality.TotalTargetsCount.ShouldBe(0);
incrementality.IncrementalityRatio.ShouldBe(0.0);
}
}
}
|