From d9fe5540f508e020ea201dd0f3dabb0270faa23e Mon Sep 17 00:00:00 2001 From: Ethan Atkins Date: Sat, 31 Aug 2019 19:26:41 -0700 Subject: [PATCH 1/3] Interlace log lines with task progress With the current supershell implementation, the progress display flickers when there is heavy console logging during task evaluation. This is because the console appender clears out the task progress and it isn't restored until the next periodic super shell report (which runs every 100ms by default). To remove the flickering, I reworked the implementation to interlace the log lines with progress reports. In order to ensure that the log lines remained contiguous, I had to apply padding at the bottom of the supershell region whenever the new report contained fewer lines than the old report. The report shifts down as new log lines are appended. This isn't optimal, but I think removing the flickering while preserving contiguous log lines is worth it. --- .../sbt/internal/util/ConsoleAppender.scala | 107 +++++++++++++----- 1 file changed, 77 insertions(+), 30 deletions(-) diff --git a/internal/util-logging/src/main/scala/sbt/internal/util/ConsoleAppender.scala b/internal/util-logging/src/main/scala/sbt/internal/util/ConsoleAppender.scala index 2b381540a..6a48084a5 100644 --- a/internal/util-logging/src/main/scala/sbt/internal/util/ConsoleAppender.scala +++ b/internal/util-logging/src/main/scala/sbt/internal/util/ConsoleAppender.scala @@ -3,7 +3,7 @@ package sbt.internal.util import sbt.util._ import java.io.{ PrintStream, PrintWriter } import java.util.Locale -import java.util.concurrent.atomic.{ AtomicBoolean, AtomicInteger } +import java.util.concurrent.atomic.{ AtomicBoolean, AtomicInteger, AtomicReference } import org.apache.logging.log4j.{ Level => XLevel } import org.apache.logging.log4j.message.{ Message, ObjectMessage, ReusableObjectMessage } import org.apache.logging.log4j.core.{ LogEvent => XLogEvent } @@ -108,7 +108,6 @@ object ConsoleAppender { private[this] val showProgressHolder: AtomicBoolean = new AtomicBoolean(false) def setShowProgress(b: Boolean): Unit = showProgressHolder.set(b) def showProgress: Boolean = showProgressHolder.get - private[sbt] val lastTaskCount = new AtomicInteger(0) /** Hide stack trace altogether. */ val noSuppressedMessage = (_: SuppressedTraceContext) => None @@ -311,6 +310,80 @@ object ConsoleAppender { } +/** + * Caches the task progress lines so that they can be reprinted whenever the default + * appender logs additional messages. This makes it so that the progress lines are + * more stable with less appearance of flickering. + */ +private object SuperShellLogger { + private val progressLines = new AtomicReference[Seq[String]](Nil) + // leave some blank lines for tasks that might use println(...) + private val blankZone = 5 + + /** + * Splits a log message into individual lines and interlaces each line with + * the task progress report to reduce the appearance of flickering. It is assumed + * that this method is only called while holding the out.lockObject. + */ + private[util] def writeMsg(out: ConsoleOut, msg: String): Unit = { + val progress = progressLines.get + msg.linesIterator.foreach { l => + out.println(s"$DeleteLine$l") + if (progress.length > 0) { + deleteConsoleLines(out, blankZone) + progress.foreach(out.println) + out.print(cursorUp(blankZone + progress.length)) + } + } + out.flush() + } + + /** + * Receives a new task report and replaces the old one. In the event that the new + * report has fewer lines than the previous report, the report is shifted up by + * the difference in the previous and current number of lines. As new log lines + * are added by the regular console appender, the report will shift down until the + * padding is filled. This allows the regular log lines to be viewable as a continuous + * line stream with no holes. The unfortunate part is that the super shell output + * location does shift around a little bit. There are at least two ways to address this + * + * 1) Add an invariant that the super shell region never shrinks, but may grow, during + * task evaluation. We'd have to add some kind of special message to send to the + * appender to let it now that task evaluation is completely done so that it can + * reset the progress area size. + * + * 2) Refactor ConsoleAppender so that knows the log level. Right now, we print lines + * to the console appender that ultimately get discarded because they are at the + * debug level. As a result, it's impossible to know whether or not the line + * out.println(s"$DeleteLine$l") actually prints anything to the console. If we + * could guarantee that every line in a message passed into writeMsg was actually + * written to the screen, then we could apply the padding at the top and reduce + * the padding whenever a new line is logged until it is no longer necessary to + * apply padding to the progress region to keep the lines stream contiguous. + * + */ + private[util] def update(out: ConsoleOut, pe: ProgressEvent): Unit = { + val sorted = pe.items.sortBy(x => x.elapsedMicros) + val info = sorted map { item => + val elapsed = item.elapsedMicros / 1000000L + s"$DeleteLine | => ${item.name} ${elapsed}s" + } + + deleteConsoleLines(out, blankZone) + info.foreach(i => out.println(i)) + + val previousLines = progressLines.getAndSet(info) + val padding = math.max(0, previousLines.length - info.length) + deleteConsoleLines(out, padding) + out.print(cursorUp(blankZone + info.length + padding)) + out.flush() + } + private def deleteConsoleLines(out: ConsoleOut, n: Int): Unit = { + (1 to n) foreach { _ => + out.println(DeleteLine) + } + } +} // See http://stackoverflow.com/questions/24205093/how-to-create-a-custom-appender-in-log4j2 // for custom appender using Java. // http://logging.apache.org/log4j/2.x/manual/customconfig.html @@ -455,19 +528,11 @@ class ConsoleAppender private[ConsoleAppender] ( appendLog(SUCCESS_LABEL_COLOR, Level.SuccessLabel, SUCCESS_MESSAGE_COLOR, message) } - // leave some blank lines for tasks that might use println(...) - private val blankZone = 5 private def write(msg: String): Unit = { if (!useFormat || !ansiCodesSupported) { out.println(EscHelpers.removeEscapeSequences(msg)) } else if (ConsoleAppender.showProgress) { - val clearNum = lastTaskCount.get + blankZone - if (clearNum > 1) { - deleteConsoleLines(clearNum) - out.print(s"${cursorUp(clearNum)}") - } - out.println(msg) - out.flush() + SuperShellLogger.writeMsg(out, msg) } else { out.println(msg) } @@ -503,27 +568,9 @@ class ConsoleAppender private[ConsoleAppender] ( private def appendProgressEvent(pe: ProgressEvent): Unit = if (ConsoleAppender.showProgress) { out.lockObject.synchronized { - deleteConsoleLines(blankZone) - val currentTasksCount = pe.items.size - val ltc = pe.lastTaskCount.getOrElse(0) - val sorted = pe.items.sortBy(_.name).sortBy(x => -x.elapsedMicros) - sorted foreach { item => - val elapsed = item.elapsedMicros / 1000000L - out.println(s"$DeleteLine | => ${item.name} ${elapsed}s") - } - if (ltc > currentTasksCount) deleteConsoleLines(ltc - currentTasksCount) - else () - out.print(cursorUp(math.max(currentTasksCount, ltc) + blankZone)) - out.flush() - lastTaskCount.set(ltc) + SuperShellLogger.update(out, pe) } - } else () - - private def deleteConsoleLines(n: Int): Unit = { - (1 to n) foreach { _ => - out.println(DeleteLine) } - } private def appendMessageContent(level: Level.Value, o: AnyRef): Unit = { def appendEvent(oe: ObjectEvent[_]): Unit = { From a5666e97b6e2395c7404d21c85f3efc58778df19 Mon Sep 17 00:00:00 2001 From: Ethan Atkins Date: Sun, 1 Sep 2019 21:54:15 -0700 Subject: [PATCH 2/3] Manage progress padding With this commit, I improved the padding management so that padding is now added above the progress report. Whenever a line is logged at the info or greater level, we can reduce the padding level by one since that line has effectively filled in the padding. --- .../sbt/internal/util/ConsoleAppender.scala | 48 ++++++++----------- 1 file changed, 21 insertions(+), 27 deletions(-) diff --git a/internal/util-logging/src/main/scala/sbt/internal/util/ConsoleAppender.scala b/internal/util-logging/src/main/scala/sbt/internal/util/ConsoleAppender.scala index 6a48084a5..8a46acc35 100644 --- a/internal/util-logging/src/main/scala/sbt/internal/util/ConsoleAppender.scala +++ b/internal/util-logging/src/main/scala/sbt/internal/util/ConsoleAppender.scala @@ -319,6 +319,8 @@ private object SuperShellLogger { private val progressLines = new AtomicReference[Seq[String]](Nil) // leave some blank lines for tasks that might use println(...) private val blankZone = 5 + private val padding = new AtomicInteger(0) + private val ascii = "[^\\p{ASCII}]".r.pattern /** * Splits a log message into individual lines and interlaces each line with @@ -330,9 +332,15 @@ private object SuperShellLogger { msg.linesIterator.foreach { l => out.println(s"$DeleteLine$l") if (progress.length > 0) { - deleteConsoleLines(out, blankZone) + val stripped = ascii.matcher(l).replaceAll("") + val isDebugLine = + l.startsWith("[debug]") || l.startsWith(s"${scala.Console.RESET}[debug]") + // As long as the line isn't a debug line, we can assume it was printed to + // the console and reduce the top padding. + val pad = if (padding.get > 0 && !isDebugLine) padding.decrementAndGet else padding.get + deleteConsoleLines(out, blankZone + pad) progress.foreach(out.println) - out.print(cursorUp(blankZone + progress.length)) + out.print(cursorUp(blankZone + progress.length + padding.get)) } } out.flush() @@ -340,27 +348,10 @@ private object SuperShellLogger { /** * Receives a new task report and replaces the old one. In the event that the new - * report has fewer lines than the previous report, the report is shifted up by - * the difference in the previous and current number of lines. As new log lines - * are added by the regular console appender, the report will shift down until the - * padding is filled. This allows the regular log lines to be viewable as a continuous - * line stream with no holes. The unfortunate part is that the super shell output - * location does shift around a little bit. There are at least two ways to address this - * - * 1) Add an invariant that the super shell region never shrinks, but may grow, during - * task evaluation. We'd have to add some kind of special message to send to the - * appender to let it now that task evaluation is completely done so that it can - * reset the progress area size. - * - * 2) Refactor ConsoleAppender so that knows the log level. Right now, we print lines - * to the console appender that ultimately get discarded because they are at the - * debug level. As a result, it's impossible to know whether or not the line - * out.println(s"$DeleteLine$l") actually prints anything to the console. If we - * could guarantee that every line in a message passed into writeMsg was actually - * written to the screen, then we could apply the padding at the top and reduce - * the padding whenever a new line is logged until it is no longer necessary to - * apply padding to the progress region to keep the lines stream contiguous. - * + * report has fewer lines than the previous report, padding lines are added on top + * so that the console log lines remain contiguous. When a console line is printed + * at the info or greater level, we can decrement the padding because the console + * line will have filled in the blank line. */ private[util] def update(out: ConsoleOut, pe: ProgressEvent): Unit = { val sorted = pe.items.sortBy(x => x.elapsedMicros) @@ -369,13 +360,16 @@ private object SuperShellLogger { s"$DeleteLine | => ${item.name} ${elapsed}s" } + val previousLines = progressLines.getAndSet(info) + val prevPadding = padding.get + val newPadding = math.max(0, previousLines.length + prevPadding - info.length) + padding.set(newPadding) + + deleteConsoleLines(out, newPadding) deleteConsoleLines(out, blankZone) info.foreach(i => out.println(i)) - val previousLines = progressLines.getAndSet(info) - val padding = math.max(0, previousLines.length - info.length) - deleteConsoleLines(out, padding) - out.print(cursorUp(blankZone + info.length + padding)) + out.print(cursorUp(blankZone + info.length + newPadding)) out.flush() } private def deleteConsoleLines(out: ConsoleOut, n: Int): Unit = { From 635316902d3d46da31fb4afa607a683877b16e92 Mon Sep 17 00:00:00 2001 From: Ethan Atkins Date: Mon, 2 Sep 2019 11:07:48 -0700 Subject: [PATCH 3/3] Allow supershell to work in no color mode Supershell actually works quite well in no color mode. On the sbt side, we still want to disable supershell automatically if the output is not a terminal or no color is set, but this commit allows the user to force supershell through -Dsbt.supershell or the useSuperShell setting even when no color is set. --- .../main/scala/sbt/internal/util/ConsoleAppender.scala | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/internal/util-logging/src/main/scala/sbt/internal/util/ConsoleAppender.scala b/internal/util-logging/src/main/scala/sbt/internal/util/ConsoleAppender.scala index 8a46acc35..4be18ffb3 100644 --- a/internal/util-logging/src/main/scala/sbt/internal/util/ConsoleAppender.scala +++ b/internal/util-logging/src/main/scala/sbt/internal/util/ConsoleAppender.scala @@ -523,12 +523,12 @@ class ConsoleAppender private[ConsoleAppender] ( } private def write(msg: String): Unit = { - if (!useFormat || !ansiCodesSupported) { - out.println(EscHelpers.removeEscapeSequences(msg)) - } else if (ConsoleAppender.showProgress) { - SuperShellLogger.writeMsg(out, msg) + val toWrite = + if (!useFormat || !ansiCodesSupported) EscHelpers.removeEscapeSequences(msg) else msg + if (ConsoleAppender.showProgress) { + SuperShellLogger.writeMsg(out, toWrite) } else { - out.println(msg) + out.println(toWrite) } }