From 6c2c3253e06ec75d73f950888ecf3b866bc07472 Mon Sep 17 00:00:00 2001 From: jvican Date: Sat, 21 Oct 2017 12:25:49 +0200 Subject: [PATCH] Improve and make scripted parallel These are the improvements that I've added to scripted: 1. Scripted is now parallel and does batch execution. 2. Scripted logs to both a file and the console (if `bufferLog == true`). All the logs can be inspected locally by going to a directory in `/tmp`. This directory is shown to the user at the end of the execution. 3. Scripted UI has been improved. 3.1. Colors are used for `+` and `x`. 3.1. It shows the command that actually failed, not `Command failed {line 1}`. 3.2. It trims the stack traces of the wrapping exceptions (corresponding to the scripted infrastructure). Only the stack traces of the causing exceptions are shown (which are the ones we're interested in and are usually assertion errors). I think these improvements enhance the current dev workflow considerably. I invite you to give them a try. This change combined with #429, gives a really fast execution of scripted. Testing just one test is under 7 seconds in my machine (note that in those 7 seconds we have to fetch the bridge, etc). --- .../sbt/internal/inc/BatchScriptRunner.scala | 64 +++++ .../scala/sbt/internal/inc/IncHandler.scala | 27 ++- .../sbt/internal/inc/IncScriptedRunner.scala | 69 +++++- .../sbt/internal/inc/ScriptedTests.scala | 226 ++++++++++++++++++ .../source-dependencies/constants/pending | 1 - 5 files changed, 377 insertions(+), 10 deletions(-) create mode 100644 internal/zinc-scripted/src/test/scala/sbt/internal/inc/BatchScriptRunner.scala create mode 100644 internal/zinc-scripted/src/test/scala/sbt/internal/inc/ScriptedTests.scala diff --git a/internal/zinc-scripted/src/test/scala/sbt/internal/inc/BatchScriptRunner.scala b/internal/zinc-scripted/src/test/scala/sbt/internal/inc/BatchScriptRunner.scala new file mode 100644 index 0000000000..5f36d99a67 --- /dev/null +++ b/internal/zinc-scripted/src/test/scala/sbt/internal/inc/BatchScriptRunner.scala @@ -0,0 +1,64 @@ +package sbt.internal.inc + +import org.scalatest.exceptions.TestFailedException +import sbt.internal.inc +import sbt.internal.scripted._ +import sbt.internal.inc.BatchScriptRunner.States + +/** Defines an alternative script runner that allows batch execution. */ +private[sbt] class BatchScriptRunner extends ScriptRunner { + + /** Defines a method to run batched execution. + * + * @param statements The list of handlers and statements. + * @param states The states of the runner. In case it's empty, inherited apply is called. + */ + def apply(statements: List[(StatementHandler, Statement)], states: States): Unit = { + if (states.isEmpty) super.apply(statements) + else statements.foreach(st => processStatement(st._1, st._2, states)) + } + + def initStates(states: States, handlers: Seq[StatementHandler]): Unit = + handlers.foreach(handler => states(handler) = handler.initialState) + + def cleanUpHandlers(handlers: Seq[StatementHandler], states: States): Unit = { + for (handler <- handlers; state <- states.get(handler)) { + try handler.finish(state.asInstanceOf[handler.State]) + catch { case _: Exception => () } + } + } + + import BatchScriptRunner.PreciseScriptedError + def processStatement(handler: StatementHandler, statement: Statement, states: States): Unit = { + val state = states(handler).asInstanceOf[handler.State] + val nextState = + try { Right(handler(statement.command, statement.arguments, state)) } catch { + case e: Exception => Left(e) + } + nextState match { + case Left(err) => + if (statement.successExpected) { + err match { + case t: TestFailed => + val errorMessage = s"${t.getMessage} produced by" + throw new PreciseScriptedError(statement, errorMessage, null) + case _ => throw new PreciseScriptedError(statement, "Command failed", err) + } + } else () + case Right(s) => + if (statement.successExpected) states(handler) = s + else throw new PreciseScriptedError(statement, "Expecting error at", null) + } + } +} + +private[sbt] object BatchScriptRunner { + import scala.collection.mutable + type States = mutable.HashMap[StatementHandler, Any] + + // Should be used instead of sbt.internal.scripted.TestException that doesn't show failed command + final class PreciseScriptedError(st: Statement, msg: String, e: Throwable) + extends RuntimeException(s"$msg: '${st.command} ${st.arguments.mkString(" ")}'", e) { + override def fillInStackTrace = e + } +} diff --git a/internal/zinc-scripted/src/test/scala/sbt/internal/inc/IncHandler.scala b/internal/zinc-scripted/src/test/scala/sbt/internal/inc/IncHandler.scala index adc509e53e..8fdf8417ea 100644 --- a/internal/zinc-scripted/src/test/scala/sbt/internal/inc/IncHandler.scala +++ b/internal/zinc-scripted/src/test/scala/sbt/internal/inc/IncHandler.scala @@ -57,8 +57,18 @@ final class IncHandler(directory: File, cacheDir: File, scriptedLog: ManagedLogg type IncCommand = (ProjectStructure, List[String], IncInstance) => Unit val compiler = new IncrementalCompilerImpl - def initialState: Option[IncInstance] = None - def finish(state: Option[IncInstance]): Unit = () + + def initialState: Option[IncInstance] = { + initBuildStructure() + None + } + + def finish(state: Option[IncInstance]): Unit = { + // Required so that next projects re-read the project structure + buildStructure.clear() + () + } + val buildStructure: mutable.Map[String, ProjectStructure] = mutable.Map.empty def initBuildStructure(): Unit = { val build = initBuild @@ -70,8 +80,6 @@ final class IncHandler(directory: File, cacheDir: File, scriptedLog: ManagedLogg } } - initBuildStructure() - private final val RootIdentifier = "root" def initBuild: Build = { if ((directory / "build.json").exists) { @@ -108,14 +116,14 @@ final class IncHandler(directory: File, cacheDir: File, scriptedLog: ManagedLogg private final val noLogger = Logger.Null private[this] def onNewIncInstance(p: ProjectStructure): IncInstance = { val scalaVersion = p.scalaVersion - val (compilerBridge, si) = IncHandler.scriptedCompilerCache.get(scalaVersion) match { + val (compilerBridge, si) = IncHandler.getCompilerCacheFor(scalaVersion) match { case Some(alreadyInstantiated) => alreadyInstantiated case None => val compilerBridge = getCompilerBridge(cacheDir, noLogger, scalaVersion) val si = scalaInstance(scalaVersion, cacheDir, noLogger) val toCache = (compilerBridge, si) - IncHandler.scriptedCompilerCache.put(scalaVersion, toCache) + IncHandler.putCompilerCache(scalaVersion, toCache) toCache } val analyzingCompiler = scalaCompiler(si, compilerBridge) @@ -505,7 +513,12 @@ case class ProjectStructure( object IncHandler { type Cached = (File, xsbti.compile.ScalaInstance) - private[internal] final val scriptedCompilerCache = new mutable.WeakHashMap[String, Cached]() + private[this] final val scriptedCompilerCache = new mutable.WeakHashMap[String, Cached]() + def getCompilerCacheFor(scalaVersion: String): Option[Cached] = + synchronized(scriptedCompilerCache.get(scalaVersion)) + def putCompilerCache(scalaVersion: String, cached: Cached): Option[Cached] = + synchronized(scriptedCompilerCache.put(scalaVersion, cached)) + private[internal] final val classLoaderCache = Some( new ClassLoaderCache(new URLClassLoader(Array()))) } diff --git a/internal/zinc-scripted/src/test/scala/sbt/internal/inc/IncScriptedRunner.scala b/internal/zinc-scripted/src/test/scala/sbt/internal/inc/IncScriptedRunner.scala index cb9f48810d..0f5cca876b 100644 --- a/internal/zinc-scripted/src/test/scala/sbt/internal/inc/IncScriptedRunner.scala +++ b/internal/zinc-scripted/src/test/scala/sbt/internal/inc/IncScriptedRunner.scala @@ -2,15 +2,80 @@ package sbt.internal.inc import java.io.File -import sbt.internal.scripted.ScriptedRunnerImpl +import sbt.internal.scripted.{ HandlersProvider, ListTests, ScriptedTest } import sbt.io.IO +import sbt.util.Logger + +import scala.collection.parallel.ParSeq class IncScriptedRunner { def run(resourceBaseDirectory: File, bufferLog: Boolean, tests: Array[String]): Unit = { IO.withTemporaryDirectory { tempDir => // Create a global temporary directory to store the bridge et al val handlers = new IncScriptedHandlers(tempDir) - ScriptedRunnerImpl.run(resourceBaseDirectory, bufferLog, tests, handlers); + ScriptedRunnerImpl.run(resourceBaseDirectory, bufferLog, tests, handlers, 4) + } + } +} + +object ScriptedRunnerImpl { + type TestRunner = () => Seq[Option[String]] + + def run( + resourceBaseDirectory: File, + bufferLog: Boolean, + tests: Array[String], + handlersProvider: HandlersProvider, + instances: Int + ): Unit = { + val globalLogger = newLogger + val logsDir = newScriptedLogsDir + val runner = new ScriptedTests(resourceBaseDirectory, bufferLog, handlersProvider, logsDir) + val scriptedTests = get(tests, resourceBaseDirectory, globalLogger) + val scriptedRunners = runner.batchScriptedRunner(scriptedTests, instances) + val parallelRunners = scriptedRunners.toParArray + // Using this deprecated value for 2.11 support + val pool = new scala.concurrent.forkjoin.ForkJoinPool(instances) + parallelRunners.tasksupport = new scala.collection.parallel.ForkJoinTaskSupport(pool) + runAllInParallel(parallelRunners) + globalLogger.info(s"Log files can be found at ${logsDir.getAbsolutePath}") + } + + private val nl = IO.Newline + private val nlt = nl + "\t" + class ScriptedFailure(tests: Seq[String]) extends RuntimeException(tests.mkString(nlt, nlt, nl)) { + // We are not interested in the stack trace here, only the failing tests + override def fillInStackTrace = this + } + + private def reportErrors(errors: Seq[String]): Unit = + if (errors.nonEmpty) throw new ScriptedFailure(errors) else () + + def runAllInParallel(tests: ParSeq[TestRunner]): Unit = { + reportErrors(tests.flatMap(test => test.apply().flatten.toSeq).toList) + } + + def get(tests: Seq[String], baseDirectory: File, log: Logger): Seq[ScriptedTest] = + if (tests.isEmpty) listTests(baseDirectory, log) else parseTests(tests) + + def listTests(baseDirectory: File, log: Logger): Seq[ScriptedTest] = + (new ListTests(baseDirectory, _ => true, log)).listTests + + def parseTests(in: Seq[String]): Seq[ScriptedTest] = for (testString <- in) yield { + testString.split("/").map(_.trim) match { + case Array(group, name) => ScriptedTest(group, name) + case elems => + sys.error(s"Expected two arguments 'group/name', obtained ${elems.mkString("/")}") } } + + private[sbt] def newLogger: Logger = sbt.internal.util.ConsoleLogger() + + private[this] val random = new java.util.Random() + private[sbt] def newScriptedLogsDir: File = { + val randomName = "scripted-logs-" + java.lang.Integer.toHexString(random.nextInt) + val logsDir = new File(IO.temporaryDirectory, randomName) + IO.createDirectory(logsDir) + logsDir + } } diff --git a/internal/zinc-scripted/src/test/scala/sbt/internal/inc/ScriptedTests.scala b/internal/zinc-scripted/src/test/scala/sbt/internal/inc/ScriptedTests.scala new file mode 100644 index 0000000000..1af4282af8 --- /dev/null +++ b/internal/zinc-scripted/src/test/scala/sbt/internal/inc/ScriptedTests.scala @@ -0,0 +1,226 @@ +package sbt.internal.inc + +import java.io.File +import java.util.concurrent.atomic.AtomicInteger + +import sbt.internal.scripted._ +import sbt.io.IO +import sbt.io.FileFilter._ +import sbt.internal.io.Resources +import sbt.internal.util.{ ConsoleAppender, ConsoleOut, ManagedLogger } +import sbt.util.{ Level, LogExchange } + +final class ScriptedTests(resourceBaseDirectory: File, + bufferLog: Boolean, + handlersProvider: HandlersProvider, + logsDir: File) { + import sbt.io.syntax._ + import ScriptedTests._ + + private[this] val batchIdGenerator: AtomicInteger = new AtomicInteger + private[this] val runIdGenerator: AtomicInteger = new AtomicInteger + + final val ScriptFilename = "test" + final val PendingScriptFilename = "pending" + private val testResources = new Resources(resourceBaseDirectory) + + private def createScriptedHandlers( + label: String, + testDir: File, + logger: ManagedLogger + ): Map[Char, StatementHandler] = { + val scriptConfig = new ScriptConfig(label, testDir, logger) + handlersProvider.getHandlers(scriptConfig) + } + + /** Returns a sequence of test runners that have to be applied in the call site. */ + def batchScriptedRunner( + testGroupAndNames: Seq[ScriptedTest], + sbtInstances: Int + ): Seq[TestRunner] = { + // Test group and names may be file filters (like '*') + val groupAndNameDirs = { + for { + ScriptedTest(group, name) <- testGroupAndNames + groupDir <- resourceBaseDirectory.*(group).get + testDir <- groupDir.*(name).get + } yield (groupDir, testDir) + } + + val labelsAndDirs = groupAndNameDirs.map { + case (groupDir, nameDir) => + val groupName = groupDir.getName + val testName = nameDir.getName + val testDirectory = testResources.readOnlyResourceDirectory(groupName, testName) + (groupName, testName) -> testDirectory + } + + if (labelsAndDirs.isEmpty) List() + else { + val batchSeed = labelsAndDirs.size / sbtInstances + val batchSize = if (batchSeed == 0) labelsAndDirs.size else batchSeed + labelsAndDirs + .grouped(batchSize) + .map(batch => () => IO.withTemporaryDirectory(runBatchedTests(batch, _))) + .toList + } + } + + def createScriptedLogFile(loggerName: String): File = { + val name = s"$loggerName-${runIdGenerator.incrementAndGet}.log" + val logFile = logsDir./(name) + logFile.createNewFile() + logFile + } + + import sbt.internal.util.BufferedAppender + case class ScriptedLogger(log: ManagedLogger, logFile: File, buffer: BufferedAppender) + + private val BufferSize = 8192 // copied from IO since it's private + def rebindLogger(logger: ManagedLogger, logFile: File): ScriptedLogger = { + // Create buffered logger to a file that we will afterwards use. + import java.io.{ BufferedWriter, FileWriter } + val name = logger.name + val writer = new BufferedWriter(new FileWriter(logFile), BufferSize) + val fileOut = ConsoleOut.bufferedWriterOut(writer) + val fileAppender = ConsoleAppender(name, fileOut, useFormat = false) + val outAppender = BufferedAppender(ConsoleAppender()) + val appenders = (fileAppender -> Level.Debug) :: (outAppender -> Level.Debug) :: Nil + LogExchange.unbindLoggerAppenders(name) + LogExchange.bindLoggerAppenders(name, appenders) + ScriptedLogger(logger, logFile, outAppender) + } + + private final def createBatchLogger(name: String): ManagedLogger = LogExchange.logger(name) + + /** Defines the batch execution of scripted tests. + * + * Scripted tests are run one after the other one recycling the handlers, under + * the assumption that handlers do not produce side effects that can change scripted + * tests' behaviours. + * + * In batch mode, the test runner performs these operations between executions: + * + * 1. Delete previous test files in the common test directory. + * 2. Copy over next test files to the common test directory. + * 3. Reload the sbt handler. + * + * @param groupedTests The labels and directories of the tests to run. + * @param batchTmpDir The common test directory. + * @param log The logger. + */ + private def runBatchedTests( + groupedTests: Seq[((String, String), File)], + batchTmpDir: File + ): Seq[Option[String]] = { + val runner = new BatchScriptRunner + val batchId = s"initial-batch-${batchIdGenerator.incrementAndGet()}" + val batchLogger = createBatchLogger(batchId) + val handlers = createScriptedHandlers(batchId, batchTmpDir, batchLogger) + val states = new BatchScriptRunner.States + val seqHandlers = handlers.values.toList + runner.initStates(states, seqHandlers) + + def runBatchTests = { + groupedTests.map { + case ((group, name), originalDir) => + val label = s"$group / $name" + val loggerName = s"scripted-$group-$name.log" + val logFile = createScriptedLogFile(loggerName) + val logger = rebindLogger(batchLogger, logFile) + + println(s"Running $label") + // Copy test's contents + IO.copyDirectory(originalDir, batchTmpDir) + + // Reset the state of `IncHandler` between every scripted run + runner.cleanUpHandlers(seqHandlers, states) + runner.initStates(states, seqHandlers) + + // Run the test and delete files (except global that holds local scala jars) + val runTest = () => commonRunTest(label, batchTmpDir, handlers, runner, states, logger) + val result = runOrHandleDisabled(label, batchTmpDir, runTest, logger) + IO.delete(batchTmpDir.*("*" -- "global").get) + result + } + } + + try runBatchTests + finally runner.cleanUpHandlers(seqHandlers, states) + } + + private def runOrHandleDisabled( + label: String, + testDirectory: File, + runTest: () => Option[String], + logger: ScriptedLogger + ): Option[String] = { + val existsDisabled = new File(testDirectory, "disabled").isFile + if (!existsDisabled) runTest() + else { + logger.log.info(s"D $label [DISABLED]") + None + } + } + + import BatchScriptRunner.PreciseScriptedError + private val SuccessMark = s"${Console.GREEN + Console.BOLD}+${Console.RESET}" + private val FailureMark = s"${Console.RED + Console.BOLD}x${Console.RESET}" + private val PendingLabel = "[PENDING]" + private def commonRunTest( + label: String, + testDirectory: File, + handlers: Map[Char, StatementHandler], + runner: BatchScriptRunner, + states: BatchScriptRunner.States, + scriptedLogger: ScriptedLogger + ): Option[String] = { + val ScriptedLogger(logger, _, buffer) = scriptedLogger + if (bufferLog) buffer.record() + + val (file, pending) = { + val normal = new File(testDirectory, ScriptFilename) + val pending = new File(testDirectory, PendingScriptFilename) + if (pending.isFile) (pending, true) else (normal, false) + } + + def testFailed(t: Throwable): Option[String] = { + if (pending) { + logger.trace(t) + buffer.clearBuffer() + logger.error(s"$FailureMark $label $PendingLabel") + None + } else { + logger.error(s"$FailureMark $label") + logger.trace(t) + Some(label) + } + } + + import scala.util.control.Exception.catching + catching(classOf[PreciseScriptedError]) + .withApply(testFailed) + .andFinally(buffer.stopBuffer()) + .apply { + val parser = new TestScriptParser(handlers) + val handlersAndStatements = parser.parse(file) + runner.apply(handlersAndStatements, states) + + // Handle successful tests + if (bufferLog) buffer.clearBuffer() + if (pending) { + logger.info(s"$SuccessMark $label $PendingLabel") + logger.error(s" -> Pending test $label passed. Mark as passing to remove this failure.") + Some(label) + } else { + logger.info(s"$SuccessMark $label") + None + } + } + } +} + +object ScriptedTests { + type TestRunner = () => Seq[Option[String]] + val emptyCallback: File => Unit = _ => () +} diff --git a/zinc/src/sbt-test/source-dependencies/constants/pending b/zinc/src/sbt-test/source-dependencies/constants/pending index eebce96e43..7a5ae58795 100644 --- a/zinc/src/sbt-test/source-dependencies/constants/pending +++ b/zinc/src/sbt-test/source-dependencies/constants/pending @@ -1,5 +1,4 @@ # Marked as pending, see https://github.com/sbt/sbt/issues/1543 -# # Tests if source dependencies are tracked properly # for compile-time constants (like final vals in top-level objects) # see https://issues.scala-lang.org/browse/SI-7173 for details