fix: collect metrics to help analyze performance problems

packages/@aws-cdk/toolkit-lib/lib/api/cloud-assembly/private/prepare-source.ts

@@ -261,10 +261,7 @@ export function writeContextToEnv(env: Env, context: Context, completeness: 'add
  *
  * @param assembly - the assembly to check
  */
-async function checkContextOverflowSupport(assembly: CloudAssembly, ioHelper: IoHelper): Promise<void> {
-  const traceFn = (msg: string) => ioHelper.defaults.trace(msg);
-  const tree = await loadTree(assembly, traceFn);
-
+async function checkContextOverflowSupport(tree: ConstructTreeNode | undefined, ioHelper: IoHelper): Promise<void> {
   // We're dealing with an old version of the framework here. It is unaware of the temporary
   // file, which means that it will ignore the context overflow.
   if (!frameworkSupportsContextOverflow(tree)) {
@@ -273,19 +270,31 @@ async function checkContextOverflowSupport(assembly: CloudAssembly, ioHelper: Io
 }
 
 /**
- * Checks if the framework supports context overflow
+ * Find the `aws-cdk-lib` library version by inspecting construct tree debug information
  */
-export function frameworkSupportsContextOverflow(tree: ConstructTreeNode | undefined): boolean {
-  return !some(tree, node => {
+export function findConstructLibraryVersion(tree: ConstructTreeNode | undefined): string | undefined {
+  let ret: string | undefined = undefined;
+
+  some(tree, node => {
     const fqn = node.constructInfo?.fqn;
     const version = node.constructInfo?.version;
-    return (
-      fqn === 'aws-cdk-lib.App' // v2 app
-      && version !== '0.0.0' // ignore developer builds
-      && version != null && lte(version, '2.38.0') // last version not supporting large context
-    ) // v2
-    || fqn === '@aws-cdk/core.App'; // v1 app => not supported
+    if (fqn?.startsWith('aws-cdk-lib.') || fqn?.startsWith('@aws-cdk/core.')) {
+      ret = version;
+      return true;
+    }
+    return false;
   });
+
+  return ret !== '0.0.0' ? ret : undefined;
+}
+
+/**
+ * Checks if the framework supports context overflow
+ */
+export function frameworkSupportsContextOverflow(tree: ConstructTreeNode | undefined): boolean {
+  const version = findConstructLibraryVersion(tree);
+
+  return !version || !lte(version, '2.38.0');
 }
 
 /**
@@ -299,7 +308,10 @@ export async function assemblyFromDirectory(assemblyDir: string, ioHelper: IoHel
       // We sort as we deploy
       topoSort: false,
     });
-    await checkContextOverflowSupport(assembly, ioHelper);
+
+    const tree = await loadTree(assembly, ioHelper.defaults.trace.bind(ioHelper.defaults));
+    await checkContextOverflowSupport(tree, ioHelper);
+
     return assembly;
   } catch (err: any) {
     if (err.message.includes(cxschema.VERSION_MISMATCH)) {

packages/@aws-cdk/toolkit-lib/lib/api/io/private/span.ts

@@ -7,8 +7,12 @@ import { formatTime } from '../../../util';
 import type { IActionAwareIoHost } from '../io-host';
 import type { IoDefaultMessages } from './io-default-messages';
 
+/**
+ * These data fields are automatically added by ending a span
+ */
 export interface SpanEnd {
   readonly duration: number;
+  readonly counters?: Record<string, number>;
 }
 
 /**
@@ -23,29 +27,35 @@ export interface SpanDefinition<S extends object, E extends SpanEnd> {
   readonly end: make.IoMessageMaker<E>;
 }
 
+/**
+ * Arguments to the span.end() function
+ *
+ * `SpanEnd` represents fields that are added by the underlying `end` function.
+ *
+ * - In principle, the intersection of the underlying type and the SpanEnd keys
+ *   are made optional, the rest is the same as the underlying type.
+ * - If the expected type is subsumed by the SpanEnd type, then either void or
+ *   their intersection with all fields optional.
+ */
+type SpanEndArguments<T> = keyof T extends keyof SpanEnd
+  ? (Pick<Partial<SpanEnd>, keyof T & keyof SpanEnd> | void)
+  : Optional<T, keyof T & keyof SpanEnd>;
+
 /**
  * Used in conditional types to check if a type (e.g. after omitting fields) is an empty object
  * This is needed because counter-intuitive neither `object` nor `{}` represent that.
  */
-type EmptyObject = {
-  [index: string | number | symbol]: never;
-};
+type EmptyObject = Record<string, never>;
 
 /**
  * Helper type to force a parameter to be not present of the computed type is an empty object
  */
 type VoidWhenEmpty<T> = T extends EmptyObject ? void : T;
 
-/**
- * Helper type to force a parameter to be an empty object if the computed type is an empty object
- * This is weird, but some computed types (e.g. using `Omit`) don't end up enforcing this.
- */
-type ForceEmpty<T> = T extends EmptyObject ? EmptyObject : T;
-
 /**
  * Make some properties optional
  */
-type Optional<T, K extends keyof T> = Pick<Partial<T>, K> & Omit<T, K>;
+type Optional<T, K extends keyof T> = Omit<T, K> & Pick<Partial<T>, K>;
 
 /**
  * Ending the span returns the observed duration
@@ -67,6 +77,7 @@ export interface IMessageSpan<E extends SpanEnd> extends IActionAwareIoHost {
    * An IoDefaultMessages wrapped around the span.
    */
   readonly defaults: IoDefaultMessages;
+
   /**
    * Get the time elapsed since the start
    */
@@ -79,15 +90,34 @@ export interface IMessageSpan<E extends SpanEnd> extends IActionAwareIoHost {
   /**
    * End the span with a payload
    */
-  end(payload: VoidWhenEmpty<Omit<E, keyof SpanEnd>>): Promise<ElapsedTime>;
+  end(payload: SpanEndArguments<E>): Promise<ElapsedTime>;
   /**
-   * End the span with a payload, overwriting
+   * End the span with a message and payload
    */
-  end(payload: VoidWhenEmpty<Optional<E, keyof SpanEnd>>): Promise<ElapsedTime>;
+  end(message: string, payload: SpanEndArguments<E>): Promise<ElapsedTime>;
+
   /**
-   * End the span with a message and payload
+   * Increment a counter
    */
-  end(message: string, payload: ForceEmpty<Optional<E, keyof SpanEnd>>): Promise<ElapsedTime>;
+  incCounter(name: string, delta?: number): void;
+
+  /**
+   * Return a new timer object
+   *
+   * It will be added into the span data when it's stopped. All open timers are
+   * automatically stopped when the span is ended.
+   *
+   * Timers are ultimately added to the `counters` array with `<name>_ms` and
+   * `<name>_cnt` keys.
+   */
+  startTimer(name: string): ITimer;
+}
+
+/**
+ * A timer to time an operation in a span.
+ */
+export interface ITimer {
+  stop(): void;
 }
 
 /**
@@ -133,6 +163,8 @@ class MessageSpan<S extends object, E extends SpanEnd> implements IMessageSpan<E
   private readonly spanId: string;
   private readonly startTime: number;
   private readonly timingMsgTemplate: string;
+  private readonly counters: Record<string, number> = {};
+  private readonly openTimers = new Set<ITimer>();
 
   public constructor(ioHelper: IoHelper, definition: SpanDefinition<S, E>, makeHelper: (ioHost: IActionAwareIoHost) => IoHelper) {
     this.definition = definition;
@@ -161,26 +193,50 @@ class MessageSpan<S extends object, E extends SpanEnd> implements IMessageSpan<E
   public async notify(msg: ActionLessMessage<unknown>): Promise<void> {
     return this.ioHelper.notify(withSpanId(this.spanId, msg));
   }
-  public async end(x: any, y?: ForceEmpty<Optional<E, keyof SpanEnd>>): Promise<ElapsedTime> {
+  public async end(x: any, y?: SpanEndArguments<E>): Promise<ElapsedTime> {
     const duration = this.time();
 
-    const endInput = parseArgs<ForceEmpty<Optional<E, keyof SpanEnd>>>(x, y);
+    for (const t of this.openTimers) {
+      t.stop();
+    }
+    this.openTimers.clear();
+
+    const endInput = parseArgs<SpanEndArguments<E>>(x, y);
     const endMsg = endInput.message ?? util.format(this.timingMsgTemplate, this.definition.name, duration.asSec);
     const endPayload = endInput.payload;
 
     await this.notify(this.definition.end.msg(
       endMsg, {
         duration: duration.asMs,
+        ...(Object.keys(this.counters).length > 0 ? { counters: this.counters } : {}),
         ...endPayload,
       } as E));
 
     return duration;
   }
 
+  public incCounter(name: string, delta: number = 1): void {
+    this.counters[name] = (this.counters[name] ?? 0) + delta;
+  }
+
   public async requestResponse<T>(msg: ActionLessRequest<unknown, T>): Promise<T> {
     return this.ioHelper.requestResponse(withSpanId(this.spanId, msg));
   }
 
+  public startTimer(name: string): ITimer {
+    const start = Date.now();
+
+    const t: ITimer = {
+      stop: () => {
+        this.openTimers.delete(t);
+        this.incCounter(`${name}_ms`, Math.floor(Date.now() - start) / 1000);
+        this.incCounter(`${name}_cnt`, 1);
+      },
+    };
+    this.openTimers.add(t);
+    return t;
+  }
+
   private time() {
     const elapsedTime = new Date().getTime() - this.startTime;
     return {
@@ -190,7 +246,7 @@ class MessageSpan<S extends object, E extends SpanEnd> implements IMessageSpan<E
   }
 }
 
-function parseArgs<S extends object>(first: any, second?: S): { message: string | undefined; payload: S } {
+function parseArgs<S>(first: any, second?: S): { message: string | undefined; payload: S } {
   const firstIsMessage = typeof first === 'string';
 
   // When the first argument is a string or we have a second argument, then the first arg is the message

packages/@aws-cdk/toolkit-lib/lib/api/tree.ts

@@ -40,7 +40,7 @@ export async function loadTree(assembly: CloudAssembly, trace: (msg: string) =>
   try {
     const outdir = assembly.directory;
     const fileName = assembly.tree()?.file;
-    return fileName ? fs.readJSONSync(path.join(outdir, fileName)).tree : ({} as ConstructTreeNode);
+    return fileName ? fs.readJSONSync(path.join(outdir, fileName)).tree : undefined;
   } catch (e) {
     await trace(`Failed to get tree.json file: ${e}. Proceeding with empty tree.`);
     return undefined;

packages/@aws-cdk/toolkit-lib/lib/toolkit/toolkit.ts

@@ -1,6 +1,7 @@
 import '../private/dispose-polyfill';
 import * as path from 'node:path';
 import * as cxapi from '@aws-cdk/cloud-assembly-api';
+import { SynthesisMessageLevel } from '@aws-cdk/cloud-assembly-api';
 import type { FeatureFlagReportProperties } from '@aws-cdk/cloud-assembly-schema';
 import { ArtifactType } from '@aws-cdk/cloud-assembly-schema';
 import type { TemplateDiff } from '@aws-cdk/cloudformation-diff';
@@ -71,7 +72,7 @@ import { DiffFormatter } from '../api/diff';
 import { detectStackDrift } from '../api/drift';
 import { DriftFormatter } from '../api/drift/drift-formatter';
 import type { IIoHost, IoMessageLevel, ToolkitAction } from '../api/io';
-import type { ElapsedTime, IoHelper } from '../api/io/private';
+import type { ElapsedTime, IMessageSpan, IoHelper } from '../api/io/private';
 import { asIoHelper, IO, SPAN, withoutColor, withoutEmojis, withTrimmedWhitespace } from '../api/io/private';
 import { CloudWatchLogEventMonitor, findCloudWatchLogGroups } from '../api/logs-monitor';
 import { Mode, PluginHost } from '../api/plugin';
@@ -596,7 +597,8 @@ export class Toolkit extends CloudAssemblySourceBuilder {
       }
 
       // The generated stack has no resources
-      if (Object.keys(stack.template.Resources || {}).length === 0) {
+      const resourceCount = Object.keys(stack.template.Resources || {}).length;
+      if (resourceCount === 0) {
         // stack is empty and doesn't exist => do nothing
         const stackExists = await deployments.stackExists({ stack });
         if (!stackExists) {
@@ -661,6 +663,7 @@ export class Toolkit extends CloudAssemblySourceBuilder {
           current: stackIndex,
           stack,
         });
+      deploySpan.incCounter('resources', resourceCount);
 
       let tags = options.tags;
       if (!tags || tags.length === 0) {
@@ -1417,7 +1420,9 @@ async function synthAndMeasure(
   const synthSpan = await ioHelper.span(SPAN.SYNTH_ASSEMBLY).begin({ stacks: selectStacks });
   try {
     const ret = await assemblyFromSource(synthSpan.asHelper, cx);
+    countAssemblyResults(synthSpan, ret.assembly);
     const synthDuration = await synthSpan.end({});
+
     return Object.assign(ret, { synthDuration });
   } catch (error: any) {
     // End the span even if we had a failure
@@ -1429,3 +1434,19 @@ async function synthAndMeasure(
 function zeroTime(): ElapsedTime {
   return { asMs: 0, asSec: 0 };
 }
+
+function countAssemblyResults(span: IMessageSpan<any>, assembly: cxapi.CloudAssembly) {
+  const stacksRecursively = assembly.stacksRecursively;
+  span.incCounter('stacks', stacksRecursively.length);
+  span.incCounter('assemblies', asmCount(assembly));
+  span.incCounter('errorAnns', sum(stacksRecursively.map(s => s.messages.filter(m => m.level === SynthesisMessageLevel.ERROR).length)));
+  span.incCounter('warnings', sum(stacksRecursively.map(s => s.messages.filter(m => m.level === SynthesisMessageLevel.WARNING).length)));
+
+  function asmCount(x: cxapi.CloudAssembly): number {
+    return 1 + x.nestedAssemblies.reduce((acc, asm) => acc + asmCount(asm.nestedAssembly), 0);
+  }
+}
+
+function sum(xs: number[]) {
+  return xs.reduce((a, b) => a + b, 0);
+}

packages/@aws-cdk/toolkit-lib/test/actions/deploy.test.ts

@@ -41,6 +41,22 @@ describe('deploy', () => {
     successfulDeployment();
   });
 
+  test('emits resource counters', async () => {
+    // WHEN
+    const cx = await builderFixture(toolkit, 'two-empty-stacks');
+    await toolkit.deploy(cx);
+
+    // THEN
+    const deploy = ioHost.notifySpy.mock.calls.map(cs => cs[0]).filter(c => c.code === 'CDK_TOOLKIT_I5001');
+    expect(deploy).toContainEqual(expect.objectContaining({
+      data: expect.objectContaining({
+        counters: expect.objectContaining({
+          resources: 1,
+        }),
+      }),
+    }));
+  });
+
   test('request response contains security diff', async () => {
     // WHEN
     const cx = await builderFixture(toolkit, 'stack-with-role');

packages/@aws-cdk/toolkit-lib/test/actions/synth.test.ts

@@ -23,6 +23,22 @@ describe('synth', () => {
     }));
   });
 
+  test('emits stack counters', async () => {
+    // WHEN
+    const cx = await builderFixture(toolkit, 'two-empty-stacks');
+    await toolkit.synth(cx);
+
+    // Separate tests as colorizing hampers detection
+    expect(ioHost.notifySpy).toHaveBeenCalledWith(expect.objectContaining({
+      data: expect.objectContaining({
+        counters: expect.objectContaining({
+          assemblies: 1,
+          stacks: 2,
+        }),
+      }),
+    }));
+  });
+
   test('synth from app', async () => {
     // WHEN
     const cx = await appFixture(toolkit, 'two-empty-stacks');