// Copyright Epic Games, Inc. All Rights Reserved. using EpicGames.Core; using Microsoft.Extensions.Logging; using System; using System.Collections.Generic; using System.Linq; using System.Threading; using System.Threading.Tasks; 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 /// Peak Memory Used /// Action /// Additional description of action record ExecuteResults(List LogLines, int ExitCode, TimeSpan ExecutionTime, TimeSpan ProcessorTime, long PeakMemoryUsed, LinkedAction Action, string? AdditionalDescription = null); class ActionLogger { /// /// 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; /// /// Whether to show compilation times along with worst offenders or not. /// public bool ShowCompilationTimes = false; /// /// Output logging /// public readonly ILogger Logger; /// /// Progress writer /// public readonly ProgressWriter ProgressWriter; /// /// Process group /// public readonly ManagedProcessGroup ProcessGroup = new(); /// /// The last action group printed in multi-target builds /// private string? LastGroupPrefix = null; /// /// Whether to show CPU utilization after the work is complete. /// public bool ShowCPUUtilization = false; /// /// Action to invoke when writing tool output /// private readonly Action _writeToolOutput; /// /// Flush the tool output after logging has completed /// protected readonly System.Action _flushToolOutput; /// /// Used only by the logger to track the [x,total] output /// private int _loggedCompletedActions = 0; /// /// Collection of all actions remaining to be logged /// protected readonly List _actionsToLog = new(); /// /// Task waiting to process logging /// protected Task? _actionsToLogTask = null; /// /// Timer used to collect CPU utilization /// protected Timer? _cpuUtilizationTimer; /// /// Per-second logging of cpu utilization /// protected readonly List _cpuUtilization = new(); /// /// Optional execution results (ordered like actions) /// protected readonly ExecuteResults?[] Results; public ActionLogger(int actionCount, string progressWriterText, Action writeToolOutput, System.Action flushToolOutput, ILogger logger) { Results = new ExecuteResults[actionCount]; Logger = logger; ProgressWriter = new(progressWriterText, false, logger); _writeToolOutput = writeToolOutput; _flushToolOutput = flushToolOutput; } public void AddActionToLog(ExecuteResults executeTaskResult) { int index = executeTaskResult.Action.SortIndex; Results[index] = executeTaskResult; lock (_actionsToLog) { _actionsToLog.Add(index); _actionsToLogTask ??= Task.Run(LogActions2); } } private static int s_previousLineLength = -1; /// /// Log an action that has completed /// /// Action that has completed /// Results of the action /// Number of total actions public void LogAction(LinkedAction action, ExecuteResults? executeTaskResult, int totalActions) { List? logLines = executeTaskResult?.LogLines ?? null; int exitCode = executeTaskResult?.ExitCode ?? Int32.MaxValue; TimeSpan executionTime = executeTaskResult?.ExecutionTime ?? TimeSpan.Zero; TimeSpan processorTime = executeTaskResult?.ProcessorTime ?? TimeSpan.Zero; long peakMemory = executeTaskResult?.PeakMemoryUsed ?? 0; string? 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 completedActions = Interlocked.Increment(ref _loggedCompletedActions); ProgressWriter.Write(completedActions, totalActions); // 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 && peakMemory > 0) { compilationTimes = $" (Wall: {executionTime.TotalSeconds:0.00}s CPU: {processorTime.TotalSeconds:0.00}s Mem: {StringUtils.FormatBytesString(peakMemory)})"; } else if (processorTime.Ticks > 0) { compilationTimes = $" (Wall: {executionTime.TotalSeconds:0.00}s CPU: {processorTime.TotalSeconds:0.00}s)"; } else if (peakMemory > 0) { compilationTimes = $" (Wall: {executionTime.TotalSeconds:0.00}s Mem: {StringUtils.FormatBytesString(peakMemory)})"; } 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; } } } /// /// Generate the final summary display /// public void TraceSummary(bool success) { // Wait for logging to complete Task? loggingTask = null; lock (_actionsToLog) { loggingTask = _actionsToLogTask; } loggingTask?.Wait(); _flushToolOutput(); LogLevel LogLevel = success ? LogLevel.Information : LogLevel.Debug; Logger.Log(LogLevel, ""); if (ShowCPUUtilization) { lock (_cpuUtilization) { if (_cpuUtilization.Count > 0) { Logger.Log(LogLevel, "Average CPU Utilization : {CPUPercentage:0.00}%", _cpuUtilization.Average()); } } } if (!ShowCompilationTimes) { return; } if (ProcessGroup.TotalProcessorTime.Ticks + ProcessGroup.PeakProcessMemoryUsed + ProcessGroup.PeakJobMemoryUsed > 0) { if (ProcessGroup.TotalProcessorTime.Ticks > 0) { Logger.Log(LogLevel, "Total Processor Time : {TotalSeconds:0.00}s", ProcessGroup.TotalProcessorTime.TotalSeconds); } if (ProcessGroup.PeakProcessMemoryUsed > 0) { Logger.Log(LogLevel, "Peak Process Memory Used: {PeakProcessMemory}", StringUtils.FormatBytesString(ProcessGroup.PeakProcessMemoryUsed)); } if (ProcessGroup.PeakJobMemoryUsed > 0) { Logger.Log(LogLevel, "Peak Total Memory Used : {PeakTotalMemory}", StringUtils.FormatBytesString(ProcessGroup.PeakJobMemoryUsed)); } Logger.Log(LogLevel, ""); } IEnumerable CompletedActions = Enumerable.Range(0, Results.Length) .Where(x => Results[x] != null && Results[x]!.ExecutionTime > TimeSpan.Zero && Results[x]!.ExitCode != Int32.MaxValue) .OrderByDescending(x => Results[x]!.ExecutionTime) .Take(20); if (CompletedActions.Any()) { Logger.Log(LogLevel, "Compilation Time Top {CompletedTaskCount}", CompletedActions.Count()); Logger.Log(LogLevel, ""); foreach (int Index in CompletedActions) { ExecuteResults Result = Results[Index]!; IExternalAction Action = Result.Action.Inner; string Description = $"{(Action.CommandDescription ?? Action.CommandPath.GetFileNameWithoutExtension())} {Action.StatusDescription}".Trim(); if (Result.ProcessorTime.Ticks > 0 && Result.PeakMemoryUsed > 0) { Logger.Log(LogLevel, "{Description} [ Wall Time {ExecutionTime:0.00}s / CPU Time {ProcessorTime:0.00}s / Mem {Memory} ]", Description, Result.ExecutionTime.TotalSeconds, Result.ProcessorTime.TotalSeconds, StringUtils.FormatBytesString(Result.PeakMemoryUsed)); } else 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 if (Result.PeakMemoryUsed > 0) { Logger.Log(LogLevel, "{Description} [ Time {ExecutionTime:0.00}s / Mem {Memory} ]", Description, Result.ExecutionTime.TotalSeconds, StringUtils.FormatBytesString(Result.PeakMemoryUsed)); } else { Logger.Log(LogLevel, "{Description} [ Time {ExecutionTime:0.00}s ]", Description, Result.ExecutionTime.TotalSeconds); } } Logger.Log(LogLevel, ""); } } private void LogActions2() { 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) { ExecuteResults result = Results[index]!; LogAction(result.Action, result, Results.Length); } } } } }