/// <remarks>
/// Parses and constructs a BuildXLStats object.
/// </remarks>
public static bool TryLoadStatsFile(string statsFile, out BuildXLStats buildXlStats)
{
buildXlStats = null;
var stats = new Dictionary <string, long>(StringComparer.OrdinalIgnoreCase);
try
{
using (var stream = new FileStream(statsFile, FileMode.Open, FileAccess.Read, FileShare.ReadWrite))
using (var reader = new StreamReader(stream))
{
while (!reader.EndOfStream)
{
var line = reader.ReadLine();
var parts = line.Split('=');
if (parts.Length != 2)
{
Console.Error.WriteLine("Unexpected stats line: " + line);
return(false);
}
long value;
if (!long.TryParse(parts[1], out value))
{
Console.Error.WriteLine("Unexpected stats line. After equals is not an integer:" + line);
return(false);
}
if (string.IsNullOrEmpty(parts[0]))
{
Console.Error.WriteLine("Unexpected stats line. No Key before '=':" + line);
return(false);
}
stats[parts[0]] = value;
}
}
}
catch (IOException e)
{
Console.Error.WriteLine("Error reading stats file: " + statsFile + ": " + e.Message);
return(false);
}
catch (UnauthorizedAccessException e)
{
Console.Error.WriteLine("Error reading stats file: " + statsFile + ": " + e.Message);
return(false);
}
buildXlStats = new BuildXLStats(stats);
return(true);
}
public override int Analyze()
{
BuildXLStats stats;
if (!BuildXLStats.TryLoadStatsFile(m_statsFile, out stats))
{
return(1);
}
var main = new XElement(
"div",
m_html.CreateBlock(
"Number fo Pips",
m_html.CreateRow("Total", CachedGraph.PipTable.Count),
GetEnumValues <PipType>().Select(pipType => m_html.CreateRow(pipType.ToString(), CachedGraph.PipGraph.RetrievePipReferencesOfType(pipType).Count()))),
m_html.CreateBlock(
"Overall execution times",
m_html.CreateRow("TimeToFirstPip", stats.GetMiliSeconds("TimeToFirstPipSyntheticMs")),
m_html.CreateRow(" - Cache init", stats.GetMiliSeconds("CacheInitialization.DurationMs")),
m_html.CreateRow(" - Parse config", stats.GetMiliSeconds("ParseConfigFiles.DurationMs")),
m_html.CreateRow(" - GraphCache check", stats.GetMiliSeconds("GraphCacheReuseCheck.DurationMs")),
m_html.CreateRow(" - Graph construction", "..."),
m_html.CreateRow(" - Filter & Schedule", stats.GetMiliSeconds("ApplyFilterAndScheduleReadyNodes.DurationMs")),
m_html.CreateRow("Execute", stats.GetMiliSeconds("TimeToEngineRunCompleteMs") - stats.GetMiliSeconds("TimeToFirstPipSyntheticMs")),
m_html.CreateRow(" - HashSourceFile", stats.GetMiliSeconds("PipExecution.HashSourceFileDurationMs")),
m_html.CreateRow(" - CopyFile", stats.GetMiliSeconds("PipExecution.CopyFileDurationMs")),
m_html.CreateRow(" - WriteFile", stats.GetMiliSeconds("PipExecution.WriteFileDurationMs")),
m_html.CreateRow(" - Process", stats.GetMiliSeconds("PipExecution.ProcessDurationMs")),
m_html.CreateRow(" - -- HashDeps", stats.GetMiliSeconds("PipExecution.HashProcessDependenciesDurationMs")),
m_html.CreateRow(" - -- CacheCheck", stats.GetMiliSeconds("PipExecution.CheckProcessRunnableFromCacheDurationMs")),
m_html.CreateRow(" - -- Execution", stats.GetMiliSeconds("PipExecution.ExecuteProcessDurationMs")),
m_html.CreateRow(" - -- ProcessOutputs", stats.GetMiliSeconds("PipExecution.ProcessOutputsDurationMs")),
m_html.CreateRow(" - -- Continue", stats.GetMiliSeconds("OnPipCompletedDurationMs")),
m_html.CreateRow(" - HashSourceFile", stats.GetMiliSeconds("PipExecution.HashSourceFileDurationMs")),
m_html.CreateRow(" - HashSourceFile", stats.GetMiliSeconds("PipExecution.HashSourceFileDurationMs")),
m_html.CreateRow("Red flags", "..."),
m_html.CreateRow(" - ProcessPipCacheHits", stats["ProcessPipCacheHits"]),
m_html.CreateRow(" - PipsFailed", stats["PipsFailed"])),
m_html.CreateBlock("UsageStatistics", RenderUsageStatistics(stats)));
var doc = m_html.CreatePage("Performance Summary ", main);
Directory.CreateDirectory(Path.GetDirectoryName(m_outputFilePath));
doc.Save(m_outputFilePath);
return(0);
}
private XElement RenderUsageStatistics(BuildXLStats stats)
{
var actualUsage = new ActiveWorkerTracker();
foreach (var kv in m_pipExecutionPerf.Values)
{
actualUsage.AddEntry(kv.ExecutionStart - m_firstPip, kv.ExecutionStop - m_firstPip);
}
int numberOfPips = CachedGraph.PipTable.Count + 1; // pipIds start at 1;
Console.WriteLine("Processing nr of pipzies: " + numberOfPips);
var refCounts = new int[numberOfPips];
var startTime = new TimeSpan[numberOfPips];
var startTick = new int[numberOfPips];
var duration = new TimeSpan[numberOfPips];
var maxSimulationTick = 0;
var maxSimulationTime = TimeSpan.Zero;
var minActualStart = DateTime.MaxValue;
var maxActualStop = DateTime.MinValue;
var readyQueue = new Queue <PipId>();
// build RunState
foreach (var pipId in CachedGraph.PipTable.Keys)
{
var pipIdx = pipId.Value;
int incommingCount = CachedGraph.DirectedGraph.GetIncomingEdgesCount(pipId.ToNodeId());
refCounts[pipIdx] = incommingCount;
if (incommingCount == 0)
{
startTime[pipIdx] = TimeSpan.Zero;
startTick[pipIdx] = 0;
readyQueue.Enqueue(pipId);
}
if (m_pipExecutionPerf.ContainsKey(pipId))
{
var executionStart = m_pipExecutionPerf[pipId].ExecutionStart;
var executionStop = m_pipExecutionPerf[pipId].ExecutionStop;
minActualStart = minActualStart < executionStart ? minActualStart : executionStart;
maxActualStop = maxActualStop > executionStop ? maxActualStop : executionStop;
duration[pipIdx] = executionStop - executionStart;
}
else
{
duration[pipIdx] = TimeSpan.Zero;
}
}
while (readyQueue.Count != 0)
{
var pipId = readyQueue.Dequeue();
var pipEndTime = startTime[pipId.Value] + duration[pipId.Value];
var pipEndTick = startTick[pipId.Value] + 1;
maxSimulationTick = Math.Max(maxSimulationTick, pipEndTick);
maxSimulationTime = maxSimulationTime > pipEndTime ? maxSimulationTime : pipEndTime;
foreach (var dependent in CachedGraph.PipGraph.RetrievePipReferenceImmediateDependents(pipId))
{
var depId = dependent.PipId;
var depIdx = depId.Value;
var curCount = refCounts[depIdx];
Contract.Assert(curCount > 0);
curCount--;
refCounts[depIdx] = curCount;
if (curCount == 0)
{
startTime[depIdx] = pipEndTime;
startTick[depIdx] = pipEndTick;
readyQueue.Enqueue(depId);
}
}
}
var simulateWithActualTime = new ActiveWorkerTracker();
var simulateWithEqualTime = new ActiveWorkerTracker();
for (int i = 1; i < numberOfPips; i++)
{
if (CachedGraph.PipTable.GetPipType(new PipId((uint)i)) != PipType.Process)
{
// Skip pips other than HashSourceFile pips
continue;
}
simulateWithActualTime.AddEntry(startTime[i], startTime[i] + duration[i]);
simulateWithEqualTime.AddEntry(TimeSpan.FromSeconds(startTick[i]), TimeSpan.FromSeconds(startTick[i] + 1));
}
int graphSize = 1000;
var warnings = new XElement("div");
long?processPipCacheHits = stats.GetValue("ProcessPipCacheHits");
if (processPipCacheHits > 0)
{
warnings.Add(new XElement("div", new XAttribute("class", "warning"), $"Warning: This build had '{stats["ProcessPipCacheHits"]}' cache hits. Therefore the following graphs are not reliable for full graph analysis as those pips have a much shorter execution time than normal if they were cache hits. You can run the build with '/incremental-' to force cache misses."));
}
long?pipsFailed = stats.GetValue("PipsFailed");
if (pipsFailed > 0)
{
warnings.Add(new XElement("div", new XAttribute("class", "warning"), $"Warning: This build had '{stats["PipsFailed"]}' failed pips. Therefore the following graphs are not complete for analysis. The failed pips as well as the pips that transitively depend on them will not be visible nor measured in these graphs "));
}
return(new XElement(
"div",
warnings,
CreateGraph(
actualUsage,
durationTime: maxActualStop - minActualStart,
durationDepth: null,
graphSize: graphSize,
title: "Actual start times & durations"),
CreateGraph(
simulateWithActualTime,
durationTime: maxSimulationTime,
durationDepth: maxSimulationTick,
graphSize: graphSize,
title: "Simulate with infinite resources and actual durations"),
CreateGraph(
simulateWithEqualTime,
durationTime: null,
durationDepth: maxSimulationTick,
graphSize: graphSize,
title: "Simulate with infinite resources and equal cost per pip")));
}
