perf(sam): avoid searching for SAM CLI

Problem:
- `SamCliLocationProvider.getLocation()` is called many times and always
  searches for sam on the system, which is slow (especially on Windows).
- Hard to follow the logic of SamCliValidator, too much indirection
  involving `isSamCliVersionCached()` and `getSamCliExecutableId()`.

Solution:
- Cache the last-found sam location in `DefaultSamCliLocationProvider`
  instead of whatever `DefaultSamCliValidator` was trying to do.
- Use the cached location unless it fails `tryRun()`. This means Toolkit
  still "shells out" to `sam`, which can be slow, but at least it avoids
  a system search.

Author: justinmk3

src/shared/logger/logger.ts

@@ -142,3 +142,24 @@ export function getNullLogger(type?: 'channel' | 'debugConsole' | 'main'): Logge
 export function setLogger(logger: Logger | undefined, type?: 'channel' | 'debugConsole' | 'main') {
     toolkitLoggers[type ?? 'main'] = logger
 }
+
+export class PerfLog {
+    private log
+    public readonly start
+
+    public constructor(public readonly topic: string) {
+        const log = getLogger()
+        this.log = log
+        if (log.logLevelEnabled('verbose')) {
+            this.start = Date.now()
+        }
+    }
+
+    public done(): void {
+        if (!this.start) {
+            return
+        }
+        const elapsed = Date.now() - this.start
+        this.log.verbose('%s took %dms', this.topic, elapsed.toFixed(1))
+    }
+}

src/shared/sam/cli/samCliLocator.ts

@@ -9,16 +9,39 @@ import * as filesystemUtilities from '../../filesystemUtilities'
 import { getLogger, Logger } from '../../logger'
 import { SamCliInfoInvocation } from './samCliInfo'
 import { DefaultSamCliValidator, SamCliValidatorContext, SamCliVersionValidation } from './samCliValidator'
+import { SystemUtilities } from '../../systemUtilities'
+import { PerfLog } from '../../logger/logger'
 
 export interface SamCliLocationProvider {
     getLocation(): Promise<{ path: string; version: string } | undefined>
 }
 
 export class DefaultSamCliLocationProvider implements SamCliLocationProvider {
     private static samCliLocator: BaseSamCliLocator | undefined
+    protected static cachedSamLocation: { path: string; version: string } | undefined
 
+    /** Checks that the given `sam` actually works by invoking `sam --version`. */
+    private static async isValidSamLocation(samPath: string) {
+        return await SystemUtilities.tryRun(samPath, ['--version'], true, 'SAM CLI')
+    }
+
+    /**
+     * Gets the last-found `sam` location, or searches the system if a working
+     * `sam` wasn't previously found and cached.
+     */
     public async getLocation() {
-        return DefaultSamCliLocationProvider.getSamCliLocator().getLocation()
+        const perflog = new PerfLog('samCliLocator: getLocation')
+        const cachedLoc = DefaultSamCliLocationProvider.cachedSamLocation
+
+        // Avoid searching the system for `sam` (especially slow on Windows).
+        if (cachedLoc && await DefaultSamCliLocationProvider.isValidSamLocation(cachedLoc.path)) {
+            perflog.done()
+            return cachedLoc
+        }
+
+        DefaultSamCliLocationProvider.cachedSamLocation = await DefaultSamCliLocationProvider.getSamCliLocator().getLocation()
+        perflog.done()
+        return DefaultSamCliLocationProvider.cachedSamLocation
     }
 
     public static getSamCliLocator(): SamCliLocationProvider {
@@ -43,7 +66,6 @@ abstract class BaseSamCliLocator {
         this.verifyOs()
     }
 
-    // TODO: this method is being called multiple times on my Windows machine and is really slow
     public async getLocation() {
         let location = await this.findFileInFolders(this.getExecutableFilenames(), this.getExecutableFolders())
 
@@ -69,11 +91,10 @@ abstract class BaseSamCliLocator {
 
         for (const fullPath of fullPaths) {
             if (!BaseSamCliLocator.didFind) {
-                this.logger.verbose(`Searching for SAM CLI in: ${fullPath}`)
+                this.logger.verbose(`samCliLocator: searching in: ${fullPath}`)
             }
             const context: SamCliValidatorContext = {
                 samCliLocation: async () => fullPath,
-                getSamCliExecutableId: async () => 'bogus',
                 getSamCliInfo: async () => new SamCliInfoInvocation(fullPath).execute(),
             }
             const validator = new DefaultSamCliValidator(context)
@@ -84,10 +105,10 @@ abstract class BaseSamCliLocator {
                         BaseSamCliLocator.didFind = true
                         return { path: fullPath, version: validationResult.version }
                     }
-                    this.logger.warn(`Found invalid SAM executable (${validationResult.validation}): ${fullPath}`)
+                    this.logger.warn(`samCliLocator: found invalid SAM CLI: (${validationResult.validation}): ${fullPath}`)
                 } catch (e) {
                     const err = e as Error
-                    this.logger.error(err)
+                    this.logger.error('samCliLocator failed: %s', err.message)
                 }
             }
         }

src/shared/sam/cli/samCliSettings.ts

@@ -95,9 +95,9 @@ export class SamCliSettings extends fromExtensionManifest('aws.samcli', descript
 
     /**
      * Gets location of `sam` from:
-     * 1. previous saved location (if valid), or
-     * 2. user config (if valid), or
-     * 3. tries to find `sam` on the system if the user config is invalid.
+     * 1. user config (if any; overrides auto-detected location)
+     * 2. previous cached location (if valid)
+     * 3. searching for `sam` on the system
      *
      * @returns `autoDetected=true` if auto-detection was _attempted_.
      */

src/shared/sam/cli/samCliValidator.ts

@@ -3,7 +3,6 @@
  * SPDX-License-Identifier: Apache-2.0
  */
 
-import { stat } from 'fs-extra'
 import * as semver from 'semver'
 import { ClassToInterfaceType } from '../../utilities/tsUtils'
 import { SamCliSettings } from './samCliSettings'
@@ -63,9 +62,6 @@ export interface SamCliValidator {
 export type SamCliValidatorContext = ClassToInterfaceType<DefaultSamCliValidatorContext>
 
 export class DefaultSamCliValidator implements SamCliValidator {
-    private cachedSamInfoResponse?: SamCliInfoResponse
-    private cachedSamCliVersionId?: string
-
     public constructor(private readonly context: SamCliValidatorContext) {}
 
     public async detectValidSamCli(): Promise<SamCliValidatorResult> {
@@ -83,29 +79,11 @@ export class DefaultSamCliValidator implements SamCliValidator {
     }
 
     public async getVersionValidatorResult(): Promise<SamCliVersionValidatorResult> {
-        const samCliId: string = await this.context.getSamCliExecutableId()
-        if (!this.isSamCliVersionCached(samCliId)) {
-            this.cachedSamInfoResponse = await this.context.getSamCliInfo()
-            this.cachedSamCliVersionId = samCliId
-        }
-
-        const version = this.cachedSamInfoResponse!.version
-
+        const r = await this.context.getSamCliInfo()
         return {
-            version,
-            validation: DefaultSamCliValidator.validateSamCliVersion(version),
-        }
-    }
-
-    private isSamCliVersionCached(samCliVersionId: string): boolean {
-        if (!this.cachedSamInfoResponse) {
-            return false
+            version: r.version,
+            validation: DefaultSamCliValidator.validateSamCliVersion(r.version),
         }
-        if (!this.cachedSamCliVersionId) {
-            return false
-        }
-
-        return this.cachedSamCliVersionId === samCliVersionId
     }
 
     public static validateSamCliVersion(version?: string): SamCliVersionValidation {
@@ -136,19 +114,6 @@ export class DefaultSamCliValidatorContext implements SamCliValidatorContext {
         return (await this.config.getOrDetectSamCli()).path
     }
 
-    public async getSamCliExecutableId(): Promise<string> {
-        // Function should never get called if there is no SAM CLI
-        const location = await this.samCliLocation()
-        if (!location) {
-            throw new Error('SAM CLI does not exist')
-        }
-
-        // The modification timestamp of SAM CLI is used as the "distinct executable id"
-        const stats = await stat(location)
-
-        return stats.mtime.valueOf().toString()
-    }
-
     public async getSamCliInfo(): Promise<SamCliInfoResponse> {
         const samPath = await this.samCliLocation()
         if (!samPath) {

src/test/shared/sam/cli/samCliValidator.test.ts

@@ -26,9 +26,6 @@ describe('DefaultSamCliValidator', async function () {
             return this.mockSamLocation
         }
 
-        public async getSamCliExecutableId(): Promise<string> {
-            return this.samCliVersionId
-        }
         public async getSamCliInfo(): Promise<SamCliInfoResponse> {
             this.getInfoCallCount++
 
@@ -116,29 +113,6 @@ describe('DefaultSamCliValidator', async function () {
                 )
             })
         })
-
-        it('Uses the cached validation result', async function () {
-            const validatorContext = new TestSamCliValidatorContext(minSamCliVersion)
-            const samCliValidator = new DefaultSamCliValidator(validatorContext)
-
-            await samCliValidator.getVersionValidatorResult()
-            await samCliValidator.getVersionValidatorResult()
-
-            assert.strictEqual(validatorContext.getInfoCallCount, 1, 'getInfo called more than once')
-        })
-
-        it('Does not use the cached validation result if the SAM CLI timestamp changed', async function () {
-            const validatorContext = new TestSamCliValidatorContext(minSamCliVersion)
-            const samCliValidator = new DefaultSamCliValidator(validatorContext)
-
-            await samCliValidator.getVersionValidatorResult()
-
-            // Oh look, a new SAM CLI timestamp
-            validatorContext.samCliVersionId = validatorContext.samCliVersionId + 'x'
-            await samCliValidator.getVersionValidatorResult()
-
-            assert.strictEqual(validatorContext.getInfoCallCount, 2, 'getInfo was not called both times')
-        })
     })
 
     describe('validateSamCliVersion', async function () {