Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Improve debugging experience: add global switch MSBuildDebugEngine; Inject binary logger from BuildManager; print static graph as .dot file #6639

Merged
merged 19 commits into from
Jul 26, 2021
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions documentation/wiki/ChangeWaves.md
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
18 changes: 15 additions & 3 deletions src/Build.UnitTests/Graph/ProjectGraph_Tests.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down
49 changes: 41 additions & 8 deletions src/Build/BackEnd/BuildManager/BuildManager.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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;

Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -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));
Expand Down Expand Up @@ -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;
}
Expand Down Expand Up @@ -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(
Expand Down Expand Up @@ -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)
cdmihai marked this conversation as resolved.
Show resolved Hide resolved
{
return;
}

var logPath = DebugUtils.FindNextAvailableDebugFilePath($"{DebugUtils.ProcessInfoString}_ProjectGraph.dot");

File.WriteAllText(logPath, graph.ToDot(targetList));
}
}

private Dictionary<ProjectGraphNode, BuildResult> BuildGraph(
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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))
Expand Down
7 changes: 5 additions & 2 deletions src/Build/BackEnd/Components/Scheduler/Scheduler.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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;

Expand Down
3 changes: 2 additions & 1 deletion src/Build/BackEnd/Components/Scheduler/SchedulingPlan.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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
{
Expand Down Expand Up @@ -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();
Expand Down
7 changes: 0 additions & 7 deletions src/Build/BackEnd/Node/OutOfProcNode.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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>
Expand All @@ -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);
Expand Down
49 changes: 39 additions & 10 deletions src/Build/Graph/ProjectGraph.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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>
Expand Down Expand Up @@ -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(
Expand Down
Loading