Improve debugging experience: add global switch MSBuildDebugEngine; I…

…nject binary logger from BuildManager; print static graph as .dot file (#6639) ### Context There's still a bit of friction when debugging MSBuild, especially under VS. You have to set multiple env vars, or search through temp, find all the obscure env var names, etc ### Changes Made - add one env var, `MSBuildDebugEngine` to turn everything on and also automatically pick `./MSBuild_Logs` as the debug log path for everything that spews out log files. - in addition, when `MSBuildDebugEngine`: - inject a binary logger directly from the build manager. This is super useful when running MSBuild in VS, as the build logging that VS gives is kind of lacking - dump a `.dot` representation of the static graph, when one is available This is how `MSBuild_Logs` looks like after doing a build (both VS and cmdline should produce this): ![image](https://user-images.githubusercontent.com/2255729/123869003-4b74fa80-d8e5-11eb-8fef-bd0bea421411.png)
dotnet · Jul 26, 2021 · cdb5077 · cdb5077
1 parent 80dae43
commit cdb5077
Show file tree

Hide file tree

Showing 16 changed files with 463 additions and 345 deletions.
diff --git a/documentation/wiki/ChangeWaves.md b/documentation/wiki/ChangeWaves.md
@@ -32,6 +32,7 @@ A wave of features is set to "rotate out" (i.e. become standard functionality) t
 - [Don't compile globbing regexes on .NET Framework](https://github.com/dotnet/msbuild/pull/6632)
 - [Default to transitively copying content items](https://github.com/dotnet/msbuild/pull/6622)
 - [Reference assemblies are now no longer placed in the `bin` directory by default](https://github.com/dotnet/msbuild/pull/6560)
+- [Improve debugging experience: add global switch MSBuildDebugEngine; Inject binary logger from BuildManager; print static graph as .dot file](https://github.com/dotnet/msbuild/pull/6639)
 
 ## Change Waves No Longer In Rotation
 ### 16.8

diff --git a/src/Build.UnitTests/Graph/ProjectGraph_Tests.cs b/src/Build.UnitTests/Graph/ProjectGraph_Tests.cs
@@ -1477,22 +1477,34 @@ public void DotNotationShouldRepresentGraph(Dictionary<int, int[]> edges)
             var graph = Helpers.CreateProjectGraph(
                 _env,
                 edges,
-                new Dictionary<string, string> {{"a", "b"}});
+                globalProperties: new Dictionary<string, string> {{"a", "b"}},
+                createProjectFile: (env, projectId, references, _, _, _) => Helpers.CreateProjectFile(
+                    env,
+                    projectId,
+                    references,
+                    projectReferenceTargets: new Dictionary<string, string[]>
+                    {
+                        {"Build", new[] {$"TargetFrom{projectId}", "Build"}}
+                    }));
 
+            var targetsPerNode = graph.GetTargetLists(new []{ "Build" });
 
             Func<ProjectGraphNode, string> nodeIdProvider = GetProjectFileName;
 
-            var dot = graph.ToDot(nodeIdProvider);
+            var dot = graph.ToDot(nodeIdProvider, targetsPerNode);
 
             var edgeCount = 0;
 
             foreach (var node in graph.ProjectNodes)
             {
                 var nodeId = nodeIdProvider(node);
 
+                var targets = string.Join(".*", targetsPerNode[node]);
+                targets.ShouldNotBeNullOrEmpty();
+
                 foreach (var globalProperty in node.ProjectInstance.GlobalProperties)
                 {
-                    dot.ShouldMatch($@"{nodeId}\s*\[.*{globalProperty.Key}.*{globalProperty.Value}.*\]");
+                    dot.ShouldMatch($@"{nodeId}\s*\[.*{targets}.*{globalProperty.Key}.*{globalProperty.Value}.*\]");
                 }
 
                 foreach (var reference in node.ProjectReferences)

diff --git a/src/Build/BackEnd/BuildManager/BuildManager.cs b/src/Build/BackEnd/BuildManager/BuildManager.cs
@@ -30,7 +30,9 @@
 using Microsoft.Build.Internal;
 using Microsoft.Build.Logging;
 using Microsoft.Build.Shared;
+using Microsoft.Build.Shared.Debugging;
 using Microsoft.Build.Shared.FileSystem;
+using Microsoft.Build.Utilities;
 using ForwardingLoggerRecord = Microsoft.Build.Logging.ForwardingLoggerRecord;
 using LoggerDescription = Microsoft.Build.Logging.LoggerDescription;
 
@@ -486,7 +488,7 @@ public void BeginBuild(BuildParameters parameters)
             ILoggingService InitializeLoggingService()
             {
                 ILoggingService loggingService = CreateLoggingService(
-                    _buildParameters.Loggers,
+                    AppendDebuggingLoggers(_buildParameters.Loggers),
                     _buildParameters.ForwardingLoggers,
                     _buildParameters.WarningsAsErrors,
                     _buildParameters.WarningsAsMessages);
@@ -518,6 +520,22 @@ ILoggingService InitializeLoggingService()
                 return loggingService;
             }
 
+            // VS builds discard many msbuild events so attach a binlogger to capture them all.
+            IEnumerable<ILogger> AppendDebuggingLoggers(IEnumerable<ILogger> loggers)
+            {
+                if (DebugUtils.ShouldDebugCurrentProcess is false ||
+                    Traits.Instance.DebugEngine is false)
+                {
+                    return loggers;
+                }
+
+                var binlogPath = DebugUtils.FindNextAvailableDebugFilePath($"{DebugUtils.ProcessInfoString}_BuildManager_{_hostName}.binlog");
+
+                var logger = new BinaryLogger { Parameters = binlogPath };
+
+                return (loggers ?? Enumerable.Empty<ILogger>()).Concat(new[] { logger });
+            }
+
             void InitializeCaches()
             {
                 Debug.Assert(Monitor.IsEntered(_syncLock));
@@ -561,17 +579,14 @@ void InitializeCaches()
             }
         }
 
-        private void AttachDebugger()
+        private static void AttachDebugger()
         {
             if (Debugger.IsAttached)
             {
                 return;
             }
 
-            var processNameToBreakInto = Environment.GetEnvironmentVariable("MSBuildDebugBuildManagerOnStartProcessName");
-            var thisProcessMatchesName = string.IsNullOrWhiteSpace(processNameToBreakInto) || Process.GetCurrentProcess().ProcessName.Contains(processNameToBreakInto);
-
-            if (!thisProcessMatchesName)
+            if (!DebugUtils.ShouldDebugCurrentProcess)
             {
                 return;
             }
@@ -1757,11 +1772,17 @@ private void ExecuteGraphBuildScheduler(GraphBuildSubmission submission)
                 if (submission.BuildRequestData.GraphBuildOptions.Build)
                 {
                     var cacheServiceTask = Task.Run(() => SearchAndInitializeProjectCachePluginFromGraph(projectGraph));
-                    var targetListTask = Task.Run(() => projectGraph.GetTargetLists(submission.BuildRequestData.TargetNames));
+                    var targetListTask = projectGraph.GetTargetLists(submission.BuildRequestData.TargetNames);
+
+                    DumpGraph(projectGraph, targetListTask);
 
                     using DisposablePluginService cacheService = cacheServiceTask.Result;
 
-                    resultsPerNode = BuildGraph(projectGraph, targetListTask.Result, submission.BuildRequestData);
+                    resultsPerNode = BuildGraph(projectGraph, targetListTask, submission.BuildRequestData);
+                }
+                else
+                {
+                    DumpGraph(projectGraph);
                 }
 
                 ErrorUtilities.VerifyThrow(
@@ -1825,6 +1846,18 @@ private void ExecuteGraphBuildScheduler(GraphBuildSubmission submission)
                     _overallBuildSuccess = false;
                 }
             }
+
+            static void DumpGraph(ProjectGraph graph, IReadOnlyDictionary<ProjectGraphNode, ImmutableList<string>> targetList = null)
+            {
+                if (Traits.Instance.DebugEngine is false)
+                {
+                    return;
+                }
+
+                var logPath = DebugUtils.FindNextAvailableDebugFilePath($"{DebugUtils.ProcessInfoString}_ProjectGraph.dot");
+
+                File.WriteAllText(logPath, graph.ToDot(targetList));
+            }
         }
 
         private Dictionary<ProjectGraphNode, BuildResult> BuildGraph(

diff --git a/src/Build/BackEnd/Components/BuildRequestEngine/BuildRequestEngine.cs b/src/Build/BackEnd/Components/BuildRequestEngine/BuildRequestEngine.cs
@@ -12,6 +12,8 @@
 using Microsoft.Build.BackEnd.Logging;
 using Microsoft.Build.Execution;
 using Microsoft.Build.Shared;
+using Microsoft.Build.Shared.Debugging;
+using Microsoft.Build.Utilities;
 using BuildAbortedException = Microsoft.Build.Exceptions.BuildAbortedException;
 
 namespace Microsoft.Build.BackEnd
@@ -115,8 +117,10 @@ internal class BuildRequestEngine : IBuildRequestEngine, IBuildComponent
         /// </summary>
         internal BuildRequestEngine()
         {
-            _debugDumpState = Environment.GetEnvironmentVariable("MSBUILDDEBUGSCHEDULER") == "1";
-            _debugDumpPath = Environment.GetEnvironmentVariable("MSBUILDDEBUGPATH");
+            _debugDumpState = Traits.Instance.DebugScheduler;
+            _debugDumpPath = ChangeWaves.AreFeaturesEnabled(ChangeWaves.Wave17_0)
+                ? DebugUtils.DebugPath
+                : Environment.GetEnvironmentVariable("MSBUILDDEBUGPATH");
             _debugForceCaching = Environment.GetEnvironmentVariable("MSBUILDDEBUGFORCECACHING") == "1";
 
             if (String.IsNullOrEmpty(_debugDumpPath))

diff --git a/src/Build/BackEnd/Components/Scheduler/Scheduler.cs b/src/Build/BackEnd/Components/Scheduler/Scheduler.cs
@@ -14,6 +14,7 @@
 using Microsoft.Build.Experimental.ProjectCache;
 using Microsoft.Build.Framework;
 using Microsoft.Build.Shared;
+using Microsoft.Build.Shared.Debugging;
 using Microsoft.Build.Utilities;
 using BuildAbortedException = Microsoft.Build.Exceptions.BuildAbortedException;
 using ILoggingService = Microsoft.Build.BackEnd.Logging.ILoggingService;
@@ -176,8 +177,10 @@ internal class Scheduler : IScheduler
         /// </summary>
         public Scheduler()
         {
-            _debugDumpState = Environment.GetEnvironmentVariable("MSBUILDDEBUGSCHEDULER") == "1";
-            _debugDumpPath = Environment.GetEnvironmentVariable("MSBUILDDEBUGPATH");
+            _debugDumpState = Traits.Instance.DebugScheduler;
+            _debugDumpPath = ChangeWaves.AreFeaturesEnabled(ChangeWaves.Wave17_0)
+                ? DebugUtils.DebugPath
+                : Environment.GetEnvironmentVariable("MSBUILDDEBUGPATH");
             _schedulingUnlimitedVariable = Environment.GetEnvironmentVariable("MSBUILDSCHEDULINGUNLIMITED");
             _nodeLimitOffset = 0;
 

diff --git a/src/Build/BackEnd/Components/Scheduler/SchedulingPlan.cs b/src/Build/BackEnd/Components/Scheduler/SchedulingPlan.cs
@@ -10,6 +10,7 @@
 using Microsoft.Build.Shared;
 using Microsoft.Build.BackEnd.Logging;
 using Microsoft.Build.Shared.FileSystem;
+using Microsoft.Build.Utilities;
 
 namespace Microsoft.Build.BackEnd
 {
@@ -316,7 +317,7 @@ private int GetConfigWithComparison(IEnumerable<int> realConfigsToSchedule, Comp
         private void AnalyzeData()
         {
             DoRecursiveAnalysis();
-            if (!String.IsNullOrEmpty(Environment.GetEnvironmentVariable("MSBUILDDEBUGSCHEDULER")))
+            if (Traits.Instance.DebugScheduler)
             {
                 DetermineExpensiveConfigs();
                 DetermineConfigsByNumberOfOccurrences();

diff --git a/src/Build/BackEnd/Node/OutOfProcNode.cs b/src/Build/BackEnd/Node/OutOfProcNode.cs
@@ -118,11 +118,6 @@ public class OutOfProcNode : INode, IBuildComponentHost, INodePacketFactory, INo
         /// </summary>
         private Exception _shutdownException;
 
-        /// <summary>
-        /// Flag indicating if we should debug communications or not.
-        /// </summary>
-        private readonly bool _debugCommunications;
-
         /// <summary>
         /// Data for the use of LegacyThreading semantics.
         /// </summary>
@@ -140,8 +135,6 @@ public OutOfProcNode()
         {
             s_isOutOfProcNode = true;
 
-            _debugCommunications = (Environment.GetEnvironmentVariable("MSBUILDDEBUGCOMM") == "1");
-
             _receivedPackets = new ConcurrentQueue<INodePacket>();
             _packetReceivedEvent = new AutoResetEvent(false);
             _shutdownEvent = new ManualResetEvent(false);

diff --git a/src/Build/Graph/ProjectGraph.cs b/src/Build/Graph/ProjectGraph.cs
@@ -10,19 +10,20 @@
 using System.Linq;
 using System.Text;
 using System.Threading;
-using Microsoft.Build.BackEnd;
 using Microsoft.Build.Evaluation;
 using Microsoft.Build.Eventing;
 using Microsoft.Build.Exceptions;
 using Microsoft.Build.Execution;
 using Microsoft.Build.Shared;
+using Microsoft.Build.Shared.Debugging;
+using Microsoft.Build.Utilities;
 
 namespace Microsoft.Build.Graph
 {
     /// <summary>
     ///     Represents a graph of evaluated projects.
     /// </summary>
-    [DebuggerDisplay(@"#roots={GraphRoots.Count}, #nodes={ProjectNodes.Count}, #entryPoints={EntryPointNodes.Count}")]
+    [DebuggerDisplay(@"{DebuggerDisplayString()}")]
     public sealed class ProjectGraph
     {
         /// <summary>
@@ -475,45 +476,73 @@ GraphConstructionMetrics EndMeasurement()
             }
         }
 
-        internal string ToDot()
+        internal string ToDot(IReadOnlyDictionary<ProjectGraphNode, ImmutableList<string>> targetsPerNode = null)
         {
             var nodeCount = 0;
-            return ToDot(node => nodeCount++.ToString());
+            return ToDot(node => nodeCount++.ToString(), targetsPerNode);
         }
 
-        internal string ToDot(Func<ProjectGraphNode, string> nodeIdProvider)
+        internal string ToDot(
+            Func<ProjectGraphNode, string> nodeIdProvider,
+            IReadOnlyDictionary<ProjectGraphNode, ImmutableList<string>> targetsPerNode = null
+        )
         {
             ErrorUtilities.VerifyThrowArgumentNull(nodeIdProvider, nameof(nodeIdProvider));
 
             var nodeIds = new ConcurrentDictionary<ProjectGraphNode, string>();
 
             var sb = new StringBuilder();
 
-            sb.Append("digraph g\n{\n\tnode [shape=box]\n");
+            sb.AppendLine($"/* {DebuggerDisplayString()} */");
+
+            sb.AppendLine("digraph g")
+                .AppendLine("{")
+                .AppendLine("\tnode [shape=box]");
 
             foreach (var node in ProjectNodes)
             {
-                var nodeId = nodeIds.GetOrAdd(node, (n, idProvider) => idProvider(n), nodeIdProvider);
+                var nodeId = GetNodeId(node);
 
                 var nodeName = Path.GetFileNameWithoutExtension(node.ProjectInstance.FullPath);
+
                 var globalPropertiesString = string.Join(
                     "<br/>",
                     node.ProjectInstance.GlobalProperties.OrderBy(kvp => kvp.Key)
                         .Select(kvp => $"{kvp.Key}={kvp.Value}"));
 
-                sb.Append('\t').Append(nodeId).Append(" [label=<").Append(nodeName).Append("<br/>").Append(globalPropertiesString).AppendLine(">]");
+                var targetListString = GetTargetListString(node);
+
+                sb.AppendLine($"\t{nodeId} [label=<{nodeName}<br/>({targetListString})<br/>{globalPropertiesString}>]");
 
                 foreach (var reference in node.ProjectReferences)
                 {
-                    var referenceId = nodeIds.GetOrAdd(reference, (n, idProvider) => idProvider(n), nodeIdProvider);
+                    var referenceId = GetNodeId(reference);
 
-                    sb.Append('\t').Append(nodeId).Append(" -> ").AppendLine(referenceId);
+                    sb.AppendLine($"\t{nodeId} -> {referenceId}");
                 }
             }
 
             sb.Append("}");
 
             return sb.ToString();
+
+            string GetNodeId(ProjectGraphNode node)
+            {
+                return nodeIds.GetOrAdd(node, (n, idProvider) => idProvider(n), nodeIdProvider);
+            }
+
+            string GetTargetListString(ProjectGraphNode node)
+            {
+                var targetListString = targetsPerNode is null
+                    ? string.Empty
+                    : string.Join(", ", targetsPerNode[node]);
+                return targetListString;
+            }
+        }
+
+        private string DebuggerDisplayString()
+        {
+            return $"#roots={GraphRoots.Count}, #nodes={ProjectNodes.Count}, #entryPoints={EntryPointNodes.Count}";
         }
 
         private static IReadOnlyCollection<ProjectGraphNode> TopologicalSort(