// Copyright Epic Games, Inc. All Rights Reserved.
using System;
using System.Collections.Generic;
using System.Linq;
using System.Threading;
using System.Threading.Tasks;
using EpicGames.Core;
using Microsoft.CodeAnalysis;
using Microsoft.Extensions.Logging;
using UnrealBuildBase;
using UnrealBuildTool.Artifacts;
namespace UnrealBuildTool
{
///
/// Results from a run action
///
/// Console log lines
/// Process return code. Zero is assumed to be success and all other values an error.
/// Wall time
/// CPU time
/// Additional description of action
record ExecuteResults(List LogLines, int ExitCode, TimeSpan ExecutionTime, TimeSpan ProcessorTime, string? AdditionalDescription = null);
///
/// Defines the phase of execution
///
enum ActionPhase : byte
{
///
/// Check for already existing artifacts for the inputs
///
ArtifactCheck,
///
/// Compile the action
///
Compile,
}
///
/// Defines the type of the runner.
///
enum ImmediateActionQueueRunnerType : byte
{
///
/// Will be used to queue jobs as part of general requests
///
Automatic,
///
/// Will only be used for manual requests to queue jobs
///
Manual,
}
///
/// Actions are assigned a runner when they need executing
///
/// Type of the runner
/// The action phase that this step supports
/// Function to be run queue running a task
/// If true, use the action weight as a secondary limit
/// Maximum number of action actions
/// Maximum weight of actions
record ImmediateActionQueueRunner(ImmediateActionQueueRunnerType Type, ActionPhase ActionPhase, Func?> RunAction, bool UseActionWeights = false, int MaxActions = Int32.MaxValue, double MaxActionWeight = Int32.MaxValue)
{
///
/// Current number of active actions
///
public int ActiveActions = 0;
///
/// Current weight of actions
///
public double ActiveActionWeight = 0;
///
/// Used to track if the runner has already scanned the action list
/// for a given change count but found nothing to run.
///
public int LastActionChange = 0;
///
/// True if the current limits have not been reached.
///
public bool IsUnderLimits => ActiveActions < MaxActions && (!UseActionWeights || ActiveActionWeight < MaxActionWeight);
}
///
/// Helper class to manage the action queue
///
/// Running the queue can be done with a mixture of automatic and manual runners. Runners are responsible for performing
/// the work associated with an action. Automatic runners will have actions automatically queued to them up to the point
/// that any runtime limits aren't exceeded (such as maximum number of concurrent processes). Manual runners must have
/// jobs queued to them by calling TryStartOneAction or StartManyActions with the runner specified.
///
/// For example:
///
/// ParallelExecutor uses an automatic runner exclusively.
/// UBAExecutor uses an automatic runner to run jobs locally and a manual runner to run jobs remotely as processes
/// become available.
///
class ImmediateActionQueue : IDisposable
{
///
/// Number of second of no completed actions to trigger an action stall report.
/// If zero, stall reports will not be enabled.
///
[CommandLine("-ActionStallReportTime=")]
[XmlConfigFile(Category = "BuildConfiguration")]
public int ActionStallReportTime = 0;
///
/// Number of second of no completed actions to trigger to terminate the queue.
/// If zero, force termination not be enabled.
///
[CommandLine("-ActionStallTerminateTime=")]
[XmlConfigFile(Category = "BuildConfiguration")]
public int ActionStallTerminateTime = 0;
///
/// Running status of the action
///
private enum ActionStatus : byte
{
///
/// Queued waiting for execution
///
Queued,
///
/// Action is running
///
Running,
///
/// Action has successfully finished
///
Finished,
///
/// Action has finished with an error
///
Error,
}
///
/// Used to track the state of each action
///
private struct ActionState
{
///
/// Action to be executed
///
public LinkedAction Action;
///
/// Phase of the action
///
public ActionPhase Phase;
///
/// Current status of the execution
///
public ActionStatus Status;
///
/// Runner assigned to the action
///
public ImmediateActionQueueRunner? Runner;
///
/// Optional execution results
///
public ExecuteResults? Results;
///
/// Indices to prereq actions
///
public int[] PrereqActionsSortIndex;
};
///
/// State information about each action
///
private readonly ActionState[] Actions;
///
/// Output logging
///
public readonly ILogger Logger;
///
/// Total number of actions
///
public int TotalActions => Actions.Length;
///
/// Process group
///
public readonly ManagedProcessGroup ProcessGroup = new();
///
/// Source for the cancellation token
///
public readonly CancellationTokenSource CancellationTokenSource = new();
///
/// Cancellation token
///
public CancellationToken CancellationToken => CancellationTokenSource.Token;
///
/// Progress writer
///
public readonly ProgressWriter ProgressWriter;
///
/// Overall success of the action queue
///
public bool Success = true;
///
/// Whether to show compilation times along with worst offenders or not.
///
public bool ShowCompilationTimes = false;
///
/// Whether to show CPU utilization after the work is complete.
///
public bool ShowCPUUtilization = false;
///
/// Add target names for each action executed
///
public bool PrintActionTargetNames = false;
///
/// Whether to log command lines for actions being executed
///
public bool LogActionCommandLines = false;
///
/// Whether to show compilation times for each executed action
///
public bool ShowPerActionCompilationTimes = false;
///
/// Collapse non-error output lines
///
public bool CompactOutput = false;
///
/// When enabled, will stop compiling targets after a compile error occurs.
///
public bool StopCompilationAfterErrors = false;
public int CompletedActions => _completedActions;
public int CacheHitActions => _cacheHitActions;
public int CacheMissActions => _cacheMissActions;
///
/// Return true if the queue is done
///
public bool IsDone => _doneTaskSource.Task.IsCompleted;
///
/// Action that can be to notify when artifacts have been read for an action
///
public Action? OnArtifactsRead = null;
///
/// Action that can be to notify when artifacts have been missed
///
public Action? OnArtifactsMiss = null;
///
/// Collection of available runners
///
private readonly List _runners = new();
///
/// First action to start scanning for actions to run
///
private int _firstPendingAction;
///
/// Action to invoke when writing tool output
///
private readonly Action _writeToolOutput;
///
/// Flush the tool output after logging has completed
///
private readonly System.Action _flushToolOutput;
///
/// Timer used to collect CPU utilization
///
private Timer? _cpuUtilizationTimer;
///
/// Per-second logging of cpu utilization
///
private readonly List _cpuUtilization = new();
///
/// Collection of all actions remaining to be logged
///
private readonly List _actionsToLog = new();
///
/// Task waiting to process logging
///
private Task? _actionsToLogTask = null;
///
/// Used only by the logger to track the [x,total] output
///
private int _loggedCompletedActions = 0;
///
/// Tracks the number of completed actions.
///
private int _completedActions = 0;
///
/// Tracks the number of completed actions from cache hits.
///
private int _cacheHitActions = 0;
///
/// Tracks the number of unsuccessful actions from cache misses.
///
private int _cacheMissActions = 0;
///
/// Flags used to track how StartManyActions should run
///
private int _startManyFlags = 0;
///
/// Number of changes to the action list
///
private int _lastActionChange = 1;
///
/// If true, an action stall has been reported for the current change count
///
private bool _lastActionStallReported = false;
///
/// If true, the queue has been cancelled due to an action stall
///
private bool _lastActionStallCanceled = false;
///
/// Time of the last change to the action count. This is updated by the timer.
///
private DateTime _lastActionChangeTime;
///
/// Copy of _lastActionChange used to detect updates by the time.
///
private int _lastActionStallChange = 1;
///
/// Used to terminate the run with status
///
private readonly TaskCompletionSource _doneTaskSource = new();
///
/// The last action group printed in multi-target builds
///
private string? LastGroupPrefix = null;
///
/// If set, artifact cache used to retrieve previously compiled results and save new results
///
private readonly IActionArtifactCache? _actionArtifactCache;
///
/// Construct a new instance of the action queue
///
/// Collection of actions
/// If true, the artifact cache is being used
/// Max number of concurrent artifact cache tasks
/// Text to be displayed with the progress writer
/// Action to invoke when writing tool output
/// Action to invoke when flushing tool output
/// Logging interface
public ImmediateActionQueue(IEnumerable actions, IActionArtifactCache? actionArtifactCache, int maxActionArtifactCacheTasks, string progressWriterText, Action writeToolOutput, System.Action flushToolOutput, ILogger logger)
{
CommandLine.ParseArguments(Environment.GetCommandLineArgs(), this, logger);
XmlConfig.ApplyTo(this);
int count = actions.Count();
Actions = new ActionState[count];
Logger = logger;
ProgressWriter = new(progressWriterText, false, logger);
_actionArtifactCache = actionArtifactCache;
_writeToolOutput = writeToolOutput;
_flushToolOutput = flushToolOutput;
bool readArtifacts = _actionArtifactCache != null && _actionArtifactCache.EnableReads;
ActionPhase initialPhase = readArtifacts ? ActionPhase.ArtifactCheck : ActionPhase.Compile;
int index = 0;
foreach (LinkedAction action in actions)
{
action.SortIndex = index;
Actions[index++] = new ActionState
{
Action = action,
Status = ActionStatus.Queued,
Phase = action.ArtifactMode.HasFlag(ArtifactMode.Enabled) ? initialPhase : ActionPhase.Compile,
Results = null,
PrereqActionsSortIndex = action.PrerequisiteActions.Select(a => a.SortIndex).ToArray()
};
}
if (readArtifacts)
{
Func runAction(LinkedAction action)
{
return new Func(async () =>
{
ActionArtifactResult result = await _actionArtifactCache!.CompleteActionFromCacheAsync(action, CancellationToken);
if (result.Success)
{
ExecuteResults results = new(result.LogLines, result.ExitCode, TimeSpan.Zero, TimeSpan.Zero, "[Cache]");
Interlocked.Increment(ref _cacheHitActions);
OnActionCompleted(action, results.ExitCode == 0, results);
OnArtifactsRead?.Invoke(action);
}
else
{
Interlocked.Increment(ref _cacheMissActions);
OnArtifactsMiss?.Invoke(action);
RequeueAction(action);
}
});
}
_runners.Add(new(ImmediateActionQueueRunnerType.Automatic, ActionPhase.ArtifactCheck, runAction, false, maxActionArtifactCacheTasks, 0));
}
// Cancel the queue when Ctrl-C is pressed
Console.CancelKeyPress += CancelKeyPress;
}
///
/// Event handler for the Console.CancelKeyPress event
///
///
///
private void CancelKeyPress(object? sender, ConsoleCancelEventArgs e)
{
Console.CancelKeyPress -= CancelKeyPress;
if (!CancellationTokenSource.IsCancellationRequested)
{
Logger.LogWarning("Canceling actions...");
CancellationTokenSource.Cancel();
e.Cancel = true;
}
// We must do this and can't rely on that there are active processes that are cancelled causing a cascading cancel (force remote actions and no remote workers)
int completedActions = 0;
lock (Actions)
{
for (int actionIndex = _firstPendingAction; actionIndex != Actions.Length; ++actionIndex)
{
if (Actions[actionIndex].Status == ActionStatus.Queued)
{
Actions[actionIndex].Status = ActionStatus.Error;
++completedActions;
}
}
}
AddCompletedActions(completedActions);
}
///
/// Create a new automatic runner
///
/// Action to be run queue running a task
/// If true, use the action weight as a secondary limit
/// Maximum number of action actions
/// Maximum weight of actions
/// Created runner
public ImmediateActionQueueRunner CreateAutomaticRunner(Func?> runAction, bool useActionWeights, int maxActions, double maxActionWeight)
{
ImmediateActionQueueRunner runner = new(ImmediateActionQueueRunnerType.Automatic, ActionPhase.Compile, runAction, useActionWeights, maxActions, maxActionWeight);
_runners.Add(runner);
return runner;
}
///
/// Create a manual runner
///
/// Action to be run queue running a task
/// If true, use the action weight as a secondary limit
/// Maximum number of action actions
/// Maximum weight of actions
/// Created runner
public ImmediateActionQueueRunner CreateManualRunner(Func?> runAction, bool useActionWeights = false, int maxActions = Int32.MaxValue, double maxActionWeight = Double.MaxValue)
{
ImmediateActionQueueRunner runner = new(ImmediateActionQueueRunnerType.Manual, ActionPhase.Compile, runAction, useActionWeights, maxActions, maxActionWeight);
_runners.Add(runner);
return runner;
}
///
/// Start the process of running all the actions
///
public void Start()
{
if (ShowCPUUtilization || ActionStallReportTime > 0)
{
_lastActionChangeTime = DateTime.Now;
_cpuUtilizationTimer = new(x =>
{
if (ShowCPUUtilization)
{
lock (_cpuUtilization)
{
if (Utils.GetTotalCpuUtilization(out float cpuUtilization))
{
_cpuUtilization.Add(cpuUtilization);
}
}
}
if (ActionStallReportTime > 0 || ActionStallTerminateTime > 0)
{
lock (Actions)
{
// If there has been an action count change, reset the timer and enable the report again
if (_lastActionStallChange != _lastActionChange)
{
_lastActionStallChange = _lastActionChange;
_lastActionChangeTime = DateTime.Now;
_lastActionStallReported = false;
}
// Otherwise, if we haven't already generated a report, test for a timeout in seconds and generate one on timeout.
else if (ActionStallReportTime > 0 && !_lastActionStallReported && (DateTime.Now - _lastActionChangeTime).TotalSeconds > ActionStallReportTime)
{
_lastActionStallReported = true;
GenerateStallReport();
}
else if (ActionStallTerminateTime > 0 && !_lastActionStallCanceled && (DateTime.Now - _lastActionChangeTime).TotalSeconds > ActionStallTerminateTime)
{
_lastActionStallCanceled = true;
CancelStalledActions();
}
}
}
}, null, 1000, 1000);
}
Logger.LogInformation("------ Building {TotalActions} action(s) started ------", TotalActions);
}
///
/// Run the actions until complete
///
/// True if completed successfully
public async Task RunTillDone()
{
await _doneTaskSource.Task;
TraceSummary();
return Success;
}
///
/// Get the number of actions that were run, and how many succeeded or failed
///
/// Out parameter, the total number of actions
/// Out parameter, the number of successful actions
/// Out parameter, the number of failed actions
/// Out parameter, the number of cache hit actions
/// Out parameter, the number of cache miss actions
public void GetActionResultCounts(out int totalActions, out int succeededActions, out int failedActions, out int cacheHitActions, out int cacheMissActions)
{
totalActions = Actions.Length;
succeededActions = Actions.Where(x => x.Results?.ExitCode == 0).Count();
failedActions = Actions.Where(x => x.Results != null && x.Results.ExitCode != 0).Count();
cacheHitActions = _cacheHitActions;
cacheMissActions = _cacheMissActions;
}
///
/// Return an enumeration of ready compile tasks. This is not executed under a lock and
/// does not modify the state of any actions.
///
/// Enumerations of all ready to compile actions.
public IEnumerable EnumerateReadyToCompileActions()
{
for (int actionIndex = _firstPendingAction; actionIndex != Actions.Length; ++actionIndex)
{
ActionState actionState = Actions[actionIndex];
if (actionState.Status == ActionStatus.Queued &&
actionState.Phase == ActionPhase.Compile &&
GetActionReadyState(actionState) == ActionReadyState.Ready)
{
yield return actionState.Action;
}
}
}
///
/// Try to start one action
///
/// If specified, tasks will only be queued to this runner. Otherwise all manual runners will be used.
/// True if an action was run, false if not
public bool TryStartOneAction(ImmediateActionQueueRunner? runner = null)
{
// Loop until we have an action or no completed actions (i.e. no propagated errors)
for (; ; )
{
bool hasCanceled = false;
// Try to get the next action
Func? runAction = null;
LinkedAction? action = null;
int completedActions = 0;
lock (Actions)
{
hasCanceled = CancellationTokenSource.IsCancellationRequested;
// Don't bother if we have been canceled or the specified running has already failed to find
// anything at the given change number.
if (!hasCanceled && (runner == null || runner.LastActionChange != _lastActionChange))
{
// Try to get an action
(runAction, action, completedActions) = TryStartOneActionInternal(runner);
// If we have completed actions (i.e. error propagations), then increment the change counter
if (completedActions != 0)
{
_lastActionChange++;
}
// Otherwise if nothing was found, remember that we have already scanned at this change.
else if ((runAction == null || action == null) && runner != null)
{
runner.LastActionChange = _lastActionChange;
}
}
}
// If we have an action, run it and account for any completed actions
if (runAction != null && action != null)
{
if (runner != null && runner.Type == ImmediateActionQueueRunnerType.Manual)
{
try
{
runAction().Wait(CancellationToken);
}
catch (Exception ex)
{
HandleException(action, ex);
}
}
else
{
Task.Factory.StartNew(() =>
{
try
{
runAction().Wait(CancellationToken);
}
catch (Exception ex)
{
HandleException(action, ex);
}
}, CancellationToken, TaskCreationOptions.LongRunning | TaskCreationOptions.PreferFairness, TaskScheduler.Default);
}
AddCompletedActions(completedActions);
return true;
}
// If we have no completed actions, then we need to check for a stall
if (completedActions == 0)
{
// We found nothing, check to see if we have no active running tasks and no manual runners.
// If we don't, then it is assumed we can't queue any more work.
bool prematureDone = true;
foreach (ImmediateActionQueueRunner tryRunner in _runners)
{
if ((tryRunner.Type == ImmediateActionQueueRunnerType.Manual && !hasCanceled) || tryRunner.ActiveActions != 0)
{
prematureDone = false;
break;
}
}
if (prematureDone)
{
AddCompletedActions(Int32.MaxValue);
}
return false;
}
// Otherwise add the completed actions and test again for the possibility that errors still need propagating
AddCompletedActions(completedActions);
}
}
///
/// Handle an exception running a task
///
/// Action that has been run
/// Thrown exception
void HandleException(LinkedAction action, Exception ex)
{
if (ex is AggregateException aggregateEx)
{
if (aggregateEx.InnerException != null)
{
HandleException(action, aggregateEx.InnerException);
}
else
{
ExecuteResults results = new(new List(), Int32.MaxValue, TimeSpan.Zero, TimeSpan.Zero);
OnActionCompleted(action, false, results);
}
}
else if (ex is OperationCanceledException)
{
ExecuteResults results = new(new List(), Int32.MaxValue, TimeSpan.Zero, TimeSpan.Zero);
OnActionCompleted(action, false, results);
}
else
{
List text = new()
{
ExceptionUtils.FormatException(ex),
ExceptionUtils.FormatExceptionDetails(ex),
};
ExecuteResults results = new(text, Int32.MaxValue, TimeSpan.Zero, TimeSpan.Zero);
OnActionCompleted(action, false, results);
}
}
///
/// Try to start one action.
///
/// If specified, tasks will only be queued to this runner. Otherwise all manual runners will be used.
/// Action to be run if something was queued and the number of completed actions
public (Func?, LinkedAction?, int) TryStartOneActionInternal(ImmediateActionQueueRunner? runner = null)
{
int completedActions = 0;
// If we are starting deeper in the action collection, then never set the first pending action location
bool foundFirstPending = false;
// Loop through the items
for (int actionIndex = _firstPendingAction; actionIndex != Actions.Length; ++actionIndex)
{
// If the action has already reached the compilation state, then just ignore
if (Actions[actionIndex].Status != ActionStatus.Queued)
{
continue;
}
// If needed, update the first valid slot for searching for actions to run
if (!foundFirstPending)
{
_firstPendingAction = actionIndex;
foundFirstPending = true;
}
// Based on the ready state, use this action or mark as an error
switch (GetActionReadyState(Actions[actionIndex]))
{
case ActionReadyState.NotReady:
break;
case ActionReadyState.Error:
Actions[actionIndex].Status = ActionStatus.Error;
Actions[actionIndex].Phase = ActionPhase.Compile;
completedActions++;
break;
case ActionReadyState.Ready:
ImmediateActionQueueRunner? selectedRunner = null;
Func? runAction = null;
if (runner != null)
{
if (runner.IsUnderLimits && runner.ActionPhase == Actions[actionIndex].Phase)
{
runAction = runner.RunAction(Actions[actionIndex].Action);
if (runAction != null)
{
selectedRunner = runner;
}
}
}
else
{
foreach (ImmediateActionQueueRunner tryRunner in _runners)
{
if (tryRunner.Type == ImmediateActionQueueRunnerType.Automatic &&
tryRunner.IsUnderLimits && tryRunner.ActionPhase == Actions[actionIndex].Phase)
{
runAction = tryRunner.RunAction(Actions[actionIndex].Action);
if (runAction != null)
{
selectedRunner = tryRunner;
break;
}
}
}
}
if (runAction != null && selectedRunner != null)
{
Actions[actionIndex].Status = ActionStatus.Running;
Actions[actionIndex].Runner = selectedRunner;
selectedRunner.ActiveActions++;
selectedRunner.ActiveActionWeight += Actions[actionIndex].Action.Weight;
return (runAction, Actions[actionIndex].Action, completedActions);
}
break;
default:
throw new ApplicationException("Unexpected action ready state");
}
}
return (null, null, completedActions);
}
///
/// Start as many actions as possible.
///
/// If specified, all actions will be limited to the runner
public void StartManyActions(ImmediateActionQueueRunner? runner = null)
{
const int Running = 1 << 1;
const int ScanRequested = 1 << 0;
// If both flags were clear, I need to start running actions
int old = Interlocked.Or(ref _startManyFlags, Running | ScanRequested);
if (old == 0)
{
for (; ; )
{
// Clear the changed flag since we are about to scan
Interlocked.And(ref _startManyFlags, Running);
// If nothing started
if (!TryStartOneAction(runner))
{
// If we only have the running flag (nothing new changed), then exit
if (Interlocked.CompareExchange(ref _startManyFlags, 0, Running) == Running)
{
return;
}
}
}
}
}
///
/// Dispose the object
///
public void Dispose()
{
Console.CancelKeyPress -= CancelKeyPress;
_cpuUtilizationTimer?.Dispose();
_cpuUtilizationTimer = null;
CancellationTokenSource.Dispose();
ProcessGroup.Dispose();
ProgressWriter.Dispose();
}
///
/// Reset the status of the given action to the queued state.
///
/// Action being re-queued
public void RequeueAction(LinkedAction action)
{
SetActionState(action, ActionStatus.Queued, null);
}
///
/// Notify the system that an action has been completed.
///
/// Action being completed
/// If true, the action succeeded or false if it failed.
/// Optional execution results
public void OnActionCompleted(LinkedAction action, bool success, ExecuteResults? results)
{
// Delete produced items on error if requested
if (action.bDeleteProducedItemsOnError && (results?.ExitCode ?? 0) != 0)
{
foreach (FileItem output in action.ProducedItems.Distinct().Where(x => FileReference.Exists(x.Location)))
{
FileReference.Delete(output.Location);
}
}
// On success invalidate the file info for all the produced items. This needs to be
// done so the artifact system sees any compiled files.
if (success)
{
foreach (FileItem output in action.ProducedItems)
{
output.ResetCachedInfo();
}
}
SetActionState(action, success ? ActionStatus.Finished : ActionStatus.Error, results);
}
///
/// Set the new state of an action. Can only set state to Queued, Finished, or Error
///
/// Action being set
/// Status to set
/// Optional results
///
private void SetActionState(LinkedAction action, ActionStatus status, ExecuteResults? results)
{
int actionIndex = action.SortIndex;
int completedActions = 0;
// Update the actions data
lock (Actions)
{
ImmediateActionQueueRunner runner = Actions[actionIndex].Runner ?? throw new BuildException("Attempting to update action state but runner isn't set");
runner.ActiveActions--;
runner.ActiveActionWeight -= Actions[actionIndex].Action.Weight;
// Use to track that action states have changed
_lastActionChange++;
// If we are doing an artifact check, then move to compile phase
bool wasArtifactCheck = false;
if (Actions[actionIndex].Phase == ActionPhase.ArtifactCheck)
{
wasArtifactCheck = true;
Actions[actionIndex].Phase = ActionPhase.Compile;
if (status != ActionStatus.Finished && (results?.ExitCode ?? 0) == 0)
{
status = ActionStatus.Queued;
}
}
Actions[actionIndex].Status = status;
Actions[actionIndex].Runner = null;
if (results != null)
{
Actions[actionIndex].Results = results;
}
// Add the action to the logging queue
if (status != ActionStatus.Queued)
{
lock (_actionsToLog)
{
_actionsToLog.Add(action.SortIndex);
_actionsToLogTask ??= Task.Run(LogActions);
}
}
switch (status)
{
case ActionStatus.Queued:
if (actionIndex < _firstPendingAction)
{
_firstPendingAction = actionIndex;
}
break;
case ActionStatus.Finished:
// Notify the artifact handler of the action completing. We don't wait on the resulting task. The
// cache is required to remember any pending saves and a final call to Flush will wait for everything to complete.
if (!wasArtifactCheck)
{
_actionArtifactCache?.ActionCompleteAsync(action, CancellationToken);
}
completedActions = 1;
break;
case ActionStatus.Error:
Success = false;
completedActions = 1;
break;
default:
throw new BuildException("Unexpected action status set");
}
}
// Outside of lock, update the completed actions
AddCompletedActions(completedActions);
// Since something has been completed or returned to the queue, try to run actions again
StartManyActions();
}
///
/// Add the number of completed actions and signal done if all actions complete.
///
/// Number of completed actions to add. If int.MaxValue, then the number is immediately set to total actions
private void AddCompletedActions(int count)
{
if (count == 0)
{
// do nothing
}
else if (count != Int32.MaxValue)
{
if (Interlocked.Add(ref _completedActions, count) == TotalActions)
{
_doneTaskSource.SetResult();
}
}
else
{
if (Interlocked.Exchange(ref _completedActions, TotalActions) != TotalActions)
{
_doneTaskSource.SetResult();
}
}
}
///
/// Returns the number of queued actions left (including queued actions that will do artifact check first)
/// Note, this method is lockless and will not always return accurate count
///
/// Optional function to filter out actions. Return false if action should not be included
public uint GetQueuedActionsCount(Func? filterFunc = null)
{
uint count = 0;
for (int actionIndex = _firstPendingAction; actionIndex != Actions.Length; ++actionIndex)
{
if (Actions[actionIndex].Status != ActionStatus.Queued)
{
continue;
}
if (filterFunc != null && !filterFunc(Actions[actionIndex].Action))
{
continue;
}
++count;
}
return count;
}
///
/// Purge the pending logging actions
///
private void LogActions()
{
for (; ; )
{
int[]? actionsToLog = null;
lock (_actionsToLog)
{
if (_actionsToLog.Count == 0)
{
_actionsToLogTask = null;
}
else
{
actionsToLog = _actionsToLog.ToArray();
_actionsToLog.Clear();
}
}
if (actionsToLog == null)
{
return;
}
foreach (int index in actionsToLog)
{
LogAction(Actions[index].Action, Actions[index].Results);
}
}
}
private static int s_previousLineLength = -1;
///
/// Log an action that has completed
///
/// Action that has completed
/// Results of the action
private void LogAction(LinkedAction action, ExecuteResults? executeTaskResult)
{
List? logLines = null;
int exitCode = Int32.MaxValue;
TimeSpan executionTime = TimeSpan.Zero;
TimeSpan processorTime = TimeSpan.Zero;
string? additionalDescription = null;
if (executeTaskResult != null)
{
logLines = executeTaskResult.LogLines;
exitCode = executeTaskResult.ExitCode;
executionTime = executeTaskResult.ExecutionTime;
processorTime = executeTaskResult.ProcessorTime;
additionalDescription = executeTaskResult.AdditionalDescription;
}
// Write it to the log
string description = String.Empty;
if (action.bShouldOutputStatusDescription || (logLines != null && logLines.Count == 0))
{
description = $"{(action.CommandDescription ?? action.CommandPath.GetFileNameWithoutExtension())} {action.StatusDescription}".Trim();
}
else if (logLines != null && logLines.Count > 0)
{
description = $"{(action.CommandDescription ?? action.CommandPath.GetFileNameWithoutExtension())} {logLines[0]}".Trim();
}
if (!String.IsNullOrEmpty(additionalDescription))
{
description = $"{description} {additionalDescription}";
}
lock (ProgressWriter)
{
int totalActions = Actions.Length;
int completedActions = Interlocked.Increment(ref _loggedCompletedActions);
ProgressWriter.Write(completedActions, Actions.Length);
// Canceled
if (exitCode == Int32.MaxValue)
{
//Logger.LogInformation("[{CompletedActions}/{TotalActions}] {Description} canceled", completedActions, totalActions, description);
return;
}
string targetDetails = "";
TargetDescriptor? target = action.Target;
if (PrintActionTargetNames && target != null)
{
targetDetails = $"[{target.Name} {target.Platform} {target.Configuration}]";
}
if (LogActionCommandLines)
{
Logger.LogDebug("[{CompletedActions}/{TotalActions}]{TargetDetails} Command: {CommandPath} {CommandArguments}", completedActions, totalActions, targetDetails, action.CommandPath, action.CommandArguments);
}
string compilationTimes = "";
if (ShowPerActionCompilationTimes)
{
if (processorTime.Ticks > 0)
{
compilationTimes = $" (Wall: {executionTime.TotalSeconds:0.00}s CPU: {processorTime.TotalSeconds:0.00}s)";
}
else
{
compilationTimes = $" (Wall: {executionTime.TotalSeconds:0.00}s)";
}
}
string message = ($"[{completedActions}/{totalActions}]{targetDetails}{compilationTimes} {description}");
if (CompactOutput)
{
if (s_previousLineLength > 0)
{
// move the cursor to the far left position, one line back
Console.CursorLeft = 0;
Console.CursorTop -= 1;
// clear the line
Console.Write("".PadRight(s_previousLineLength));
// move the cursor back to the left, so output is written to the desired location
Console.CursorLeft = 0;
}
}
else
{
// If the action group has changed for a multi target build, write it to the log
if (action.GroupNames.Count > 0)
{
string ActionGroup = $"** For {String.Join(" + ", action.GroupNames)} **";
if (!ActionGroup.Equals(LastGroupPrefix, StringComparison.Ordinal))
{
LastGroupPrefix = ActionGroup;
_writeToolOutput(ActionGroup);
}
}
}
s_previousLineLength = message.Length;
_writeToolOutput(message);
if (logLines != null && action.bShouldOutputLog)
{
foreach (string Line in logLines.Skip(action.bShouldOutputStatusDescription ? 0 : 1))
{
// suppress library creation messages when writing compact output
if (CompactOutput && Line.StartsWith(" Creating library ", StringComparison.OrdinalIgnoreCase) && Line.EndsWith(".exp", StringComparison.OrdinalIgnoreCase))
{
continue;
}
_writeToolOutput(Line);
// Prevent overwriting of logged lines
s_previousLineLength = -1;
}
}
if (exitCode != 0)
{
string exitCodeStr = String.Empty;
if ((uint)exitCode == 0xC0000005)
{
exitCodeStr = "(Access violation)";
}
else if ((uint)exitCode == 0xC0000409)
{
exitCodeStr = "(Stack buffer overflow)";
}
// If we have an error code but no output, chances are the tool crashed. Generate more detailed information to let the
// user know something went wrong.
if (logLines == null || logLines.Count <= (action.bShouldOutputStatusDescription ? 0 : 1))
{
Logger.LogError("{TargetDetails} {Description}: Exited with error code {ExitCode} {ExitCodeStr}. The build will fail.", targetDetails, description, exitCode, exitCodeStr);
Logger.LogInformation("{TargetDetails} {Description}: WorkingDirectory {WorkingDirectory}", targetDetails, description, action.WorkingDirectory);
Logger.LogInformation("{TargetDetails} {Description}: {CommandPath} {CommandArguments}", targetDetails, description, action.CommandPath, action.CommandArguments);
}
// Always print error details to to the log file
else
{
Logger.LogDebug("{TargetDetails} {Description}: Exited with error code {ExitCode} {ExitCodeStr}. The build will fail.", targetDetails, description, exitCode, exitCodeStr);
Logger.LogDebug("{TargetDetails} {Description}: WorkingDirectory {WorkingDirectory}", targetDetails, description, action.WorkingDirectory);
Logger.LogDebug("{TargetDetails} {Description}: {CommandPath} {CommandArguments}", targetDetails, description, action.CommandPath, action.CommandArguments);
}
// prevent overwriting of error text
s_previousLineLength = -1;
// Cancel all other pending tasks
if (StopCompilationAfterErrors)
{
CancellationTokenSource.Cancel();
}
}
}
}
///
/// Generate the final summary display
///
private void TraceSummary()
{
// Wait for logging to complete
Task? loggingTask = null;
lock (_actionsToLog)
{
loggingTask = _actionsToLogTask;
}
loggingTask?.Wait();
_flushToolOutput();
LogLevel LogLevel = Success ? LogLevel.Information : LogLevel.Debug;
if (ShowCPUUtilization)
{
lock (_cpuUtilization)
{
if (_cpuUtilization.Count > 0)
{
Logger.Log(LogLevel, "");
Logger.Log(LogLevel, "Average CPU Utilization: {CPUPercentage}%", (int)(_cpuUtilization.Average()));
}
}
}
if (!ShowCompilationTimes)
{
return;
}
Logger.Log(LogLevel, "");
if (ProcessGroup.TotalProcessorTime.Ticks > 0)
{
Logger.Log(LogLevel, "Total CPU Time: {TotalSeconds} s", ProcessGroup.TotalProcessorTime.TotalSeconds);
Logger.Log(LogLevel, "");
}
IEnumerable CompletedActions = Enumerable.Range(0, Actions.Length)
.Where(x => Actions[x].Results != null && Actions[x].Results!.ExecutionTime > TimeSpan.Zero && Actions[x].Results!.ExitCode != Int32.MaxValue)
.OrderByDescending(x => Actions[x].Results!.ExecutionTime)
.Take(20);
if (CompletedActions.Any())
{
Logger.Log(LogLevel, "Compilation Time Top {CompletedTaskCount}", CompletedActions.Count());
Logger.Log(LogLevel, "");
foreach (int Index in CompletedActions)
{
IExternalAction Action = Actions[Index].Action.Inner;
ExecuteResults Result = Actions[Index].Results!;
string Description = $"{(Action.CommandDescription ?? Action.CommandPath.GetFileNameWithoutExtension())} {Action.StatusDescription}".Trim();
if (Result.ProcessorTime.Ticks > 0)
{
Logger.Log(LogLevel, "{Description} [ Wall Time {ExecutionTime:0.00} s / CPU Time {ProcessorTime:0.00} s ]", Description, Result.ExecutionTime.TotalSeconds, Result.ProcessorTime.TotalSeconds);
}
else
{
Logger.Log(LogLevel, "{Description} [ Time {ExecutionTime:0.00} s ]", Description, Result.ExecutionTime.TotalSeconds);
}
}
Logger.Log(LogLevel, "");
}
}
private enum ActionReadyState
{
NotReady,
Error,
Ready,
}
///
/// Get the ready state of an action
///
/// Action in question
/// Action ready state
private ActionReadyState GetActionReadyState(ActionState action)
{
foreach (int prereqIndex in action.PrereqActionsSortIndex)
{
// To avoid doing artifact checks on actions that might need compiling,
// we first make sure the action is in the compile phase
if (Actions[prereqIndex].Phase != ActionPhase.Compile)
{
return ActionReadyState.NotReady;
}
// Respect the compile status of the action
switch (Actions[prereqIndex].Status)
{
case ActionStatus.Finished:
continue;
case ActionStatus.Error:
return ActionReadyState.Error;
default:
return ActionReadyState.NotReady;
}
}
return ActionReadyState.Ready;
}
private void GenerateStallReport()
{
Logger.LogInformation("Action stall detected:");
foreach (ImmediateActionQueueRunner runner in _runners)
{
Logger.LogInformation("Runner Type: {Type}, Running Actions: {ActionCount}", runner.Type.ToString(), runner.ActiveActions);
if (runner.ActiveActions > 0)
{
int count = 0;
foreach (ActionState state in Actions)
{
if (state.Runner == runner && state.Status == ActionStatus.Running)
{
string description = $"{(state.Action.CommandDescription ?? state.Action.CommandPath.GetFileNameWithoutExtension())} {state.Action.StatusDescription}".Trim();
Logger.LogInformation(" Action[{Index}]: {Description}", count++, description);
}
}
}
}
{
int queued = 0;
int running = 0;
int error = 0;
int finished = 0;
foreach (ActionState state in Actions)
{
switch (state.Status)
{
case ActionStatus.Error:
error++;
break;
case ActionStatus.Finished:
finished++;
break;
case ActionStatus.Queued:
queued++;
break;
case ActionStatus.Running:
running++;
break;
}
}
Logger.LogInformation("Queue Counts: Queued = {Queued}, Running = {Running}, Finished = {Finished}, Error = {Error}", queued, running, finished, error);
}
}
private void CancelStalledActions()
{
GenerateStallReport();
Logger.LogInformation("Action stall terminate time exceeded, canceling remaining actions...");
CancellationTokenSource.Cancel();
}
}
}