chore: tweak logging and profiling (#6529)

* chore: remove noisy logging Removed log line could produce duplicate logs entries for config files located in the same directory. That looked confusing and non-informative. * chore: formatting in tech notes * refactor: extract local variable * chore: extra logging * refactor: extract function `addConfig` * refactor: rename function `addConfig` to `addActionConfig` * refactor: extracted named type `ComputedActionMode` * chore: extra debug logging * chore: more detailed profiling * chore: profile repo roots cache hits/misses
garden-io · Oct 10, 2024 · b556571 · b556571
1 parent 07a577e
commit b556571
Show file tree

Hide file tree

Showing 5 changed files with 85 additions and 42 deletions.
diff --git a/core/src/cache.ts b/core/src/cache.ts
@@ -148,10 +148,9 @@ export class TreeCache {
     if (entry) {
       log.silly(() => `TreeCache: Found cached value for key ${stringKey}`)
       return entry.value
-    } else {
-      log.silly(() => `TreeCache: No cached value for key ${stringKey}`)
-      return
     }
+
+    return undefined
   }
 
   getOrThrow(log: Log, key: CacheKey): CacheValue {

diff --git a/core/src/garden.ts b/core/src/garden.ts
@@ -1074,18 +1074,18 @@ export class Garden {
     )
 
     // Get action configs
-    const actionConfigs: ActionConfigsByKey = {}
+    const actionConfigsByKey: ActionConfigsByKey = {}
 
     for (const kind of actionKinds) {
       for (const name in this.actionConfigs[kind]) {
         const key = actionReferenceToString({ kind, name })
-        actionConfigs[key] = this.actionConfigs[kind][name]
+        actionConfigsByKey[key] = this.actionConfigs[kind][name]
       }
     }
 
     for (const config of moduleActionConfigs) {
       const key = actionReferenceToString(config)
-      const existing = actionConfigs[key]
+      const existing = actionConfigsByKey[key]
 
       if (existing) {
         const moduleActionPath = config.internal.configFilePath || config.internal.basePath
@@ -1095,15 +1095,16 @@ export class Garden {
         })
       }
 
-      actionConfigs[key] = config
+      actionConfigsByKey[key] = config
     }
 
     // Resolve configs to Actions
     const linkedSources = keyBy(await getLinkedSources(this, "action"), "name")
 
+    const actionConfigs = Object.values(actionConfigsByKey)
     const graph = await actionConfigsToGraph({
       garden: this,
-      configs: Object.values(actionConfigs),
+      configs: actionConfigs,
       groupConfigs: moduleGroups,
       log: graphLog,
       moduleGraph,
@@ -1161,14 +1162,14 @@ export class Garden {
             config,
             router,
             log: graphLog,
-            configsByKey: actionConfigs,
+            configsByKey: actionConfigsByKey,
             mode: actionModes[key] || "default",
             linkedSources,
             scanRoot: config.internal.basePath,
           })
 
           graph.addAction(action)
-          actionConfigs[key] = config
+          actionConfigsByKey[key] = config
 
           updated = true
         })

diff --git a/core/src/graph/actions.ts b/core/src/graph/actions.ts
@@ -70,6 +70,39 @@ import { getSourcePath } from "../vcs/vcs.js"
 import { actionIsDisabled } from "../actions/base.js"
 import { styles } from "../logger/styles.js"
 
+function addActionConfig({
+  garden,
+  log,
+  config,
+  collector,
+}: {
+  garden: Garden
+  log: Log
+  config: ActionConfig
+  collector: ActionConfigsByKey
+}) {
+  if (!actionKinds.includes(config.kind)) {
+    throw new ConfigurationError({ message: `Unknown action kind: ${config.kind}` })
+  }
+
+  const key = actionReferenceToString(config)
+  const existing = collector[key]
+
+  if (existing) {
+    if (actionIsDisabled(config, garden.environmentName)) {
+      log.silly(() => `Skipping disabled action ${key} in favor of other action with same key`)
+      return
+    } else if (actionIsDisabled(existing, garden.environmentName)) {
+      log.silly(() => `Skipping disabled action ${key} in favor of other action with same key`)
+      collector[key] = config
+      return
+    } else {
+      throw actionNameConflictError(existing, config, garden.projectRoot)
+    }
+  }
+  collector[key] = config
+}
+
 export const actionConfigsToGraph = profileAsync(async function actionConfigsToGraph({
   garden,
   log,
@@ -89,33 +122,14 @@ export const actionConfigsToGraph = profileAsync(async function actionConfigsToG
   linkedSources: LinkedSourceMap
   actionsFilter?: string[]
 }): Promise<MutableConfigGraph> {
-  const configsByKey: ActionConfigsByKey = {}
+  log.debug(`Building graph from ${configs.length} action configs and ${groupConfigs.length} group configs`)
 
-  function addConfig(config: ActionConfig) {
-    if (!actionKinds.includes(config.kind)) {
-      throw new ConfigurationError({ message: `Unknown action kind: ${config.kind}` })
-    }
+  const configsByKey: ActionConfigsByKey = {}
 
-    const key = actionReferenceToString(config)
-    const existing = configsByKey[key]
-
-    if (existing) {
-      if (actionIsDisabled(config, garden.environmentName)) {
-        log.silly(() => `Skipping disabled action ${key} in favor of other action with same key`)
-        return
-      } else if (actionIsDisabled(existing, garden.environmentName)) {
-        log.silly(() => `Skipping disabled action ${key} in favor of other action with same key`)
-        configsByKey[key] = config
-        return
-      } else {
-        throw actionNameConflictError(existing, config, garden.projectRoot)
-      }
-    }
-    configsByKey[key] = config
+  for (const config of configs) {
+    addActionConfig({ garden, log, config, collector: configsByKey })
   }
 
-  configs.forEach(addConfig)
-
   for (const group of groupConfigs) {
     for (const config of group.actions) {
       config.internal.groupName = group.name
@@ -124,10 +138,12 @@ export const actionConfigsToGraph = profileAsync(async function actionConfigsToG
         config.internal.configFilePath = group.internal.configFilePath
       }
 
-      addConfig(config)
+      addActionConfig({ garden, log, config, collector: configsByKey })
     }
   }
 
+  log.debug(`Retained ${Object.keys(configsByKey).length} configs`)
+
   const router = await garden.getActionRouter()
 
   // We need to preprocess the action configs to make sure any template strings have been resolved on the `source.path`
@@ -137,7 +153,7 @@ export const actionConfigsToGraph = profileAsync(async function actionConfigsToG
   //
   // Doing this in two steps makes the code a bit less readable, but it's worth it for the performance boost.
   const preprocessResults: { [key: string]: PreprocessActionResult } = {}
-  const computedActionModes: { [key: string]: { mode: ActionMode; explicitMode: boolean } } = {}
+  const computedActionModes: { [key: string]: ComputedActionMode } = {}
 
   const preprocessActions = async (predicate: (config: ActionConfig) => boolean = () => true) => {
     return await Promise.all(
@@ -166,7 +182,9 @@ export const actionConfigsToGraph = profileAsync(async function actionConfigsToG
   }
 
   // First preprocess only the Deploy actions, so we can infer the mode of Build actions that are used by them.
+  log.debug(`Preprocessing Deploy action configs...`)
   await preprocessActions((config) => config.kind === "Deploy")
+  log.debug(`Preprocessed Deploy action configs`)
 
   // This enables users to use `this.mode` in Build action configs, such that `this.mode == "sync"`
   // when a Deploy action that uses the Build action is in sync mode.
@@ -196,10 +214,13 @@ export const actionConfigsToGraph = profileAsync(async function actionConfigsToG
 
   // Preprocess all remaining actions (Deploy actions are preprocessed above)
   // We are preprocessing actions in two batches so we can infer the mode of Build actions that are used by Deploy actions. See the comments above.
+  log.debug(`Preprocessing non-Deploy action configs...`)
   await preprocessActions((config) => config.kind !== "Deploy")
+  log.debug(`Preprocessed non-Deploy action configs`)
 
   // Apply actionsFilter if provided to avoid unnecessary VCS scanning and resolution
   if (actionsFilter) {
+    log.debug(`Applying action filter...`)
     const depGraph = new DependencyGraph<string>()
 
     for (const [key, res] of Object.entries(preprocessResults)) {
@@ -235,12 +256,18 @@ export const actionConfigsToGraph = profileAsync(async function actionConfigsToG
         delete preprocessResults[key]
       }
     }
+
+    log.debug(`Applied action filter`)
   }
 
-  // Optimize file scanning by avoiding unnecessarily broad scans when project is not in repo root.
   const preprocessedConfigs = Object.values(preprocessResults).map((r) => r.config)
+  log.debug(`Got ${preprocessedConfigs.length} action configs ${!!actionsFilter ? "with" : "without"} action filter`)
+
+  // Optimize file scanning by avoiding unnecessarily broad scans when project is not in repo root.
   const allPaths = preprocessedConfigs.map((c) => getSourcePath(c))
+  log.debug(`Finding minimal roots for ${allPaths.length} paths`)
   const minimalRoots = await garden.vcs.getMinimalRoots(log, allPaths)
+  log.debug(`Finding minimal roots for ${allPaths.length} paths`)
 
   // TODO: Maybe we could optimize resolving tree versions, avoid parallel scanning of the same directory etc.
   const graph = new MutableConfigGraph({
@@ -250,6 +277,7 @@ export const actionConfigsToGraph = profileAsync(async function actionConfigsToG
     groups: groupConfigs,
   })
 
+  log.debug(`Processing ${Object.keys(preprocessResults).length} action configs...`)
   await Promise.all(
     Object.entries(preprocessResults).map(async ([key, res]) => {
       const { config, linkedSource, remoteSourcePath, supportedModes, dependencies } = res
@@ -293,8 +321,11 @@ export const actionConfigsToGraph = profileAsync(async function actionConfigsToG
       }
     })
   )
+  log.debug(`Processed ${Object.keys(preprocessResults).length} action configs`)
 
+  log.debug(`Validating the graph`)
   graph.validate()
+  log.debug(`Validation is done.`)
 
   return graph
 })
@@ -384,7 +415,7 @@ export const actionFromConfig = profileAsync(async function actionFromConfig({
   })
 })
 
-async function processActionConfig({
+export const processActionConfig = profileAsync(async function processActionConfig({
   garden,
   graph,
   config,
@@ -504,7 +535,7 @@ async function processActionConfig({
   } else {
     return config satisfies never
   }
-}
+})
 
 export function actionNameConflictError(configA: ActionConfig, configB: ActionConfig, rootPath: string) {
   return new ConfigurationError({
@@ -655,6 +686,11 @@ interface PreprocessActionResult {
   linkedSource: LinkedSource | null
 }
 
+interface ComputedActionMode {
+  mode: ActionMode
+  explicitMode: boolean
+}
+
 export const preprocessActionConfig = profileAsync(async function preprocessActionConfig({
   garden,
   config,

diff --git a/core/src/graph/notes.md b/core/src/graph/notes.md
@@ -3,12 +3,16 @@
 Actions exist in three stages:
 
 **The base**
-Partially resolved without dependencies resolved, and `variables` and the type-specific `spec` fields only partially resolved. This is what's in ConfigGraph upon resolution.
+Partially resolved without dependencies resolved, and `variables` and the type-specific `spec` fields only partially
+resolved. This is what's in `ConfigGraph` upon resolution.
 
 **Resolved**
-Fully resolved in terms of its configuration, variables, and all its dependencies, but does not have all outputs available. This is enough to call e.g. getStatus, build, deploy handlers.
+Fully resolved in terms of its configuration, variables, and all its dependencies, but does not have all outputs
+available. This is enough to call e.g. `getStatus`, `build`, `deploy` handlers.
 
 **Executed**
-Includes runtime outputs that are only available after building, deploying etc. These are necessary to resolve dependencies that reference action outputs.
+Includes runtime outputs that are only available after building, deploying etc. These are necessary to resolve
+dependencies that reference action outputs.
 
-The "do" tasks (BuildTask, DeployTask etc.) for each action kind, plus DeleteDeployTask, are the only ones that don't require a action
+The "do" tasks (`BuildTask`, `DeployTask` etc.) for each action kind, plus `DeleteDeployTask`, are the only ones that
+don't require an action.
diff --git a/core/src/vcs/git.ts b/core/src/vcs/git.ts
@@ -156,20 +156,23 @@ export abstract class AbstractGitHandler extends VcsHandler {
   async getRepoRoot(log: Log, path: string, failOnPrompt = false): Promise<string> {
     let cachedRepoRoot = this.repoRoots.get(path)
     if (!!cachedRepoRoot) {
+      this.profiler.inc("GitHandler.RepoRoots.hits")
       return cachedRepoRoot
     }
 
     // Make sure we're not asking concurrently for the same root
     return this.lock.acquire(`repo-root:${path}`, async () => {
       cachedRepoRoot = this.repoRoots.get(path)
       if (!!cachedRepoRoot) {
+        this.profiler.inc("GitHandler.RepoRoots.hits")
         return cachedRepoRoot
       }
 
       try {
         const git = new GitCli({ log, cwd: path, failOnPrompt })
         const repoRoot = await git.getRepositoryRoot()
         this.repoRoots.set(path, repoRoot)
+        this.profiler.inc("GitHandler.RepoRoots.misses")
         return repoRoot
       } catch (err) {
         if (!(err instanceof ChildProcessError)) {