Share profile loggers between nested evaluations

integration/feature/full-run-logs/src/FullRunLogsTests.scala

@@ -1,10 +1,12 @@
 package mill.integration
 
+import mill.main.client.OutFiles
 import mill.testkit.UtestIntegrationTestSuite
-import utest._
+import utest.*
 
-// Run simple commands on a simple build and check their entire output,
-// ensuring we don't get spurious warnings or logging messages slipping in
+// Run simple commands on a simple build and check their entire output and some
+// metadata files, ensuring we don't get spurious warnings or logging messages
+// slipping in and the important parts of the logs and output files are present
 object FullRunLogsTests extends UtestIntegrationTestSuite {
 
   def tests: Tests = Tests {
@@ -50,5 +52,27 @@ object FullRunLogsTests extends UtestIntegrationTestSuite {
 
       assert(expectedErrorRegex.r.matches(res.err.replace('\\', '/').replaceAll("(\r\n)|\r", "\n")))
     }
+    test("show") - integrationTest { tester =>
+      import tester._
+      // Make sure when we have nested evaluations, e.g. due to usage of evaluator commands
+      // like `show`, both outer and inner evaluations hae their metadata end up in the
+      // same profile files so a user can see what's going on in either
+      eval(("show", "compile"))
+      val millProfile = ujson.read(os.read(workspacePath / OutFiles.out / "mill-profile.json")).arr
+      val millChromeProfile =
+        ujson.read(os.read(workspacePath / OutFiles.out / "mill-chrome-profile.json")).arr
+      // Profile logs for the thing called by show
+      assert(millProfile.exists(_.obj("label").str == "compile"))
+      assert(millProfile.exists(_.obj("label").str == "compileClasspath"))
+      assert(millProfile.exists(_.obj("label").str == "ivyDeps"))
+      assert(millProfile.exists(_.obj("label").str == "javacOptions"))
+      assert(millChromeProfile.exists(_.obj("name").str == "compile"))
+      assert(millChromeProfile.exists(_.obj("name").str == "compileClasspath"))
+      assert(millChromeProfile.exists(_.obj("name").str == "ivyDeps"))
+      assert(millChromeProfile.exists(_.obj("name").str == "javacOptions"))
+      // Profile logs for show itself
+      assert(millProfile.exists(_.obj("label").str == "show"))
+      assert(millChromeProfile.exists(_.obj("name").str == "show"))
+    }
   }
 }

main/eval/src/mill/eval/Evaluator.scala

@@ -14,7 +14,7 @@ import scala.util.DynamicVariable
 /**
  * Public facing API of the Mill evaluation logic.
  */
-trait Evaluator {
+trait Evaluator extends AutoCloseable {
   def baseLogger: ColorLogger
   def rootModule: BaseModule
   def effectiveThreadCount: Int
@@ -67,6 +67,7 @@ trait Evaluator {
     r =>
       new Exception(s"Failure during task evaluation: ${formatFailing(r)}")): Evaluator.EvalOrThrow
 
+  def close() = ()
 }
 
 object Evaluator {

main/eval/src/mill/eval/EvaluatorCore.scala

@@ -5,7 +5,7 @@ import mill.api.Strict.Agg
 import mill.api._
 import mill.define._
 import mill.eval.Evaluator.TaskResult
-import mill.main.client.OutFiles._
+
 import mill.util._
 
 import java.util.concurrent.atomic.{AtomicBoolean, AtomicInteger}
@@ -18,6 +18,8 @@ import scala.concurrent._
 private[mill] trait EvaluatorCore extends GroupEvaluator {
 
   def baseLogger: ColorLogger
+  protected[eval] def chromeProfileLogger: ChromeProfileLogger
+  protected[eval] def profileLogger: ProfileLogger
 
   /**
    * @param goals The tasks that need to be evaluated
@@ -38,11 +40,7 @@ private[mill] trait EvaluatorCore extends GroupEvaluator {
         if (effectiveThreadCount == 1) ExecutionContexts.RunNow
         else new ExecutionContexts.ThreadPool(effectiveThreadCount)
 
-      def contextLoggerMsg(threadId: Int) =
-        if (effectiveThreadCount == 1) ""
-        else s"#${if (effectiveThreadCount > 9) f"$threadId%02d" else threadId} "
-
-      try evaluate0(goals, logger, reporter, testReporter, ec, contextLoggerMsg, serialCommandExec)
+      try evaluate0(goals, logger, reporter, testReporter, ec, serialCommandExec)
       finally ec.close()
     }
   }
@@ -68,12 +66,10 @@ private[mill] trait EvaluatorCore extends GroupEvaluator {
       reporter: Int => Option[CompileProblemReporter] = _ => Option.empty[CompileProblemReporter],
       testReporter: TestReporter = DummyTestReporter,
       ec: mill.api.Ctx.Fork.Impl,
-      contextLoggerMsg0: Int => String,
       serialCommandExec: Boolean
   ): Evaluator.Results = {
     os.makeDir.all(outPath)
-    val chromeProfileLogger = new ChromeProfileLogger(outPath / millChromeProfile)
-    val profileLogger = new ProfileLogger(outPath / millProfile)
+
     val threadNumberer = new ThreadNumberer()
     val (sortedGroups, transitive) = Plan.plan(goals)
     val interGroupDeps = findInterGroupDeps(sortedGroups)
@@ -240,9 +236,6 @@ private[mill] trait EvaluatorCore extends GroupEvaluator {
 
     val results: Map[Task[_], TaskResult[(Val, Int)]] = results0.toMap
 
-    chromeProfileLogger.close()
-    profileLogger.close()
-
     EvaluatorCore.Results(
       goals.indexed.map(results(_).map(_._1).result),
       // result of flatMap may contain non-distinct entries,

main/eval/src/mill/eval/EvaluatorImpl.scala

@@ -4,6 +4,7 @@ import mill.api.{CompileProblemReporter, Strict, SystemStreams, TestReporter, Va
 import mill.api.Strict.Agg
 import mill.define._
 import mill.util._
+import mill.main.client.OutFiles._
 
 import scala.collection.mutable
 import scala.reflect.ClassTag
@@ -22,16 +23,18 @@ private[mill] case class EvaluatorImpl(
     baseLogger: ColorLogger,
     classLoaderSigHash: Int,
     classLoaderIdentityHash: Int,
-    workerCache: mutable.Map[Segments, (Int, Val)] = mutable.Map.empty,
-    env: Map[String, String] = Evaluator.defaultEnv,
-    failFast: Boolean = true,
-    threadCount: Option[Int] = Some(1),
-    scriptImportGraph: Map[os.Path, (Int, Seq[os.Path])] = Map.empty,
+    workerCache: mutable.Map[Segments, (Int, Val)],
+    env: Map[String, String],
+    failFast: Boolean,
+    threadCount: Option[Int],
+    scriptImportGraph: Map[os.Path, (Int, Seq[os.Path])],
     methodCodeHashSignatures: Map[String, Int],
     override val disableCallgraph: Boolean,
     override val allowPositionalCommandArgs: Boolean,
     val systemExit: Int => Nothing,
-    val exclusiveSystemStreams: SystemStreams
+    val exclusiveSystemStreams: SystemStreams,
+    protected[eval] val chromeProfileLogger: ChromeProfileLogger,
+    protected[eval] val profileLogger: ProfileLogger
 ) extends Evaluator with EvaluatorCore {
   import EvaluatorImpl._
 
@@ -64,9 +67,56 @@ private[mill] case class EvaluatorImpl(
   override def evalOrThrow(exceptionFactory: Evaluator.Results => Throwable)
       : Evaluator.EvalOrThrow =
     new EvalOrThrow(this, exceptionFactory)
+
+  override def close(): Unit = {
+    chromeProfileLogger.close()
+    profileLogger.close()
+  }
 }
 
 private[mill] object EvaluatorImpl {
+  def make(
+      home: os.Path,
+      workspace: os.Path,
+      outPath: os.Path,
+      externalOutPath: os.Path,
+      rootModule: mill.define.BaseModule,
+      baseLogger: ColorLogger,
+      classLoaderSigHash: Int,
+      classLoaderIdentityHash: Int,
+      workerCache: mutable.Map[Segments, (Int, Val)] = mutable.Map.empty,
+      env: Map[String, String] = Evaluator.defaultEnv,
+      failFast: Boolean = true,
+      threadCount: Option[Int] = Some(1),
+      scriptImportGraph: Map[os.Path, (Int, Seq[os.Path])] = Map.empty,
+      methodCodeHashSignatures: Map[String, Int],
+      disableCallgraph: Boolean,
+      allowPositionalCommandArgs: Boolean,
+      systemExit: Int => Nothing,
+      exclusiveSystemStreams: SystemStreams
+  ) = new EvaluatorImpl(
+    home,
+    workspace,
+    outPath,
+    externalOutPath,
+    rootModule,
+    baseLogger,
+    classLoaderSigHash,
+    classLoaderIdentityHash,
+    workerCache,
+    env,
+    failFast,
+    threadCount,
+    scriptImportGraph,
+    methodCodeHashSignatures,
+    disableCallgraph,
+    allowPositionalCommandArgs,
+    systemExit,
+    exclusiveSystemStreams,
+    chromeProfileLogger = new ChromeProfileLogger(outPath / millChromeProfile),
+    profileLogger = new ProfileLogger(outPath / millProfile)
+  )
+
   class EvalOrThrow(evaluator: Evaluator, exceptionFactory: Evaluator.Results => Throwable)
       extends Evaluator.EvalOrThrow {
     def apply[T: ClassTag](task: Task[T]): T =

main/eval/src/mill/eval/JsonArrayLogger.scala

@@ -35,7 +35,7 @@ private class JsonArrayLogger[T: upickle.default.Writer](outPath: os.Path, inden
   }
 }
 
-private class ProfileLogger(outPath: os.Path)
+private[eval] class ProfileLogger(outPath: os.Path)
     extends JsonArrayLogger[ProfileLogger.Timing](outPath, indent = 2)
 
 private object ProfileLogger {
@@ -53,7 +53,7 @@ private object ProfileLogger {
   }
 }
 
-private class ChromeProfileLogger(outPath: os.Path)
+private[eval] class ChromeProfileLogger(outPath: os.Path)
     extends JsonArrayLogger[ChromeProfileLogger.TraceEvent](outPath, indent = -1) {
 
   def log(

runner/src/mill/runner/MillBuildBootstrap.scala

@@ -10,6 +10,7 @@ import mill.define.{BaseModule, Segments}
 import mill.main.client.OutFiles.{millBuild, millRunnerState}
 
 import java.net.URLClassLoader
+import scala.util.Using
 
 /**
  * Logic around bootstrapping Mill, creating a [[MillBuildRootModule.BootstrapModule]]
@@ -69,6 +70,9 @@ class MillBuildBootstrap(
   }
 
   def evaluateRec(depth: Int): RunnerState = {
+    mill.main.client.DebugLog.println(
+      "MillBuildBootstrap.evaluateRec " + depth + " " + targetsAndParams.mkString(" ")
+    )
     // println(s"+evaluateRec($depth) " + recRoot(projectRoot, depth))
     val prevFrameOpt = prevRunnerState.frames.lift(depth)
     val prevOuterFrameOpt = prevRunnerState.frames.lift(depth - 1)
@@ -153,7 +157,7 @@ class MillBuildBootstrap(
           case Some(nestedFrame) => getRootModule(nestedFrame.classLoaderOpt.get)
         }
 
-        val evaluator = makeEvaluator(
+        Using.resource(makeEvaluator(
           prevFrameOpt.map(_.workerCache).getOrElse(Map.empty),
           nestedState.frames.headOption.map(_.methodCodeHashSignatures).getOrElse(Map.empty),
           rootModule,
@@ -176,29 +180,28 @@ class MillBuildBootstrap(
             .getOrElse(0),
           depth,
           actualBuildFileName = nestedState.buildFile
-        )
-
-        if (depth != 0) {
-          val retState = processRunClasspath(
-            nestedState,
-            rootModule,
-            evaluator,
-            prevFrameOpt,
-            prevOuterFrameOpt
-          )
+        )) { evaluator =>
+          if (depth != 0) {
+            val retState = processRunClasspath(
+              nestedState,
+              rootModule,
+              evaluator,
+              prevFrameOpt,
+              prevOuterFrameOpt
+            )
 
-          if (retState.errorOpt.isEmpty && depth == requestedDepth) {
-            // TODO: print some message and indicate actual evaluated frame
-            val evalRet = processFinalTargets(nestedState, rootModule, evaluator)
-            if (evalRet.errorOpt.isEmpty) retState
-            else evalRet
-          } else
-            retState
+            if (retState.errorOpt.isEmpty && depth == requestedDepth) {
+              // TODO: print some message and indicate actual evaluated frame
+              val evalRet = processFinalTargets(nestedState, rootModule, evaluator)
+              if (evalRet.errorOpt.isEmpty) retState
+              else evalRet
+            } else
+              retState
 
-        } else {
-          processFinalTargets(nestedState, rootModule, evaluator)
+          } else {
+            processFinalTargets(nestedState, rootModule, evaluator)
+          }
         }
-
       }
     // println(s"-evaluateRec($depth) " + recRoot(projectRoot, depth))
     res
@@ -343,7 +346,7 @@ class MillBuildBootstrap(
           .mkString("/")
       )
 
-    mill.eval.EvaluatorImpl(
+    mill.eval.EvaluatorImpl.make(
       home,
       projectRoot,
       recOut(output, depth),

testkit/src/mill/testkit/IntegrationTester.scala

@@ -3,6 +3,7 @@ package mill.testkit
 import mill.main.client.EnvVars.MILL_TEST_SUITE
 import mill.define.Segments
 import mill.eval.Evaluator
+import mill.main.client.OutFiles
 import mill.resolve.SelectMode
 import ujson.Value
 
@@ -110,7 +111,7 @@ object IntegrationTester {
           mill.resolve.ParseArgs.apply(Seq(selector0), SelectMode.Separated).getOrElse(???)
 
         val segments = selector._2.getOrElse(Segments()).value.flatMap(_.pathSegments)
-        os.read(workspacePath / "out" / segments.init / s"${segments.last}.json")
+        os.read(workspacePath / OutFiles.out / segments.init / s"${segments.last}.json")
       }
 
       /**

testkit/src/mill/testkit/UnitTester.scala

@@ -86,7 +86,7 @@ class UnitTester(
     override def debug(s: String): Unit = super.debug(s"${prefix}: ${s}")
     override def ticker(s: String): Unit = super.ticker(s"${prefix}: ${s}")
   }
-  val evaluator: EvaluatorImpl = mill.eval.EvaluatorImpl(
+  val evaluator: EvaluatorImpl = mill.eval.EvaluatorImpl.make(
     mill.api.Ctx.defaultHome,
     module.millSourcePath,
     outPath,
@@ -192,5 +192,6 @@ class UnitTester(
     for (case (_, Val(obsolete: AutoCloseable)) <- evaluator.workerCache.values) {
       obsolete.close()
     }
+    evaluator.close()
   }
 }