// 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(); } } }