From b79508c3d27fd80f6f82d009d28ab76197d21fa0 Mon Sep 17 00:00:00 2001 From: Vladimir Vagaytsev <10628074+vvagaytsev@users.noreply.github.com> Date: Fri, 18 Oct 2024 07:44:40 +0200 Subject: [PATCH 1/5] chore: remove excessive logging Revert some changes from #6553 --- core/src/graph/actions.ts | 11 ----------- 1 file changed, 11 deletions(-) diff --git a/core/src/graph/actions.ts b/core/src/graph/actions.ts index b8426fd9bd..2937d8d700 100644 --- a/core/src/graph/actions.ts +++ b/core/src/graph/actions.ts @@ -741,21 +741,18 @@ export const preprocessActionConfig = profileAsync(async function preprocessActi actionTypes: ActionDefinitionMap }): Promise { const actionKey = actionReferenceToString(config) - log.debug(`Preprocessing action ${actionKey}...`) const description = describeActionConfig(config) const templateName = config.internal.templateName // in pre-processing, only use varfiles that are not template strings const resolvedVarFiles = config.varfiles?.filter((f) => !maybeTemplateString(getVarfileData(f).path)) - log.debug(`Merging variables...`) const variables = await mergeVariables({ basePath: config.internal.basePath, variables: config.variables, varfiles: resolvedVarFiles, }) - log.debug(`Resolving variables (partially)...`) const resolvedVariables = resolveTemplateStrings({ value: variables, context: new ActionConfigContext({ @@ -773,7 +770,6 @@ export const preprocessActionConfig = profileAsync(async function preprocessActi }) if (templateName) { - log.debug(`Resolving inputs (partially)...`) // Partially resolve inputs const partiallyResolvedInputs = resolveTemplateStrings({ value: config.internal.inputs || {}, @@ -871,12 +867,9 @@ export const preprocessActionConfig = profileAsync(async function preprocessActi config = { ...config, ...resolvedOther } } - log.debug(`Resolving templates...`) resolveTemplates() - log.debug(`Configuring action...`) const configureActionResult = await router.configureAction({ config, log }) - log.debug(`Action configured`) const { config: updatedConfig } = configureActionResult @@ -913,7 +906,6 @@ export const preprocessActionConfig = profileAsync(async function preprocessActi // -> Resolve templates again after configure handler // TODO: avoid this if nothing changed in the configure handler - log.debug(`Resolving templates again (for configured action)...`) try { resolveTemplates() } catch (error) { @@ -936,7 +928,6 @@ export const preprocessActionConfig = profileAsync(async function preprocessActi remoteSourcePath = config.internal.remoteClonePath } else { const key = actionReferenceToString(config) - log.debug(`Resolving external sources...`) remoteSourcePath = await garden.resolveExtSourcePath({ name: key, sourceType: "action", @@ -952,7 +943,6 @@ export const preprocessActionConfig = profileAsync(async function preprocessActi } } - log.debug(`Collecting dependencies...`) const dependencies = dependenciesFromActionConfig({ log, config, @@ -962,7 +952,6 @@ export const preprocessActionConfig = profileAsync(async function preprocessActi actionTypes, }) - log.debug(`Preprocessed action ${actionKey}...`) return { config, dependencies, From 61ac0a143cba0ebaa46284235dee14a2e57fd5db Mon Sep 17 00:00:00 2001 From: Vladimir Vagaytsev <10628074+vvagaytsev@users.noreply.github.com> Date: Fri, 18 Oct 2024 08:18:53 +0200 Subject: [PATCH 2/5] chore: log action preprocessing and ver merging durations --- core/src/graph/actions.ts | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/core/src/graph/actions.ts b/core/src/graph/actions.ts index 2937d8d700..848a5b4bca 100644 --- a/core/src/graph/actions.ts +++ b/core/src/graph/actions.ts @@ -740,6 +740,7 @@ export const preprocessActionConfig = profileAsync(async function preprocessActi definition: MaybeUndefined> actionTypes: ActionDefinitionMap }): Promise { + const actionStart = new Date().getTime() const actionKey = actionReferenceToString(config) const description = describeActionConfig(config) @@ -747,11 +748,16 @@ export const preprocessActionConfig = profileAsync(async function preprocessActi // in pre-processing, only use varfiles that are not template strings const resolvedVarFiles = config.varfiles?.filter((f) => !maybeTemplateString(getVarfileData(f).path)) + const mergeVarsStart = new Date().getTime() const variables = await mergeVariables({ basePath: config.internal.basePath, variables: config.variables, varfiles: resolvedVarFiles, }) + const mergeVarsEnd = new Date().getTime() + const varfilesDesc = + resolvedVarFiles && resolvedVarFiles.length > 0 ? `with varfiles: \n${resolvedVarFiles.join("\n")}` : "" + log.debug(`Merged variables for action ${actionKey} in ${mergeVarsEnd - mergeVarsStart}ms ${varfilesDesc}`) const resolvedVariables = resolveTemplateStrings({ value: variables, @@ -952,6 +958,9 @@ export const preprocessActionConfig = profileAsync(async function preprocessActi actionTypes, }) + const actionEnd = new Date().getTime() + log.debug(`Preprocessed action ${actionKey} in ${actionEnd - actionStart}ms`) + return { config, dependencies, From eb7463ac013f2e82ef85b18cbde94797f4325e9f Mon Sep 17 00:00:00 2001 From: Vladimir Vagaytsev <10628074+vvagaytsev@users.noreply.github.com> Date: Fri, 18 Oct 2024 13:13:00 +0200 Subject: [PATCH 3/5] chore: print fine-grained messages on silly level --- core/src/graph/actions.ts | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/core/src/graph/actions.ts b/core/src/graph/actions.ts index 848a5b4bca..3340c626e4 100644 --- a/core/src/graph/actions.ts +++ b/core/src/graph/actions.ts @@ -171,7 +171,7 @@ export const actionConfigsToGraph = profileAsync(async function actionConfigsToG const preprocessActions = async (predicate: (config: ActionConfig) => boolean = () => true) => { let batchNo = 1 for (const batch of sliceToBatches(configsByKey, processingBatchSize)) { - log.debug(`Preprocessing actions batch #${batchNo} (${batch.length} items)`) + log.silly(`Preprocessing actions batch #${batchNo} (${batch.length} items)`) await Promise.all( batch.map(async ([key, config]) => { if (!predicate(config)) { @@ -303,7 +303,7 @@ export const actionConfigsToGraph = profileAsync(async function actionConfigsToG log.debug(`Processing ${actionConfigCount} action configs...`) let batchNo = 1 for (const batch of sliceToBatches(preprocessResults, 100)) { - log.debug(`Processing actions batch #${batchNo} (${batch.length} items)`) + log.silly(`Processing actions batch #${batchNo} (${batch.length} items)`) await Promise.all( batch.map(async ([key, res]) => { const { config, linkedSource, remoteSourcePath, supportedModes, dependencies } = res @@ -757,7 +757,7 @@ export const preprocessActionConfig = profileAsync(async function preprocessActi const mergeVarsEnd = new Date().getTime() const varfilesDesc = resolvedVarFiles && resolvedVarFiles.length > 0 ? `with varfiles: \n${resolvedVarFiles.join("\n")}` : "" - log.debug(`Merged variables for action ${actionKey} in ${mergeVarsEnd - mergeVarsStart}ms ${varfilesDesc}`) + log.silly(`Merged variables for action ${actionKey} in ${mergeVarsEnd - mergeVarsStart}ms ${varfilesDesc}`) const resolvedVariables = resolveTemplateStrings({ value: variables, @@ -959,7 +959,7 @@ export const preprocessActionConfig = profileAsync(async function preprocessActi }) const actionEnd = new Date().getTime() - log.debug(`Preprocessed action ${actionKey} in ${actionEnd - actionStart}ms`) + log.silly(`Preprocessed action ${actionKey} in ${actionEnd - actionStart}ms`) return { config, From 4e0a064e03f52ea9f9eaa440e75143936353d3a0 Mon Sep 17 00:00:00 2001 From: Vladimir Vagaytsev <10628074+vvagaytsev@users.noreply.github.com> Date: Fri, 18 Oct 2024 13:14:06 +0200 Subject: [PATCH 4/5] chore: remove outdated todo-comment --- core/src/graph/actions.ts | 1 - 1 file changed, 1 deletion(-) diff --git a/core/src/graph/actions.ts b/core/src/graph/actions.ts index 3340c626e4..592946455c 100644 --- a/core/src/graph/actions.ts +++ b/core/src/graph/actions.ts @@ -291,7 +291,6 @@ export const actionConfigsToGraph = profileAsync(async function actionConfigsToG const minimalRoots = await garden.vcs.getMinimalRoots(log, allPaths) log.debug(`Found minimal roots for ${allPaths.size} paths`) - // TODO: Maybe we could optimize resolving tree versions, avoid parallel scanning of the same directory etc. const graph = new MutableConfigGraph({ environmentName: garden.environmentName, actions: [], From 6bac64064a9d849ec4c1828f923b411116d94049 Mon Sep 17 00:00:00 2001 From: Vladimir Vagaytsev <10628074+vvagaytsev@users.noreply.github.com> Date: Fri, 18 Oct 2024 13:17:22 +0200 Subject: [PATCH 5/5] chore: log action pre-/processing batch exec time --- core/src/graph/actions.ts | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/core/src/graph/actions.ts b/core/src/graph/actions.ts index 592946455c..aaa6b3f39e 100644 --- a/core/src/graph/actions.ts +++ b/core/src/graph/actions.ts @@ -172,6 +172,7 @@ export const actionConfigsToGraph = profileAsync(async function actionConfigsToG let batchNo = 1 for (const batch of sliceToBatches(configsByKey, processingBatchSize)) { log.silly(`Preprocessing actions batch #${batchNo} (${batch.length} items)`) + const startTime = new Date().getTime() await Promise.all( batch.map(async ([key, config]) => { if (!predicate(config)) { @@ -196,6 +197,8 @@ export const actionConfigsToGraph = profileAsync(async function actionConfigsToG }) ) batchNo++ + const endTime = new Date().getTime() + log.silly(`Preprocessed actions batch #${batchNo} (${batch.length} items in ${endTime - startTime}ms`) } } @@ -303,6 +306,7 @@ export const actionConfigsToGraph = profileAsync(async function actionConfigsToG let batchNo = 1 for (const batch of sliceToBatches(preprocessResults, 100)) { log.silly(`Processing actions batch #${batchNo} (${batch.length} items)`) + const startTime = new Date().getTime() await Promise.all( batch.map(async ([key, res]) => { const { config, linkedSource, remoteSourcePath, supportedModes, dependencies } = res @@ -347,6 +351,8 @@ export const actionConfigsToGraph = profileAsync(async function actionConfigsToG }) ) batchNo++ + const endTime = new Date().getTime() + log.silly(`Processed actions batch #${batchNo} (${batch.length} items in ${endTime - startTime}ms`) } log.debug(`Processed ${actionConfigCount} action configs`)