Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

chore: diagnostic logging #6558

Merged
merged 5 commits into from
Oct 18, 2024
Merged

chore: diagnostic logging #6558

Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
b79508c
chore: remove excessive logging
vvagaytsev Oct 18, 2024
61ac0a1
chore: log action preprocessing and ver merging durations
vvagaytsev Oct 18, 2024
eb7463a
chore: print fine-grained messages on silly level
vvagaytsev Oct 18, 2024
4e0a064
chore: remove outdated todo-comment
vvagaytsev Oct 18, 2024
6bac640
chore: log action pre-/processing batch exec time
vvagaytsev Oct 18, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
31 changes: 17 additions & 14 deletions core/src/graph/actions.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -171,7 +171,8 @@ 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)`)
const startTime = new Date().getTime()
await Promise.all(
batch.map(async ([key, config]) => {
if (!predicate(config)) {
Expand All @@ -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`)
}
}

Expand Down Expand Up @@ -291,7 +294,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: [],
Expand All @@ -303,7 +305,8 @@ 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)`)
const startTime = new Date().getTime()
await Promise.all(
batch.map(async ([key, res]) => {
const { config, linkedSource, remoteSourcePath, supportedModes, dependencies } = res
Expand Down Expand Up @@ -348,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`)

Expand Down Expand Up @@ -740,22 +745,25 @@ export const preprocessActionConfig = profileAsync(async function preprocessActi
definition: MaybeUndefined<ActionTypeDefinition<any>>
actionTypes: ActionDefinitionMap
}): Promise<PreprocessActionResult> {
const actionStart = new Date().getTime()
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 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.silly(`Merged variables for action ${actionKey} in ${mergeVarsEnd - mergeVarsStart}ms ${varfilesDesc}`)

log.debug(`Resolving variables (partially)...`)
const resolvedVariables = resolveTemplateStrings({
value: variables,
context: new ActionConfigContext({
Expand All @@ -773,7 +781,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 || {},
Expand Down Expand Up @@ -871,12 +878,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

Expand Down Expand Up @@ -913,7 +917,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) {
Expand All @@ -936,7 +939,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",
Expand All @@ -952,7 +954,6 @@ export const preprocessActionConfig = profileAsync(async function preprocessActi
}
}

log.debug(`Collecting dependencies...`)
const dependencies = dependenciesFromActionConfig({
log,
config,
Expand All @@ -962,7 +963,9 @@ export const preprocessActionConfig = profileAsync(async function preprocessActi
actionTypes,
})

log.debug(`Preprocessed action ${actionKey}...`)
const actionEnd = new Date().getTime()
log.silly(`Preprocessed action ${actionKey} in ${actionEnd - actionStart}ms`)

return {
config,
dependencies,
Expand Down