Emmit BuildTelemetry event

src/Build.UnitTests/BackEnd/KnownTelemetry_Tests.cs

@@ -0,0 +1,121 @@
+// Copyright (c) Microsoft. All rights reserved.
+// Licensed under the MIT license. See LICENSE file in the project root for full license information.
+
+#nullable disable
+using System;
+using System.Globalization;
+using Microsoft.Build.Framework.Telemetry;
+using Shouldly;
+using Xunit;
+
+namespace Microsoft.Build.UnitTests.Telemetry;
+
+public class KnownTelemetry_Tests
+{
+    [Fact]
+    public void BuildTelemetryCanBeSetToNull()
+    {
+        KnownTelemetry.BuildTelemetry = new BuildTelemetry();
+        KnownTelemetry.BuildTelemetry = null;
+
+        KnownTelemetry.BuildTelemetry.ShouldBeNull();
+    }
+
+    [Fact]
+    public void BuildTelemetryCanBeSet()
+    {
+        BuildTelemetry buildTelemetry = new BuildTelemetry();
+        KnownTelemetry.BuildTelemetry = buildTelemetry;
+
+        KnownTelemetry.BuildTelemetry.ShouldBeSameAs(buildTelemetry);
+    }
+
+    [Fact]
+    public void BuildTelemetryConstructedHasNoProperties()
+    {
+        BuildTelemetry buildTelemetry = new BuildTelemetry();
+
+        buildTelemetry.DisplayVersion.ShouldBeNull();
+        buildTelemetry.EventName.ShouldBe("build");
+        buildTelemetry.FinishedAt.ShouldBeNull();
+        buildTelemetry.FrameworkName.ShouldBeNull();
+        buildTelemetry.Host.ShouldBeNull();
+        buildTelemetry.InitialServerState.ShouldBeNull();
+        buildTelemetry.InnerStartAt.ShouldBeNull();
+        buildTelemetry.Project.ShouldBeNull();
+        buildTelemetry.ServerFallbackReason.ShouldBeNull();
+        buildTelemetry.StartAt.ShouldBeNull();
+        buildTelemetry.Success.ShouldBeNull();
+        buildTelemetry.Target.ShouldBeNull();
+        buildTelemetry.Version.ShouldBeNull();
+
+        buildTelemetry.UpdateEventProperties();
+        buildTelemetry.Properties.ShouldBeEmpty();
+    }
+
+    [Fact]
+    public void BuildTelemetryCreateProperProperties()
+    {
+        BuildTelemetry buildTelemetry = new BuildTelemetry();
+
+        DateTime startAt = new DateTime(2023, 01, 02, 10, 11, 22);
+        DateTime innerStartAt = new DateTime(2023, 01, 02, 10, 20, 30);
+        DateTime finishedAt = new DateTime(2023, 12, 13, 14, 15, 16);
+
+        buildTelemetry.DisplayVersion = "Some Display Version";
+        buildTelemetry.FinishedAt = finishedAt;
+        buildTelemetry.FrameworkName = "new .NET";
+        buildTelemetry.Host = "Host description";
+        buildTelemetry.InitialServerState = "hot";
+        buildTelemetry.InnerStartAt = innerStartAt;
+        buildTelemetry.Project = @"C:\\dev\\theProject";
+        buildTelemetry.ServerFallbackReason = "busy";
+        buildTelemetry.StartAt = startAt;
+        buildTelemetry.Success = true;
+        buildTelemetry.Target = "clean";
+        buildTelemetry.Version = new Version(1, 2, 3, 4);
+
+        buildTelemetry.UpdateEventProperties();
+        buildTelemetry.Properties.Count.ShouldBe(11);
+
+        buildTelemetry.Properties["BuildEngineDisplayVersion"].ShouldBe("Some Display Version");
+        buildTelemetry.Properties["BuildEngineFrameworkName"].ShouldBe("new .NET");
+        buildTelemetry.Properties["BuildEngineHost"].ShouldBe("Host description");
+        buildTelemetry.Properties["InitialMSBuildServerState"].ShouldBe("hot");
+        buildTelemetry.Properties["ProjectPath"].ShouldBe(@"C:\\dev\\theProject");
+        buildTelemetry.Properties["ServerFallbackReason"].ShouldBe("busy");
+        buildTelemetry.Properties["BuildSuccess"].ShouldBe("True");
+        buildTelemetry.Properties["BuildTarget"].ShouldBe("clean");
+        buildTelemetry.Properties["BuildEngineVersion"].ShouldBe("1.2.3.4");
+
+        // verify computed
+        buildTelemetry.Properties["BuildDurationInMilliseconds"] = (finishedAt - startAt).TotalMilliseconds.ToString(CultureInfo.InvariantCulture);
+        buildTelemetry.Properties["InnerBuildDurationInMilliseconds"] = (finishedAt - innerStartAt).TotalMilliseconds.ToString(CultureInfo.InvariantCulture);
+    }
+
+    [Fact]
+    public void BuildTelemetryHandleNullsInRecordedTimes()
+    {
+        BuildTelemetry buildTelemetry = new BuildTelemetry();
+
+        buildTelemetry.StartAt = DateTime.MinValue;
+        buildTelemetry.FinishedAt = null;
+        buildTelemetry.UpdateEventProperties();
+        buildTelemetry.Properties.ShouldBeEmpty();
+
+        buildTelemetry.StartAt = null;
+        buildTelemetry.FinishedAt = DateTime.MaxValue;
+        buildTelemetry.UpdateEventProperties();
+        buildTelemetry.Properties.ShouldBeEmpty();
+
+        buildTelemetry.InnerStartAt = DateTime.MinValue;
+        buildTelemetry.FinishedAt = null;
+        buildTelemetry.UpdateEventProperties();
+        buildTelemetry.Properties.ShouldBeEmpty();
+
+        buildTelemetry.InnerStartAt = null;
+        buildTelemetry.FinishedAt = DateTime.MaxValue;
+        buildTelemetry.UpdateEventProperties();
+        buildTelemetry.Properties.ShouldBeEmpty();
+    }
+}

src/Build/BackEnd/BuildManager/BuildManager.cs

@@ -25,6 +25,7 @@
 using Microsoft.Build.Exceptions;
 using Microsoft.Build.Experimental.ProjectCache;
 using Microsoft.Build.Framework;
+using Microsoft.Build.Framework.Telemetry;
 using Microsoft.Build.Graph;
 using Microsoft.Build.Internal;
 using Microsoft.Build.Logging;
@@ -456,7 +457,7 @@ public void BeginBuild(BuildParameters parameters)
                         _nodeManager?.ShutdownAllNodes();
                         _taskHostNodeManager?.ShutdownAllNodes();
                     }
-               }
+                }
             }
 
             _previousLowPriority = parameters.LowPriority;
@@ -470,6 +471,14 @@ public void BeginBuild(BuildParameters parameters)
 
                 MSBuildEventSource.Log.BuildStart();
 
+                // Initiate build telemetry data
+                DateTime now = DateTime.UtcNow;
+                KnownTelemetry.BuildTelemetry ??= new()
+                {
+                    StartAt = now,
+                };
+                KnownTelemetry.BuildTelemetry.InnerStartAt = now;
+
                 if (BuildParameters.DumpOpportunisticInternStats)
                 {
                     Strings.EnableDiagnostics();
@@ -796,6 +805,13 @@ public BuildSubmission PendBuildRequest(BuildRequestData requestData)
                 VerifyStateInternal(BuildManagerState.Building);
 
                 var newSubmission = new BuildSubmission(this, GetNextSubmissionId(), requestData, _buildParameters.LegacyThreadingSemantics);
+
+                if (KnownTelemetry.BuildTelemetry != null)
+                {
+                    KnownTelemetry.BuildTelemetry.Project ??= requestData.ProjectFullPath;
+                    KnownTelemetry.BuildTelemetry.Target ??= string.Join(",", requestData.TargetNames);
+                }
+
                 _buildSubmissions.Add(newSubmission.SubmissionId, newSubmission);
                 _noActiveSubmissionsEvent.Reset();
                 return newSubmission;
@@ -817,6 +833,13 @@ public GraphBuildSubmission PendBuildRequest(GraphBuildRequestData requestData)
                 VerifyStateInternal(BuildManagerState.Building);
 
                 var newSubmission = new GraphBuildSubmission(this, GetNextSubmissionId(), requestData);
+
+                if (KnownTelemetry.BuildTelemetry != null)
+                {
+                    KnownTelemetry.BuildTelemetry.Project ??= requestData.ProjectGraphEntryPoints?.FirstOrDefault().ProjectFile;
+                    KnownTelemetry.BuildTelemetry.Target ??= string.Join(",", requestData.TargetNames);
+                }
+
                 _graphBuildSubmissions.Add(newSubmission.SubmissionId, newSubmission);
                 _noActiveSubmissionsEvent.Reset();
                 return newSubmission;
@@ -965,6 +988,36 @@ public void EndBuild()
                         }
 
                         loggingService.LogBuildFinished(_overallBuildSuccess);
+
+                        if (KnownTelemetry.BuildTelemetry != null)
+                        {
+                            KnownTelemetry.BuildTelemetry.FinishedAt = DateTime.UtcNow;
+                            KnownTelemetry.BuildTelemetry.Success = _overallBuildSuccess;
+                            KnownTelemetry.BuildTelemetry.Version = ProjectCollection.Version;
+                            KnownTelemetry.BuildTelemetry.DisplayVersion = ProjectCollection.DisplayVersion;
+                            KnownTelemetry.BuildTelemetry.FrameworkName = NativeMethodsShared.FrameworkName;
+                            NativeMethodsShared.GetOSNameForExtensionsPath();
+
+                            string host = null;
+                            if (BuildEnvironmentState.s_runningInVisualStudio)
+                            {
+                                host = "VS";
+                            }
+                            else if (!string.IsNullOrEmpty(Environment.GetEnvironmentVariable("MSBUILD_HOST_NAME")))
+                            {
+                                host = Environment.GetEnvironmentVariable("MSBUILD_HOST_NAME");
+                            }
+                            else if (!string.IsNullOrEmpty(Environment.GetEnvironmentVariable("VSCODE_CWD")) || Environment.GetEnvironmentVariable("TERM_PROGRAM") == "vscode")
+                            {
+                                host = "VSCode";
+                            }
+                            KnownTelemetry.BuildTelemetry.Host = host;
+
+                            KnownTelemetry.BuildTelemetry.UpdateEventProperties();
+                            loggingService.LogTelemetry(buildEventContext: null, KnownTelemetry.BuildTelemetry.EventName, KnownTelemetry.BuildTelemetry.Properties);
+                            // Clean telemetry which makes it ready for next build submission.
+                            KnownTelemetry.BuildTelemetry = null;
+                        }
                     }
 
                     ShutdownLoggingService(loggingService);

src/Build/BackEnd/Client/MSBuildClient.cs

@@ -15,6 +15,7 @@
 using Microsoft.Build.Eventing;
 using Microsoft.Build.Execution;
 using Microsoft.Build.Framework;
+using Microsoft.Build.Framework.Telemetry;
 using Microsoft.Build.Internal;
 using Microsoft.Build.Shared;
 
@@ -152,6 +153,10 @@ public MSBuildClientExitResult Execute(CancellationToken cancellationToken)
 
             // Start server it if is not running.
             bool serverIsAlreadyRunning = ServerNamedMutex.WasOpen(serverRunningMutexName);
+            if (KnownTelemetry.BuildTelemetry != null)
+            {
+                KnownTelemetry.BuildTelemetry.InitialServerState = serverIsAlreadyRunning ? "hot" : "cold";
+            }
             if (!serverIsAlreadyRunning)
             {
                 CommunicationsUtilities.Trace("Server was not running. Starting server now.");
@@ -432,13 +437,23 @@ private ServerNodeBuildCommand GetServerNodeBuildCommand()
             // We remove env variable used to invoke MSBuild server as that might be equal to 1, so we do not get an infinite recursion here. 
             envVars[Traits.UseMSBuildServerEnvVarName] = "0";
 
+            Debug.Assert(KnownTelemetry.BuildTelemetry == null || KnownTelemetry.BuildTelemetry.StartAt.HasValue, "BuildTelemetry.StartAt was not initialized!");
+
+            PartialBuildTelemetry? partialBuildTelemetry = KnownTelemetry.BuildTelemetry == null
+                ? null
+                : new PartialBuildTelemetry(
+                    startedAt: KnownTelemetry.BuildTelemetry.StartAt.GetValueOrDefault(),
+                    initialServerState: KnownTelemetry.BuildTelemetry.InitialServerState,
+                    serverFallbackReason: KnownTelemetry.BuildTelemetry.ServerFallbackReason);
+
             return new ServerNodeBuildCommand(
                         _commandLine,
                         startupDirectory: Directory.GetCurrentDirectory(),
                         buildProcessEnvironment: envVars,
                         CultureInfo.CurrentCulture,
                         CultureInfo.CurrentUICulture,
-                        _consoleConfiguration!);
+                        _consoleConfiguration!,
+                        partialBuildTelemetry);
         }
 
         private ServerNodeHandshake GetHandshake()

src/Build/BackEnd/Node/OutOfProcServerNode.cs

@@ -6,12 +6,13 @@
 using System.Collections.Concurrent;
 using System.IO;
 using System.Threading;
+using System.Threading.Tasks;
 using Microsoft.Build.BackEnd;
 using Microsoft.Build.Shared;
 using Microsoft.Build.Internal;
-using System.Threading.Tasks;
 using Microsoft.Build.Execution;
 using Microsoft.Build.BackEnd.Logging;
+using Microsoft.Build.Framework.Telemetry;
 
 namespace Microsoft.Build.Experimental
 {
@@ -332,6 +333,18 @@ private void HandleServerNodeBuildCommand(ServerNodeBuildCommand command)
             // Configure console configuration so Loggers can change their behavior based on Target (client) Console properties.
             ConsoleConfiguration.Provider = command.ConsoleConfiguration;
 
+            // Initiate build telemetry
+            if (KnownTelemetry.BuildTelemetry == null)
+            {
+                KnownTelemetry.BuildTelemetry = new BuildTelemetry();
+            }
+            if (command.PartialBuildTelemetry != null)
+            {
+                KnownTelemetry.BuildTelemetry.StartAt = command.PartialBuildTelemetry.StartedAt;
+                KnownTelemetry.BuildTelemetry.InitialServerState = command.PartialBuildTelemetry.InitialServerState;
+                KnownTelemetry.BuildTelemetry.ServerFallbackReason = command.PartialBuildTelemetry.ServerFallbackReason;
+            }
+
             // Also try our best to increase chance custom Loggers which use Console static members will work as expected.
             try
             {

src/Build/BackEnd/Node/PartialBuildTelemetry.cs

@@ -0,0 +1,51 @@
+// Copyright (c) Microsoft. All rights reserved.
+// Licensed under the MIT license. See LICENSE file in the project root for full license information.
+
+using System;
+
+namespace Microsoft.Build.BackEnd;
+
+/// <summary>
+/// Part of BuildTelemetry which is collected on client and needs to be sent to server,
+/// so server can log BuildTelemetry once it is finished.
+/// </summary>
+internal sealed class PartialBuildTelemetry : ITranslatable
+{
+    private DateTime _startedAt = default;
+    private string? _initialServerState = default;
+    private string? _serverFallbackReason = default;
+
+    public PartialBuildTelemetry(DateTime startedAt, string? initialServerState, string? serverFallbackReason)
+    {
+        _startedAt = startedAt;
+        _initialServerState = initialServerState;
+        _serverFallbackReason = serverFallbackReason;
+    }
+
+    /// <summary>
+    /// Constructor for deserialization
+    /// </summary>
+    private PartialBuildTelemetry()
+    {
+    }
+
+    public DateTime? StartedAt => _startedAt;
+
+    public string? InitialServerState => _initialServerState;
+
+    public string? ServerFallbackReason => _serverFallbackReason;
+
+    public void Translate(ITranslator translator)
+    {
+        translator.Translate(ref _startedAt);
+        translator.Translate(ref _initialServerState);
+        translator.Translate(ref _serverFallbackReason);
+    }
+
+    internal static PartialBuildTelemetry FactoryForDeserialization(ITranslator translator)
+    {
+        PartialBuildTelemetry partialTelemetryData = new();
+        partialTelemetryData.Translate(translator);
+        return partialTelemetryData;
+    }
+}

src/Build/BackEnd/Node/ServerNodeBuildCommand.cs

@@ -24,6 +24,7 @@ internal sealed class ServerNodeBuildCommand : INodePacket
         private CultureInfo _culture = default!;
         private CultureInfo _uiCulture = default!;
         private TargetConsoleConfiguration _consoleConfiguration = default!;
+        private PartialBuildTelemetry? _partialBuildTelemetry = default;
 
         /// <summary>
         /// Retrieves the packet type.
@@ -64,6 +65,12 @@ internal sealed class ServerNodeBuildCommand : INodePacket
         /// </summary>
         public TargetConsoleConfiguration ConsoleConfiguration => _consoleConfiguration;
 
+        /// <summary>
+        /// Part of BuildTelemetry which is collected on client and needs to be sent to server,
+        /// so server can log BuildTelemetry once it is finished.
+        /// </summary>
+        public PartialBuildTelemetry? PartialBuildTelemetry => _partialBuildTelemetry;
+
         /// <summary>
         /// Private constructor for deserialization
         /// </summary>
@@ -80,7 +87,8 @@ public ServerNodeBuildCommand(
             string startupDirectory,
             Dictionary<string, string> buildProcessEnvironment,
             CultureInfo culture, CultureInfo uiCulture,
-            TargetConsoleConfiguration consoleConfiguration)
+            TargetConsoleConfiguration consoleConfiguration,
+            PartialBuildTelemetry? partialBuildTelemetry)
         {
             ErrorUtilities.VerifyThrowInternalNull(consoleConfiguration, nameof(consoleConfiguration));
 
@@ -90,6 +98,7 @@ public ServerNodeBuildCommand(
             _culture = culture;
             _uiCulture = uiCulture;
             _consoleConfiguration = consoleConfiguration;
+            _partialBuildTelemetry = partialBuildTelemetry;
         }
 
         /// <summary>
@@ -104,6 +113,7 @@ public void Translate(ITranslator translator)
             translator.TranslateCulture(ref _culture);
             translator.TranslateCulture(ref _uiCulture);
             translator.Translate(ref _consoleConfiguration, TargetConsoleConfiguration.FactoryForDeserialization);
+            translator.Translate(ref _partialBuildTelemetry, PartialBuildTelemetry.FactoryForDeserialization);
         }
 
         /// <summary>