From b556571d7926e408187b682ac111a99999cef815 Mon Sep 17 00:00:00 2001 From: Vladimir Vagaytsev <10628074+vvagaytsev@users.noreply.github.com> Date: Thu, 10 Oct 2024 17:53:43 +0200 Subject: [PATCH] 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 --- core/src/cache.ts | 5 +-- core/src/garden.ts | 15 ++++--- core/src/graph/actions.ts | 92 +++++++++++++++++++++++++++------------ core/src/graph/notes.md | 12 +++-- core/src/vcs/git.ts | 3 ++ 5 files changed, 85 insertions(+), 42 deletions(-) diff --git a/core/src/cache.ts b/core/src/cache.ts index 047724a1e9..7fbefd16de 100644 --- 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 index 5c10daf814..ee9d96e960 100644 --- 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 index 9ea2ace746..978964ddac 100644 --- 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 { - 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() 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 index 686a1bfb0c..e6967e7bb9 100644 --- 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 index 089f922f7d..8c78066cc5 100644 --- a/core/src/vcs/git.ts +++ b/core/src/vcs/git.ts @@ -156,6 +156,7 @@ export abstract class AbstractGitHandler extends VcsHandler { async getRepoRoot(log: Log, path: string, failOnPrompt = false): Promise { let cachedRepoRoot = this.repoRoots.get(path) if (!!cachedRepoRoot) { + this.profiler.inc("GitHandler.RepoRoots.hits") return cachedRepoRoot } @@ -163,6 +164,7 @@ export abstract class AbstractGitHandler extends VcsHandler { return this.lock.acquire(`repo-root:${path}`, async () => { cachedRepoRoot = this.repoRoots.get(path) if (!!cachedRepoRoot) { + this.profiler.inc("GitHandler.RepoRoots.hits") return cachedRepoRoot } @@ -170,6 +172,7 @@ export abstract class AbstractGitHandler extends VcsHandler { 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)) {