From 3395128aee0bac96d105ad789232aa773a008437 Mon Sep 17 00:00:00 2001 From: Eduardo Villalpando Mello Date: Tue, 24 Jan 2023 01:41:10 -0800 Subject: [PATCH] [FancyLogger] Improve render performance (#8331) * Improved performance Added indicators to buffer and project nodes to avoid unnecessary rerenders and operations Delimited foreach loop in FancyLoggerBuffer.Render() to avoid unnecessary operations Text is logged to the console all at once Reduced render time significantly * Addressed review comments * Improved ANSIWrap Added static Regex, used spans instead of strings, used Regex.Match(string, position) * Add comments --- src/Build/Logging/FancyLogger/ANSIBuilder.cs | 23 ++-- src/Build/Logging/FancyLogger/FancyLogger.cs | 60 ++++++++-- .../Logging/FancyLogger/FancyLoggerBuffer.cs | 106 +++++++----------- .../FancyLogger/FancyLoggerMessageNode.cs | 3 +- .../FancyLogger/FancyLoggerProjectNode.cs | 22 ++-- 5 files changed, 122 insertions(+), 92 deletions(-) diff --git a/src/Build/Logging/FancyLogger/ANSIBuilder.cs b/src/Build/Logging/FancyLogger/ANSIBuilder.cs index 6034676c3cc..4bd20820b46 100644 --- a/src/Build/Logging/FancyLogger/ANSIBuilder.cs +++ b/src/Build/Logging/FancyLogger/ANSIBuilder.cs @@ -11,16 +11,24 @@ namespace Microsoft.Build.Logging.FancyLogger internal static class ANSIBuilder { public static string ANSIRegex = @"\x1b(?:[@-Z\-_]|\[[0-?]*[ -\/]*[@-~])"; + // TODO: This should replace ANSIRegex once FancyLogger's API is internal + public static Regex ANSIRegexRegex = new Regex(ANSIRegex); public static string ANSIRemove(string text) { - return Regex.Replace(text, ANSIRegex, ""); + return ANSIRegexRegex.Replace(text, ""); } + // TODO: This should be an optional parameter for ANSIBreakpoint(string text, int positioon, int initialPosition = 0) public static int ANSIBreakpoint(string text, int position) + { + return ANSIBreakpoint(text, position, 0); + } + public static int ANSIBreakpoint(string text, int position, int initialPosition) { if (position >= text.Length) return text.Length; int nonAnsiIndex = 0; - Match nextMatch = Regex.Match(text, ANSIRegex); + // Match nextMatch = Regex.Match(text, ANSIRegex); + Match nextMatch = ANSIRegexRegex.Match(text, initialPosition); int i = 0; while (i < text.Length && nonAnsiIndex != position) { @@ -39,15 +47,16 @@ public static int ANSIBreakpoint(string text, int position) public static List ANSIWrap(string text, int position) { + ReadOnlySpan textSpan = text.AsSpan(); List result = new(); int breakpoint = ANSIBreakpoint(text, position); - while (text.Length > breakpoint) + while (textSpan.Length > breakpoint) { - result.Add(text.Substring(0, breakpoint)); - text = text.Substring(breakpoint); - breakpoint = ANSIBreakpoint(text, position); + result.Add(textSpan.Slice(0, breakpoint).ToString()); + textSpan = textSpan.Slice(breakpoint); + breakpoint = ANSIBreakpoint(text, position, breakpoint); } - result.Add(text); + result.Add(textSpan.ToString()); return result; } diff --git a/src/Build/Logging/FancyLogger/FancyLogger.cs b/src/Build/Logging/FancyLogger/FancyLogger.cs index d6e23e760f0..a364ee13cb9 100644 --- a/src/Build/Logging/FancyLogger/FancyLogger.cs +++ b/src/Build/Logging/FancyLogger/FancyLogger.cs @@ -3,6 +3,7 @@ using System; using System.Collections.Generic; +using System.Threading.Tasks; using Microsoft.Build.Framework; namespace Microsoft.Build.Logging.FancyLogger @@ -44,11 +45,54 @@ public void Initialize(IEventSource eventSource) eventSource.ErrorRaised += new BuildErrorEventHandler(eventSource_ErrorRaised); // Cancelled Console.CancelKeyPress += new ConsoleCancelEventHandler(console_CancelKeyPressed); + + Task.Run(() => + { + Render(); + }); + } + + void Render() + { // Initialize FancyLoggerBuffer FancyLoggerBuffer.Initialize(); // TODO: Fix. First line does not appear at top. Leaving empty line for now FancyLoggerBuffer.WriteNewLine(string.Empty); + // First render FancyLoggerBuffer.Render(); + int i = 0; + // Rerender periodically + while (!FancyLoggerBuffer.IsTerminated) + { + i++; + // Delay by 1/60 seconds + // Use task delay to avoid blocking the task, so that keyboard input is listened continously + Task.Delay((i / 60) * 1_000).ContinueWith((t) => + { + // Rerender projects only when needed + foreach (var project in projects) project.Value.Log(); + // Rerender buffer + FancyLoggerBuffer.Render(); + }); + // Handle keyboard input + if (Console.KeyAvailable) + { + ConsoleKey key = Console.ReadKey().Key; + switch (key) + { + case ConsoleKey.UpArrow: + if (FancyLoggerBuffer.TopLineIndex > 0) FancyLoggerBuffer.TopLineIndex--; + FancyLoggerBuffer.ShouldRerender = true; + break; + case ConsoleKey.DownArrow: + FancyLoggerBuffer.TopLineIndex++; + FancyLoggerBuffer.ShouldRerender = true; + break; + default: + break; + } + } + } } // Build @@ -72,7 +116,7 @@ void eventSource_ProjectStarted(object sender, ProjectStartedEventArgs e) FancyLoggerProjectNode node = new FancyLoggerProjectNode(e); projects[id] = node; // Log - node.Log(); + node.ShouldRerender = true; } void eventSource_ProjectFinished(object sender, ProjectFinishedEventArgs e) @@ -83,7 +127,7 @@ void eventSource_ProjectFinished(object sender, ProjectFinishedEventArgs e) // Update line node.Finished = true; // Log - node.Log(); + node.ShouldRerender = true; } // Target @@ -95,7 +139,7 @@ void eventSource_TargetStarted(object sender, TargetStartedEventArgs e) // Update node.AddTarget(e); // Log - node.Log(); + node.ShouldRerender = true; } void eventSource_TargetFinished(object sender, TargetFinishedEventArgs e) @@ -106,7 +150,7 @@ void eventSource_TargetFinished(object sender, TargetFinishedEventArgs e) // Update node.FinishedTargets++; // Log - node.Log(); + node.ShouldRerender = true; } // Task @@ -119,7 +163,7 @@ void eventSource_TaskStarted(object sender, TaskStartedEventArgs e) node.AddTask(e); existingTasks++; // Log - node.Log(); + node.ShouldRerender = true; } void eventSource_TaskFinished(object sender, TaskFinishedEventArgs e) @@ -137,7 +181,7 @@ void eventSource_MessageRaised(object sender, BuildMessageEventArgs e) // Update node.AddMessage(e); // Log - node.Log(); + node.ShouldRerender = true; } void eventSource_WarningRaised(object sender, BuildWarningEventArgs e) @@ -148,7 +192,7 @@ void eventSource_WarningRaised(object sender, BuildWarningEventArgs e) // Update node.AddWarning(e); // Log - node.Log(); + node.ShouldRerender = true; } void eventSource_ErrorRaised(object sender, BuildErrorEventArgs e) { @@ -158,7 +202,7 @@ void eventSource_ErrorRaised(object sender, BuildErrorEventArgs e) // Update node.AddError(e); // Log - node.Log(); + node.ShouldRerender = true; } void console_CancelKeyPressed(object? sender, ConsoleCancelEventArgs eventArgs) diff --git a/src/Build/Logging/FancyLogger/FancyLoggerBuffer.cs b/src/Build/Logging/FancyLogger/FancyLoggerBuffer.cs index 02453838914..04923ba5461 100644 --- a/src/Build/Logging/FancyLogger/FancyLoggerBuffer.cs +++ b/src/Build/Logging/FancyLogger/FancyLoggerBuffer.cs @@ -6,7 +6,6 @@ using System.Collections.Generic; using System.Linq; using System.Text; -using System.Threading.Tasks; namespace Microsoft.Build.Logging.FancyLogger { @@ -26,6 +25,8 @@ public string Text _text = value; if (ShouldWrapLines) WrappedText = ANSIBuilder.ANSIWrap(value, Console.BufferWidth); else WrappedText = new List { value }; + // Buffer should rerender + FancyLoggerBuffer.ShouldRerender = true; } } @@ -53,51 +54,22 @@ public class FancyLoggerBuffer private static List Lines = new(); public static int TopLineIndex = 0; public static string Footer = string.Empty; - private static bool AutoScrollEnabled = true; - private static bool IsTerminated = false; - public static void Initialize() + internal static bool IsTerminated = false; + internal static bool ShouldRerender = true; + internal static int ScrollableAreaHeight { - - Task.Run(() => + get { - // Configure buffer, encoding and cursor - Console.OutputEncoding = Encoding.UTF8; - Console.Write(ANSIBuilder.Buffer.UseAlternateBuffer()); - Console.Write(ANSIBuilder.Cursor.Invisible()); - - // Counter for delaying render - int i = 0; - - // Execute while the buffer is active - while (!IsTerminated) - { - // Delay by 1/60 seconds - i++; - Task.Delay((i/60) * 1_000).ContinueWith((t) => - { - Render(); - }); - if (Console.KeyAvailable) - { - // Handle keyboard input - ConsoleKey key = Console.ReadKey().Key; - switch (key) - { - case ConsoleKey.UpArrow: - if (TopLineIndex > 0) TopLineIndex--; - break; - case ConsoleKey.DownArrow: - TopLineIndex++; - break; - case ConsoleKey.Spacebar: - AutoScrollEnabled = !AutoScrollEnabled; - break; - default: - break; - } - } - } - }); + // Height of the buffer -3 (titlebar, footer, and footer line) + return Console.BufferHeight - 3; + } + } + public static void Initialize() + { + // Configure buffer, encoding and cursor + Console.OutputEncoding = Encoding.UTF8; + Console.Write(ANSIBuilder.Buffer.UseAlternateBuffer()); + Console.Write(ANSIBuilder.Cursor.Invisible()); } public static void Terminate() @@ -114,7 +86,8 @@ public static void Terminate() #region Rendering public static void Render() { - if (IsTerminated) return; + if (IsTerminated || !ShouldRerender) return; + ShouldRerender = false; Console.Write( // Write header ANSIBuilder.Cursor.Home() + @@ -127,31 +100,38 @@ public static void Render() if (Lines.Count == 0) return; // Iterate over lines and display on terminal - // TODO: Delimit range to improve performance + string contents = string.Empty; int accumulatedLineCount = 0; + int lineIndex = 0; foreach (FancyLoggerBufferLine line in Lines) { + // Continue if accum line count + next lines < scrolling area + if (accumulatedLineCount + line.WrappedText.Count < TopLineIndex) { + accumulatedLineCount += line.WrappedText.Count; + continue; + } + // Break if exceeds scrolling area + if (accumulatedLineCount - TopLineIndex > ScrollableAreaHeight) break; foreach (string s in line.WrappedText) { // Get line index relative to scroll area - int lineIndex = accumulatedLineCount - TopLineIndex; + lineIndex = accumulatedLineCount - TopLineIndex; // Print if line in scrolling area - if (lineIndex >= 0 && lineIndex < Console.BufferHeight - 3) - { - Console.Write(ANSIBuilder.Cursor.Position(lineIndex + 2, 0) + ANSIBuilder.Eraser.LineCursorToEnd() + s); - } + if (lineIndex >= 0 && lineIndex < ScrollableAreaHeight) contents += ANSIBuilder.Cursor.Position(lineIndex + 2, 0) + ANSIBuilder.Eraser.LineCursorToEnd() + s; accumulatedLineCount++; } } + // Iterate for the rest of the screen + for (int i = lineIndex + 1; i < ScrollableAreaHeight; i++) + { + contents += ANSIBuilder.Cursor.Position(i + 2, 0) + ANSIBuilder.Eraser.LineCursorToEnd(); + } + Console.Write(contents); } #endregion #region Line identification public static int GetLineIndexById(int lineId) { - for (int i = 0; i < Lines.Count; i++) - { - if (Lines[i].Id == lineId) return i; - } - return -1; + return Lines.FindIndex(x => x.Id == lineId); } public static FancyLoggerBufferLine? GetLineById(int lineId) @@ -187,7 +167,6 @@ public static int GetLineIndexById(int lineId) { Lines.Add(line); } - // TODO: Handle autoscrolling return line; } @@ -206,15 +185,10 @@ public static int GetLineIndexById(int lineId) } // Update line + // TODO: Remove. Use line.Text instead public static FancyLoggerBufferLine? UpdateLine(int lineId, string text) { - // Get line - FancyLoggerBufferLine? line = GetLineById(lineId); - if (line == null) return null; - line.Text = text; - // Return - return line; - // TODO: Handle autoscrolling + return null; } // Delete line @@ -223,11 +197,9 @@ public static void DeleteLine(int lineId) // Get line index int lineIndex = GetLineIndexById(lineId); if (lineIndex == -1) return; - // Save top line - int topLineId = Lines[TopLineIndex].Id; // Delete Lines.RemoveAt(lineIndex); - // TODO: Handle autoscrolling + ShouldRerender = true; } #endregion } diff --git a/src/Build/Logging/FancyLogger/FancyLoggerMessageNode.cs b/src/Build/Logging/FancyLogger/FancyLoggerMessageNode.cs index 8a0b42dbd1c..f31f56d213c 100644 --- a/src/Build/Logging/FancyLogger/FancyLoggerMessageNode.cs +++ b/src/Build/Logging/FancyLogger/FancyLoggerMessageNode.cs @@ -70,10 +70,11 @@ public string ToANSIString() } } + // TODO: Rename to Log after FancyLogger's API becomes internal public void Log() { if (Line == null) return; - FancyLoggerBuffer.UpdateLine(Line.Id, $" └── {ToANSIString()}"); + Line.Text = $" └── {ToANSIString()}"; } } } diff --git a/src/Build/Logging/FancyLogger/FancyLoggerProjectNode.cs b/src/Build/Logging/FancyLogger/FancyLoggerProjectNode.cs index dbdc72f974c..46553f529f2 100644 --- a/src/Build/Logging/FancyLogger/FancyLoggerProjectNode.cs +++ b/src/Build/Logging/FancyLogger/FancyLoggerProjectNode.cs @@ -38,6 +38,8 @@ private static string GetUnambiguousPath(string path) public int MessageCount = 0; public int WarningCount = 0; public int ErrorCount = 0; + // Bool if node should rerender + internal bool ShouldRerender = true; public FancyLoggerProjectNode(ProjectStartedEventArgs args) { Id = args.ProjectId; @@ -54,8 +56,11 @@ public FancyLoggerProjectNode(ProjectStartedEventArgs args) } } + // TODO: Rename to Render() after FancyLogger's API becomes internal public void Log() { + if (!ShouldRerender) return; + ShouldRerender = false; // Project details string lineContents = ANSIBuilder.Alignment.SpaceBetween( // Show indicator @@ -68,33 +73,32 @@ public void Log() Console.WindowWidth ); // Create or update line - if (Line == null) Line = FancyLoggerBuffer.WriteNewLine(lineContents, false); - else FancyLoggerBuffer.UpdateLine(Line.Id, lineContents); + if (Line is null) Line = FancyLoggerBuffer.WriteNewLine(lineContents, false); + else Line.Text = lineContents; // For finished projects if (Finished) { - if (CurrentTargetLine != null) FancyLoggerBuffer.DeleteLine(CurrentTargetLine.Id); + if (CurrentTargetLine is not null) FancyLoggerBuffer.DeleteLine(CurrentTargetLine.Id); foreach (FancyLoggerMessageNode node in AdditionalDetails.ToList()) { // Only delete high priority messages if (node.Type != FancyLoggerMessageNode.MessageType.HighPriorityMessage) continue; - if (node.Line != null) FancyLoggerBuffer.DeleteLine(node.Line.Id); - // AdditionalDetails.Remove(node); + if (node.Line is not null) FancyLoggerBuffer.DeleteLine(node.Line.Id); } } // Current target details - if (CurrentTargetNode == null) return; + if (CurrentTargetNode is null) return; string currentTargetLineContents = $" └── {CurrentTargetNode.TargetName} : {CurrentTargetNode.CurrentTaskNode?.TaskName ?? String.Empty}"; - if (CurrentTargetLine == null) CurrentTargetLine = FancyLoggerBuffer.WriteNewLineAfter(Line!.Id, currentTargetLineContents); - else FancyLoggerBuffer.UpdateLine(CurrentTargetLine.Id, currentTargetLineContents); + if (CurrentTargetLine is null) CurrentTargetLine = FancyLoggerBuffer.WriteNewLineAfter(Line!.Id, currentTargetLineContents); + else CurrentTargetLine.Text = currentTargetLineContents; // Messages, warnings and errors foreach (FancyLoggerMessageNode node in AdditionalDetails) { if (Finished && node.Type == FancyLoggerMessageNode.MessageType.HighPriorityMessage) continue; - if (node.Line == null) node.Line = FancyLoggerBuffer.WriteNewLineAfter(Line!.Id, "Message"); + if (node.Line is null) node.Line = FancyLoggerBuffer.WriteNewLineAfter(Line!.Id, "Message"); node.Log(); } }