diff --git a/main/src/main/scala/sbt/Plugins.scala b/main/src/main/scala/sbt/Plugins.scala index 90a6c8f66..8177aa0ab 100644 --- a/main/src/main/scala/sbt/Plugins.scala +++ b/main/src/main/scala/sbt/Plugins.scala @@ -175,36 +175,38 @@ object Plugins extends PluginsFunctions { // Note: Here is where the function begins. We're given a list of plugins now. (requestedPlugins, log) => { - def explicitlyDisabled(p: AutoPlugin): Boolean = hasExclude(requestedPlugins, p) - val alwaysEnabled: List[AutoPlugin] = defined.filter(_.isAlwaysEnabled).filterNot(explicitlyDisabled) - val knowlege0: Set[Atom] = ((flatten(requestedPlugins) ++ alwaysEnabled) collect { - case x: AutoPlugin => Atom(x.label) - }).toSet - val clauses = Clauses((allRequirementsClause ::: allEnabledByClause) filterNot { _.head subsetOf knowlege0 }) - log.debug(s"deducing auto plugins based on known facts ${knowlege0.toString} and clauses ${clauses.toString}") - Logic.reduce(clauses, (flattenConvert(requestedPlugins) ++ convertAll(alwaysEnabled)).toSet) match { - case Left(problem) => throw AutoPluginException(problem) - case Right(results) => - log.debug(s" :: deduced result: ${results}") - val selectedAtoms: List[Atom] = results.ordered - val selectedPlugins = selectedAtoms map { a => - byAtomMap.getOrElse(a, throw AutoPluginException(s"${a} was not found in atom map.")) - } - val forbidden: Set[AutoPlugin] = (selectedPlugins flatMap { Plugins.asExclusions }).toSet - val c = selectedPlugins.toSet & forbidden - if (c.nonEmpty) { - exlusionConflictError(requestedPlugins, selectedPlugins, c.toSeq sortBy { _.label }) - } - val retval = topologicalSort(selectedPlugins, log) - log.debug(s" :: sorted deduced result: ${retval.toString}") - retval + timed("Plugins.deducer#function", log) { + def explicitlyDisabled(p: AutoPlugin): Boolean = hasExclude(requestedPlugins, p) + val alwaysEnabled: List[AutoPlugin] = defined.filter(_.isAlwaysEnabled).filterNot(explicitlyDisabled) + val knowlege0: Set[Atom] = ((flatten(requestedPlugins) ++ alwaysEnabled) collect { + case x: AutoPlugin => Atom(x.label) + }).toSet + val clauses = Clauses((allRequirementsClause ::: allEnabledByClause) filterNot { _.head subsetOf knowlege0 }) + log.debug(s"deducing auto plugins based on known facts ${knowlege0.toString} and clauses ${clauses.toString}") + Logic.reduce(clauses, (flattenConvert(requestedPlugins) ++ convertAll(alwaysEnabled)).toSet) match { + case Left(problem) => throw AutoPluginException(problem) + case Right(results) => + log.debug(s" :: deduced result: ${results}") + val selectedAtoms: List[Atom] = results.ordered + val selectedPlugins = selectedAtoms map { a => + byAtomMap.getOrElse(a, throw AutoPluginException(s"${a} was not found in atom map.")) + } + val forbidden: Set[AutoPlugin] = (selectedPlugins flatMap { Plugins.asExclusions }).toSet + val c = selectedPlugins.toSet & forbidden + if (c.nonEmpty) { + exlusionConflictError(requestedPlugins, selectedPlugins, c.toSeq sortBy { _.label }) + } + val retval = topologicalSort(selectedPlugins, log) + // log.debug(s" :: sorted deduced result: ${retval.toString}") + retval + } } } } private[sbt] def topologicalSort(ns: List[AutoPlugin], log: Logger): List[AutoPlugin] = { - log.debug(s"sorting: ns: ${ns.toString}") + // log.debug(s"sorting: ns: ${ns.toString}") @tailrec def doSort(found0: List[AutoPlugin], notFound0: List[AutoPlugin], limit0: Int): List[AutoPlugin] = { - log.debug(s" :: sorting:: found: ${found0.toString} not found ${notFound0.toString}") + // log.debug(s" :: sorting:: found: ${found0.toString} not found ${notFound0.toString}") if (limit0 < 0) throw AutoPluginException(s"Failed to sort ${ns} topologically") else if (notFound0.isEmpty) found0 else { @@ -360,4 +362,13 @@ ${listConflicts(conflicting)}""") } hasGetterOpt getOrElse false } + + /** Debugging method to time how long it takes to run various compilation tasks. */ + private[this] def timed[T](label: String, log: Logger)(t: => T): T = { + val start = System.nanoTime + val result = t + val elapsed = System.nanoTime - start + log.debug(label + " took " + (elapsed / 1e6) + " ms") + result + } } diff --git a/main/src/main/scala/sbt/internal/Load.scala b/main/src/main/scala/sbt/internal/Load.scala index 4c77a5731..b2b70f1c1 100755 --- a/main/src/main/scala/sbt/internal/Load.scala +++ b/main/src/main/scala/sbt/internal/Load.scala @@ -50,14 +50,18 @@ private[sbt] object Load { // note that there is State passed in but not pulled out def defaultLoad(state: State, baseDirectory: File, log: Logger, isPlugin: Boolean = false, topLevelExtras: List[URI] = Nil): (() => Eval, BuildStructure) = { - val globalBase = getGlobalBase(state) - val base = baseDirectory.getCanonicalFile - val rawConfig = defaultPreGlobal(state, base, globalBase, log) - val config0 = defaultWithGlobal(state, base, rawConfig, globalBase, log) - val config = if (isPlugin) enableSbtPlugin(config0) else config0.copy(extraBuilds = topLevelExtras) + val (base, config) = timed("Load.defaultLoad until apply", log) { + val globalBase = getGlobalBase(state) + val base = baseDirectory.getCanonicalFile + val rawConfig = defaultPreGlobal(state, base, globalBase, log) + val config0 = defaultWithGlobal(state, base, rawConfig, globalBase, log) + val config = if (isPlugin) enableSbtPlugin(config0) else config0.copy(extraBuilds = topLevelExtras) + (base, config) + } val result = apply(base, state, config) result } + def defaultPreGlobal(state: State, baseDirectory: File, globalBase: File, log: Logger): LoadBuildConfiguration = { val provider = state.configuration.provider @@ -158,16 +162,27 @@ private[sbt] object Load { // 8) Evaluate settings def apply(rootBase: File, s: State, config: LoadBuildConfiguration): (() => Eval, BuildStructure) = { + val log = config.log + // load, which includes some resolution, but can't fill in project IDs yet, so follow with full resolution - val loaded = resolveProjects(load(rootBase, s, config)) + val partBuild = timed("Load.apply: load", log) { load(rootBase, s, config) } + val loaded = timed("Load.apply: resolveProjects", log) { + resolveProjects(partBuild) + } val projects = loaded.units lazy val rootEval = lazyEval(loaded.units(loaded.root).unit) - val settings = finalTransforms(buildConfigurations(loaded, getRootProject(projects), config.injectSettings)) - val delegates = config.delegates(loaded) - val data = Def.make(settings)(delegates, config.scopeLocal, Project.showLoadingKey(loaded)) + val settings = timed("Load.apply: finalTransforms", log) { + finalTransforms(buildConfigurations(loaded, getRootProject(projects), config.injectSettings)) + } + val delegates = timed("Load.apply: config.delegates", log) { config.delegates(loaded) } + val data = timed("Load.apply: Def.make(settings)...", log) { + Def.make(settings)(delegates, config.scopeLocal, Project.showLoadingKey(loaded)) + } Project.checkTargets(data) foreach sys.error - val index = structureIndex(data, settings, loaded.extra(data), projects) - val streams = mkStreams(projects, loaded.root, data) + val index = timed("Load.apply: structureIndex", log) { + structureIndex(data, settings, loaded.extra(data), projects) + } + val streams = timed("Load.apply: mkStreams", log) { mkStreams(projects, loaded.root, data) } (rootEval, new BuildStructure(projects, loaded.root, settings, data, index, streams, delegates, config.scopeLocal)) } @@ -298,13 +313,15 @@ private[sbt] object Load { { val fail = (uri: URI) => sys.error("Invalid build URI (no handler available): " + uri) val resolver = (info: BuildLoader.ResolveInfo) => RetrieveUnit(info) - val build = (info: BuildLoader.BuildInfo) => Some(() => loadUnit(info.uri, info.base, info.state, info.config)) + val build = (info: BuildLoader.BuildInfo) => Some(() => + loadUnit(info.uri, info.base, info.state, info.config)) val components = BuildLoader.components(resolver, build, full = BuildLoader.componentLoader) BuildLoader(components, fail, s, config) } def load(file: File, loaders: BuildLoader, extra: List[URI]): PartBuild = loadURI(IO.directoryURI(file), loaders, extra) def loadURI(uri: URI, loaders: BuildLoader, extra: List[URI]): PartBuild = { + val log = loaders.config.log IO.assertAbsolute(uri) val (referenced, map, newLoaders) = loadAll(uri :: extra, Map.empty, loaders, Map.empty) checkAll(referenced, map) @@ -445,20 +462,23 @@ private[sbt] object Load { def noProject(uri: URI, id: String) = sys.error(s"No project '$id' defined in '$uri'.") def noConfiguration(uri: URI, id: String, conf: String) = sys.error(s"No configuration '$conf' defined in project '$id' in '$uri'") + // Called from builtinLoader def loadUnit(uri: URI, localBase: File, s: State, config: LoadBuildConfiguration): BuildUnit = - { + timed(s"Load.loadUnit($uri, ...)", config.log) { + val log = config.log val normBase = localBase.getCanonicalFile val defDir = projectStandard(normBase) - val plugs = plugins(defDir, s, config.copy(pluginManagement = config.pluginManagement.forPlugin)) - val defsScala = plugs.detected.builds.values - val buildLevelExtraProjects = plugs.detected.autoPlugins flatMap { d => - d.value.extraProjects map { _.setProjectOrigin(ProjectOrigin.ExtraProject) } + val plugs = timed("Load.loadUnit: plugins", log) { + plugins(defDir, s, config.copy(pluginManagement = config.pluginManagement.forPlugin)) + } + val defsScala = timed("Load.loadUnit: defsScala", log) { + plugs.detected.builds.values } // NOTE - because we create an eval here, we need a clean-eval later for this URI. - lazy val eval = mkEval(plugs.classpath, defDir, plugs.pluginData.scalacOptions) - val initialProjects = defsScala.flatMap(b => projectsFromBuild(b, normBase)) ++ buildLevelExtraProjects + lazy val eval = timed("Load.loadUnit: mkEval", log) { mkEval(plugs.classpath, defDir, plugs.pluginData.scalacOptions) } + val initialProjects = defsScala.flatMap(b => projectsFromBuild(b, normBase)) val hasRootAlreadyDefined = defsScala.exists(_.rootProject.isDefined) @@ -467,8 +487,7 @@ private[sbt] object Load { val result = loadTransitive(ps, normBase, plugs, () => eval, config.injectSettings, Nil, memoSettings, config.log, createRoot, uri, config.pluginManagement.context, Nil) result } - - val loadedProjectsRaw = loadProjects(initialProjects, !hasRootAlreadyDefined) + val loadedProjectsRaw = timed("Load.loadUnit: loadedProjectsRaw", log) { loadProjects(initialProjects, !hasRootAlreadyDefined) } // TODO - As of sbt 0.13.6 we should always have a default root project from // here on, so the autogenerated build aggregated can be removed from this code. ( I think) // We may actually want to move it back here and have different flags in loadTransitive... @@ -481,13 +500,14 @@ private[sbt] object Load { val refs = existingIDs.map(id => ProjectRef(uri, id)) val defaultID = autoID(normBase, config.pluginManagement.context, existingIDs) val b = BuildDef.defaultAggregated(defaultID, refs) - val defaultProjects = loadProjects(projectsFromBuild(b, normBase), false) + val defaultProjects = timed("Load.loadUnit: defaultProjects", log) { loadProjects(projectsFromBuild(b, normBase), false) } (defaultProjects.projects ++ loadedProjectsRaw.projects, b, defaultProjects.generatedConfigClassFiles ++ loadedProjectsRaw.generatedConfigClassFiles) } // Now we clean stale class files. // TODO - this may cause issues with multiple sbt clients, but that should be deprecated pending sbt-server anyway - cleanEvalClasses(defDir, keepClassFiles) - + timed("Load.loadUnit: cleanEvalClasses", log) { + cleanEvalClasses(defDir, keepClassFiles) + } val defs = if (defsScala.isEmpty) defaultBuildIfNone :: Nil else defsScala // HERE we pull out the defined vals from memoSettings and unify them all so // we can use them later. @@ -565,7 +585,7 @@ private[sbt] object Load { context: PluginManagement.Context, generatedConfigClassFiles: Seq[File] ): LoadedProjects = - { + /*timed(s"Load.loadTransitive(${ newProjects.map(_.id) })", log)*/ { // load all relevant configuration files (.sbt, as .scala already exists at this point) def discover(auto: AddSettings, base: File): DiscoveredProjects = discoverProjects(auto, base, plugins, eval, memoSettings) @@ -615,7 +635,7 @@ private[sbt] object Load { discover(AddSettings.defaultSbtFiles, buildBase) match { case DiscoveredProjects(Some(root), discovered, files, generated) => log.debug(s"[Loading] Found root project ${root.id} w/ remaining ${discovered.map(_.id).mkString(",")}") - val (finalRoot, projectLevelExtra) = finalizeProject(root, files, true) + val (finalRoot, projectLevelExtra) = timed(s"Load.loadTransitive: finalizeProject($root)", log) { finalizeProject(root, files, true) } loadTransitive(discovered ++ projectLevelExtra, buildBase, plugins, eval, injectSettings, finalRoot +: acc, memoSettings, log, false, buildUri, context, generated ++ generatedConfigClassFiles) // Here we need to create a root project... case DiscoveredProjects(None, discovered, files, generated) => @@ -628,7 +648,7 @@ private[sbt] object Load { val defaultID = autoID(buildBase, context, existingIds) val root0 = if (discovered.isEmpty || java.lang.Boolean.getBoolean("sbt.root.ivyplugin")) BuildDef.defaultAggregatedProject(defaultID, buildBase, refs) else BuildDef.generatedRootWithoutIvyPlugin(defaultID, buildBase, refs) - val (root, _) = finalizeProject(root0, files, false) + val (root, _) = timed(s"Load.loadTransitive: finalizeProject2($root0)", log) { finalizeProject(root0, files, false) } val result = root +: (acc ++ otherProjects.projects) log.debug(s"[Loading] Done in ${buildBase}, returning: ${result.map(_.id).mkString("(", ", ", ")")}") LoadedProjects(result, generated ++ otherGenerated ++ generatedConfigClassFiles) @@ -679,39 +699,40 @@ private[sbt] object Load { globalUserSettings: InjectSettings, memoSettings: mutable.Map[File, LoadedSbtFile], log: Logger - ): Project = { - import AddSettings._ - val autoConfigs = projectPlugins.flatMap(_.projectConfigurations) + ): Project = + timed(s"Load.resolveProject(${p.id})", log) { + import AddSettings._ + val autoConfigs = projectPlugins.flatMap(_.projectConfigurations) - // 3. Use AddSettings instance to order all Setting[_]s appropriately - val allSettings = { - // TODO - This mechanism of applying settings could be off... It's in two places now... - lazy val defaultSbtFiles = configurationSources(p.base) - // Filter the AutoPlugin settings we included based on which ones are - // intended in the AddSettings.AutoPlugins filter. - def autoPluginSettings(f: AutoPlugins) = - projectPlugins.filter(f.include).flatMap(_.projectSettings) - // Grab all the settigns we already loaded from sbt files - def settings(files: Seq[File]): Seq[Setting[_]] = - for { - file <- files - config <- (memoSettings get file).toSeq - setting <- config.settings - } yield setting - // Expand the AddSettings instance into a real Seq[Setting[_]] we'll use on the project - def expandSettings(auto: AddSettings): Seq[Setting[_]] = auto match { - case BuildScalaFiles => p.settings - case User => globalUserSettings.projectLoaded(loadedPlugins.loader) - case sf: SbtFiles => settings(sf.files.map(f => IO.resolve(p.base, f))) - case sf: DefaultSbtFiles => settings(defaultSbtFiles.filter(sf.include)) - case p: AutoPlugins => autoPluginSettings(p) - case q: Sequence => (Seq.empty[Setting[_]] /: q.sequence) { (b, add) => b ++ expandSettings(add) } + // 3. Use AddSettings instance to order all Setting[_]s appropriately + val allSettings = { + // TODO - This mechanism of applying settings could be off... It's in two places now... + lazy val defaultSbtFiles = configurationSources(p.base) + // Filter the AutoPlugin settings we included based on which ones are + // intended in the AddSettings.AutoPlugins filter. + def autoPluginSettings(f: AutoPlugins) = + projectPlugins.filter(f.include).flatMap(_.projectSettings) + // Grab all the settigns we already loaded from sbt files + def settings(files: Seq[File]): Seq[Setting[_]] = + for { + file <- files + config <- (memoSettings get file).toSeq + setting <- config.settings + } yield setting + // Expand the AddSettings instance into a real Seq[Setting[_]] we'll use on the project + def expandSettings(auto: AddSettings): Seq[Setting[_]] = auto match { + case BuildScalaFiles => p.settings + case User => globalUserSettings.projectLoaded(loadedPlugins.loader) + case sf: SbtFiles => settings(sf.files.map(f => IO.resolve(p.base, f))) + case sf: DefaultSbtFiles => settings(defaultSbtFiles.filter(sf.include)) + case p: AutoPlugins => autoPluginSettings(p) + case q: Sequence => (Seq.empty[Setting[_]] /: q.sequence) { (b, add) => b ++ expandSettings(add) } + } + expandSettings(p.auto) } - expandSettings(p.auto) + // Finally, a project we can use in buildStructure. + p.copy(settingsEval = Ev.later(allSettings)).setAutoPlugins(projectPlugins).prefixConfigs(autoConfigs: _*) } - // Finally, a project we can use in buildStructure. - p.copy(settingsEval = Ev.later(allSettings)).setAutoPlugins(projectPlugins).prefixConfigs(autoConfigs: _*) - } /** * This method attempts to discover all Project/settings it can using the configured AddSettings and project base. @@ -921,6 +942,15 @@ private[sbt] object Load { @deprecated("Use BuildUtil.apply", "0.13.0") def buildUtil(root: URI, units: Map[URI, LoadedBuildUnit], keyIndex: KeyIndex, data: Settings[Scope]): BuildUtil[ResolvedProject] = BuildUtil(root, units, keyIndex, data) + + /** Debugging method to time how long it takes to run various compilation tasks. */ + private[sbt] def timed[T](label: String, log: Logger)(t: => T): T = { + val start = System.nanoTime + val result = t + val elapsed = System.nanoTime - start + log.debug(label + " took " + (elapsed / 1e6) + " ms") + result + } } final case class LoadBuildConfiguration(