Add perf logs

This commit is contained in:
Eugene Yokota 2016-05-25 01:11:47 -04:00
parent c1648ac0a5
commit f523b9da0d
2 changed files with 123 additions and 82 deletions

View File

@ -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
}
}

View File

@ -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(