fix: collect metrics to help analyze performance problems

README.md

@@ -70,3 +70,4 @@ latest features.
 
 For more details on the compatibility model and specific versions that work together,
 see [COMPATIBILITY.md](COMPATIBILITY.md).
+

packages/@aws-cdk-testing/cli-integ/lib/package-sources/cli-repo-source.ts

@@ -39,7 +39,7 @@ export class TestCliRepoSource implements ITestCliSource {
   }
 
   public async makeCliAvailable() {
-    addToShellPath(this.cliPath);
+    addToShellPath(path.resolve(this.cliPath));
   }
 
   public requestedVersion() {

packages/@aws-cdk-testing/cli-integ/tests/telemetry-integ-tests/cdk-synth-guessagent.integtest.ts

@@ -0,0 +1,40 @@
+import * as path from 'path';
+import * as fs from 'fs-extra';
+import { integTest, withDefaultFixture } from '../../lib';
+
+jest.setTimeout(2 * 60 * 60_000); // Includes the time to acquire locks, worst-case single-threaded runtime
+
+integTest(
+  'cdk synth telemetry contains an agent guess',
+  withDefaultFixture(async (fixture) => {
+    const telemetryFile = path.join(fixture.integTestDir, `telemetry-${Date.now()}.json`);
+
+    const synthOutput = await fixture.cdk(
+      ['synth', fixture.fullStackName('test-1'), `--telemetry-file=${telemetryFile}`],
+      {
+        verboseLevel: 3,
+        modEnv: {
+          AWS_EXECUTION_ENV: 'AmazonQ-For-CLI Version/1.23.1',
+        },
+      }, // trace mode
+    );
+
+    // Check the trace that telemetry was executed successfully
+    expect(synthOutput).toContain('Telemetry Sent Successfully');
+
+    const json = fs.readJSONSync(telemetryFile);
+    expect(json).toEqual([
+      expect.objectContaining({
+        environment: expect.objectContaining({
+          agent: true,
+        }),
+      }),
+      expect.objectContaining({
+        environment: expect.objectContaining({
+          agent: true,
+        }),
+      }),
+    ]);
+    fs.unlinkSync(telemetryFile);
+  }),
+);

packages/@aws-cdk-testing/cli-integ/tests/telemetry-integ-tests/cdk-synth-telemetry-with-errors.integtest.ts

@@ -67,7 +67,7 @@ integTest(
           },
           nodeVersion: expect.anything(),
         },
-        project: {},
+        project: expect.objectContaining({}),
         duration: {
           total: expect.anything(),
         },
@@ -115,7 +115,7 @@ integTest(
           },
           nodeVersion: expect.anything(),
         },
-        project: {},
+        project: expect.objectContaining({}),
         duration: {
           total: expect.anything(),
         },

packages/@aws-cdk-testing/cli-integ/tests/telemetry-integ-tests/cdk-synth-telemetry.integtest.ts

@@ -56,18 +56,18 @@ integTest(
           eventId: expect.stringContaining(':1'),
           timestamp: expect.anything(),
         }),
-        environment: {
+        environment: expect.objectContaining({
           ci: expect.anything(),
           os: {
             platform: expect.anything(),
             release: expect.anything(),
           },
           nodeVersion: expect.anything(),
-        },
-        project: {},
-        duration: {
+        }),
+        project: expect.objectContaining({}),
+        duration: expect.objectContaining({
           total: expect.anything(),
-        },
+        }),
       }),
       expect.objectContaining({
         event: expect.objectContaining({
@@ -104,18 +104,18 @@ integTest(
           eventId: expect.stringContaining(':2'),
           timestamp: expect.anything(),
         }),
-        environment: {
+        environment: expect.objectContaining({
           ci: expect.anything(),
           os: {
             platform: expect.anything(),
             release: expect.anything(),
           },
           nodeVersion: expect.anything(),
-        },
-        project: {},
-        duration: {
+        }),
+        project: expect.objectContaining({}),
+        duration: expect.objectContaining({
           total: expect.anything(),
-        },
+        }),
       }),
     ]);
     fs.unlinkSync(telemetryFile);

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,41 @@ export interface SpanDefinition<S extends object, E extends SpanEnd> {
   readonly end: make.IoMessageMaker<E>;
 }
 
+/**
+ * Arguments to the span.end() function
+ *
+ * `SpanEndArguments<T>` are the fields that a user still needs to supply, it
+ * fields in the type `T` that aren't also in `SpanEnd`. `SpanEnd` represents
+ * fields that are automatically added by the underlying `end` function.
+ *
+ * Fields that are already in `SpanEnd` are still rendered as optionals, so you
+ * can override them (but you don't have to).
+ *
+ * - Does the following: fields that are shared between `T` and `SpanEnd` are
+ *   made optional, and the rest of the keys of `T` are required.
+ *
+ * - If `T` is fully subsumed by the `SpanEnd` type, then an object type with
+ *   all fields optional, OR 'void' so you can avoid passing an argument at all.
+ */
+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 +83,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 +96,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 message and payload
+   */
+  end(message: string, payload: SpanEndArguments<E>): Promise<ElapsedTime>;
+
   /**
-   * End the span with a payload, overwriting
+   * Increment a counter
    */
-  end(payload: VoidWhenEmpty<Optional<E, keyof SpanEnd>>): Promise<ElapsedTime>;
+  incCounter(name: string, delta?: number): void;
+
   /**
-   * End the span with a message and payload
+   * 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.
    */
-  end(message: string, payload: ForceEmpty<Optional<E, keyof SpanEnd>>): Promise<ElapsedTime>;
+  startTimer(name: string): ITimer;
+}
+
+/**
+ * A timer to time an operation in a span.
+ */
+export interface ITimer {
+  stop(): void;
 }
 
 /**
@@ -133,6 +169,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 +199,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 +252,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;