fix(profiler): fix sync profiler and collect more data (#6586)

* fix(profiler): fix time measurement in sync profiler

* chore(profiler): profile more classes and functions

* chore: log varfiles size

core/src/config/base.ts

@@ -571,12 +571,14 @@ export const loadVarfile = profileAsync(async function loadVarfile({
   path,
   defaultPath,
   optional = false,
+  log,
 }: {
   // project root (when resolving project config) or module root (when resolving module config)
   configRoot: string
   path: string | undefined
   defaultPath: string | undefined
   optional?: boolean
+  log?: Log
 }): Promise<PrimitiveMap> {
   if (!path && !defaultPath) {
     throw new ParameterError({
@@ -599,6 +601,7 @@ export const loadVarfile = profileAsync(async function loadVarfile({
 
   try {
     const data = await _readFile(resolvedPath)
+    log?.silly(() => `Loaded ${data.length} bytes from varfile ${resolvedPath}`)
     const relPath = relative(configRoot, resolvedPath)
     const filename = basename(resolvedPath.toLowerCase())
 

core/src/config/template-contexts/base.ts

@@ -19,6 +19,7 @@ import { isPrimitive, joi, joiIdentifier } from "../common.js"
 import { KeyedSet } from "../../util/keyed-set.js"
 import { naturalList } from "../../util/string.js"
 import { styles } from "../../logger/styles.js"
+import { Profile } from "../../util/profiling.js"
 
 export type ContextKeySegment = string | number
 export type ContextKey = ContextKeySegment[]
@@ -52,10 +53,12 @@ export function schema(joiSchema: Joi.Schema) {
 
 export interface ConfigContextType {
   new (...params: any[]): ConfigContext
+
   getSchema(): CustomObjectSchema
 }
 
 // Note: we're using classes here to be able to use decorators to describe each context node and key
+@Profile()
 export abstract class ConfigContext {
   private readonly _rootContext: ConfigContext
   private readonly _resolvedValues: { [path: string]: any }

core/src/graph/actions.ts

@@ -65,7 +65,7 @@ import { minimatch } from "minimatch"
 import type { ConfigContext } from "../config/template-contexts/base.js"
 import type { LinkedSource, LinkedSourceMap } from "../config-store/local.js"
 import { relative } from "path"
-import { profileAsync } from "../util/profiling.js"
+import { profile, profileAsync } from "../util/profiling.js"
 import { uuidv4 } from "../util/random.js"
 import { getSourcePath } from "../vcs/vcs.js"
 import { styles } from "../logger/styles.js"
@@ -532,6 +532,7 @@ export const processActionConfig = profileAsync(async function processActionConf
     basePath: effectiveConfigFileLocation,
     variables: config.variables,
     varfiles: config.varfiles,
+    log,
   })
   const mergeVarsEnd = new Date().getTime()
   const actionKey = actionReferenceToString(config)
@@ -765,6 +766,7 @@ export const preprocessActionConfig = profileAsync(async function preprocessActi
     basePath: config.internal.basePath,
     variables: config.variables,
     varfiles: resolvedVarFiles,
+    log,
   })
   const mergeVarsEnd = new Date().getTime()
   const varfilesDesc =
@@ -984,7 +986,7 @@ export const preprocessActionConfig = profileAsync(async function preprocessActi
   }
 })
 
-function dependenciesFromActionConfig({
+const dependenciesFromActionConfig = profile(function dependenciesFromActionConfig({
   log,
   config,
   configsByKey,
@@ -1141,4 +1143,4 @@ function dependenciesFromActionConfig({
   }
 
   return deps
-}
+})

core/src/graph/common.ts

@@ -17,7 +17,7 @@ import type { ActionKind } from "../plugin/action-types.js"
 import { loadVarfile } from "../config/base.js"
 import type { DeepPrimitiveMap, Varfile } from "../config/common.js"
 import type { Task } from "../tasks/base.js"
-import type { LogMetadata, TaskLogStatus } from "../logger/log-entry.js"
+import type { Log, LogMetadata, TaskLogStatus } from "../logger/log-entry.js"
 
 // Shared type used by ConfigGraph and TaskGraph to facilitate circular dependency detection
 export type DependencyGraphNode = {
@@ -150,10 +150,12 @@ export const mergeVariables = profileAsync(async function mergeVariables({
   basePath,
   variables,
   varfiles,
+  log,
 }: {
   basePath: string
   variables?: DeepPrimitiveMap
   varfiles?: Varfile[]
+  log: Log
 }) {
   const varsByFile = await Promise.all(
     (varfiles || []).map((varfile) => {
@@ -163,6 +165,7 @@ export const mergeVariables = profileAsync(async function mergeVariables({
         path,
         defaultPath: undefined,
         optional,
+        log,
       })
     })
   )

core/src/router/base.ts

@@ -42,6 +42,7 @@ import { ActionConfigContext, ActionSpecContext } from "../config/template-conte
 import type { NamespaceStatus } from "../types/namespace.js"
 import { TemplatableConfigContext } from "../config/template-contexts/project.js"
 import type { ParamsBase } from "../plugin/handlers/base/base.js"
+import { Profile } from "../util/profiling.js"
 
 export type CommonParams = keyof PluginActionContextParams
 
@@ -54,6 +55,7 @@ export interface BaseRouterParams {
 /**
  * The ProviderRouter is extended upon in BaseAction-, Module- and Provider routers.
  */
+@Profile()
 export abstract class BaseRouter {
   protected readonly garden: Garden
   protected readonly configuredPlugins: GardenPluginSpec[]

core/src/tasks/resolve-action.ts

@@ -150,7 +150,12 @@ export class ResolveActionTask<T extends Action> extends BaseActionTask<T, Resol
       const group = this.graph.getGroup(groupName)
 
       groupVariables = resolveTemplateStrings({
-        value: await mergeVariables({ basePath: group.path, variables: group.variables, varfiles: group.varfiles }),
+        value: await mergeVariables({
+          basePath: group.path,
+          variables: group.variables,
+          varfiles: group.varfiles,
+          log: this.garden.log,
+        }),
         context: inputsContext,
         // TODO: map variables to their source
         source: undefined,
@@ -164,6 +169,7 @@ export class ResolveActionTask<T extends Action> extends BaseActionTask<T, Resol
         basePath,
         variables: config.variables,
         varfiles: config.varfiles,
+        log: this.garden.log,
       }),
       context: new ActionSpecContext({
         garden: this.garden,

core/src/template-string/template-string.ts

@@ -105,6 +105,11 @@ const shouldUnescape = (ctxOpts: ContextResolveOpts) => {
   return !!ctxOpts.unescape || !ctxOpts.allowPartial
 }
 
+type ParseParams = Parameters<typeof parser.parse>
+const parseWithPegJs = profile(function parseWithPegJs(params: ParseParams) {
+  return parser.parse(...params)
+})
+
 /**
  * Parse and resolve a templated string, with the given context. The template format is similar to native JS templated
  * strings but only supports simple lookups from the given context, e.g. "prefix-${nested.key}-suffix", and not
@@ -130,27 +135,30 @@ export const resolveTemplateString = profile(function resolveTemplateString({
   }
 
   try {
-    const parsed = parser.parse(string, {
-      getKey: (key: string[], resolveOpts?: ContextResolveOpts) => {
-        return context.resolve({ key, nodePath: [], opts: { ...contextOpts, ...(resolveOpts || {}) } })
+    const parsed = parseWithPegJs([
+      string,
+      {
+        getKey: (key: string[], resolveOpts?: ContextResolveOpts) => {
+          return context.resolve({ key, nodePath: [], opts: { ...contextOpts, ...(resolveOpts || {}) } })
+        },
+        getValue,
+        resolveNested: (nested: string) => resolveTemplateString({ string: nested, context, contextOpts }),
+        buildBinaryExpression,
+        buildLogicalExpression,
+        isArray: Array.isArray,
+        ConfigurationError,
+        TemplateStringError,
+        missingKeyExceptionType,
+        passthroughExceptionType,
+        allowPartial: !!contextOpts.allowPartial,
+        unescape: shouldUnescape(contextOpts),
+        escapePrefix,
+        optionalSuffix: "}?",
+        isPlainObject,
+        isPrimitive,
+        callHelperFunction,
       },
-      getValue,
-      resolveNested: (nested: string) => resolveTemplateString({ string: nested, context, contextOpts }),
-      buildBinaryExpression,
-      buildLogicalExpression,
-      isArray: Array.isArray,
-      ConfigurationError,
-      TemplateStringError,
-      missingKeyExceptionType,
-      passthroughExceptionType,
-      allowPartial: !!contextOpts.allowPartial,
-      unescape: shouldUnescape(contextOpts),
-      escapePrefix,
-      optionalSuffix: "}?",
-      isPlainObject,
-      isPrimitive,
-      callHelperFunction,
-    })
+    ])
 
     const outputs: ResolvedClause[] = parsed.map((p: any) => {
       return isPlainObject(p) ? p : { resolved: getValue(p) }

core/src/util/profiling.ts

@@ -287,8 +287,8 @@ export const profile = <T extends Array<any>, U>(fn: (...args: T) => U, profiler
   const timingKey = fn.name
 
   return (...args: T): U => {
-    const result = fn(...args)
     const start = performance.now()
+    const result = fn(...args)
 
     if (!profiler!.isEnabled()) {
       return result