(Slow?) extension activation in VS Code

[sqs]

tl;dr I looked into vscode cody's slow activation time and it appears we aren't doing anything wrong/dumb, and it only gets slow if there are a lot of other extensions as well (we get dinged because s, the first letter of our extension ID, is lower in the alphabet than most extensions)

I saw that VS Code's Developer > Show Running Extensions was saying Cody was taking 2-3 seconds to activate. I looked into this. Here are my notes.

• My tentative conclusion is that the "2-3 seconds" time is incorrect/misleading and we are not doing anything dumb.
• All extensions with the onStartupFinished activationEvents in their package.json are loaded after everything else in VS Code. When I disable GitHub Copilot and Copilot Chat (which also use onStartupFinished), our activation time as reported by Developer > Show Running Extensions drops from 2-3s to ~600ms, which is almost exactly what Developer > Show Running Extensions reported for GitHub Copilot and Copilot Chat before I disabled them. This makes me think that VS Code loads onStartupFinished extensions in alphabetical order or something (I haven't confirmed this).
• I added in some helpful logs and noted some timings (see below).
• The fix in https://github.com/sourcegraph/cody/pull/2695 should improve performance in everyday usage, but it did not have an impact on any of the timings I recorded below.

Timings

before:

• cody-start: 11.377s (w/o running window), 5.307s, 5.05s, 4.86s, 4.16s
• show running extensions: 635ms, 600ms

w/o copilot+ocg:

• cody-start: 2.89s (w/o running window), 2.879s
• show running extensions: 590ms (w/o running window), 604ms

w/o ocg:

• cody-start: 4.01s (w/o running window), 4.05s
• show running extensions: 594ms

w/o copilot+copilotchat+ocg:

• cody-start: 2s (w/o running window), 1.57s, 1.56s, 1.53s
• show running extensions: 610ms
• cody-load-code: 93ms
• App-load: 63ms
• mementoTP set: 37ms

w/ 1.1MB memento instead of 1.8MB:

• mementoTP set 22.5ms

• w/ 1kb memento

• cody-start: 1.53s

• show running extensions: 604ms

• mementoTP: set 1.5ms

Diffs I used to get these timings:

diff --git a/vscode/src/extension.common.ts b/vscode/src/extension.common.ts
index 7169bfdf..040a76ab 100644
--- a/vscode/src/extension.common.ts
+++ b/vscode/src/extension.common.ts
@@ -43,12 +43,17 @@ export interface PlatformContext {
     onConfigurationChange?: (configuration: Configuration) => void
 }

+console.time('cody-load-code')
+
 export async function activate(
     context: vscode.ExtensionContext,
     platformContext: PlatformContext
 ): Promise<ExtensionApi> {
+    console.timeEnd('cody-load-code')
+
     const api = new ExtensionApi()

+    console.time('cody-start')
     try {
         const disposable = await start(context, platformContext)
         if (!context.globalState.get('extension.hasActivatedPreviously')) {
@@ -64,5 +69,7 @@ export async function activate(
         console.error(error)
     }

+    console.timeEnd('cody-start')
+
     return api
 }
diff --git a/vscode/src/main.ts b/vscode/src/main.ts
index 713dcbba..3496189e 100644
--- a/vscode/src/main.ts
+++ b/vscode/src/main.ts
@@ -38,6 +38,7 @@ import { createStatusBar } from './services/StatusBar'
 import { createOrUpdateEventLogger, telemetryService } from './services/telemetry'
 import { createOrUpdateTelemetryRecorderProvider, telemetryRecorder } from './services/telemetry-v2'
 import { onTextDocumentChange } from './services/utils/codeblock-action-tracker'
+import { mementoTimingProxy, proxyMemento } from './services/utils/proxyMemento'
 import { parseAllVisibleDocuments, updateParseTreeOnEdit } from './tree-sitter/parse-tree-cache'

 /**
@@ -45,7 +46,7 @@ import { parseAllVisibleDocuments, updateParseTreeOnEdit } from './tree-sitter/p
  */
 export async function start(context: vscode.ExtensionContext, platform: PlatformContext): Promise<vscode.Disposable> {
     // Set internal storage fields for storage provider singletons
-    localStorage.setStorage(context.globalState)
+    localStorage.setStorage(proxyMemento(context.globalState, mementoTimingProxy))
     if (secretStorage instanceof VSCodeSecretStorage) {
         secretStorage.setStorage(context.secrets)
     }
diff --git a/vscode/webviews/App.tsx b/vscode/webviews/App.tsx
index 4473df34..faa90e1a 100644
--- a/vscode/webviews/App.tsx
+++ b/vscode/webviews/App.tsx
@@ -27,6 +27,8 @@ import { updateWorkspaceFolderUris } from './utils/displayPath'
 import { createWebviewTelemetryService } from './utils/telemetry'
 import type { VSCodeWrapper } from './utils/VSCodeApi'

+console.time('App-load')
+
 export const App: React.FunctionComponent<{ vscodeAPI: VSCodeWrapper }> = ({ vscodeAPI }) => {
     const [config, setConfig] = useState<
         (Pick<Configuration, 'debugEnable' | 'experimentalGuardrails'> & LocalEnv) | null
diff --git a/vscode/webviews/Chat.tsx b/vscode/webviews/Chat.tsx
index 3aadf0e4..aeab2dc7 100644
--- a/vscode/webviews/Chat.tsx
+++ b/vscode/webviews/Chat.tsx
@@ -172,6 +172,10 @@ export const Chat: React.FunctionComponent<React.PropsWithChildren<ChatboxProps>
         [vscodeAPI]
     )

+    useEffect(() => {
+        setTimeout(() => console.timeEnd('App-load'))
+    }, [])
+
     return (
         <ChatUI
             messageInProgress={messageInProgress}
diff --git a/vscode/src/services/utils/proxyMemento.ts b/vscode/src/services/utils/proxyMemento.ts
new file mode 100644
index 00000000..476c27fe
--- /dev/null
+++ b/vscode/src/services/utils/proxyMemento.ts
@@ -0,0 +1,39 @@
+import { type Memento } from 'vscode'
+
+interface MementoProxy {
+    beforeGet?: (key: string) => void
+    afterGet?: (key: string, value: unknown) => void
+    beforeSet?: (key: string, value: unknown) => void
+    afterSet?: (key: string, value: unknown) => void
+}
+
+/** Proxy a {@link Memento} for debugging/development. */
+export function proxyMemento(memento: Memento, proxy: MementoProxy): Memento {
+    return {
+        get<T>(key: string, defaultValue?: T): T | undefined {
+            proxy.beforeGet?.(key)
+            const value = memento.get(key, defaultValue)
+            proxy.afterGet?.(key, value)
+            return value
+        },
+        keys(): readonly string[] {
+            return memento.keys()
+        },
+        // eslint-disable-next-line @typescript-eslint/no-explicit-any
+        async update(key: string, value: any): Promise<void> {
+            proxy.beforeSet?.(key, value)
+            const result = await memento.update(key, value)
+            proxy.afterSet?.(key, value)
+            return result
+        },
+    }
+}
+
+export const mementoTimingProxy: MementoProxy = {
+    beforeSet: key => {
+        console.time('mementoTimingProxy.set ' + key)
+    },
+    afterSet: key => {
+        console.timeEnd('mementoTimingProxy.set ' + key)
+    },
+}

[github-actions[bot]]

This issue is marked as stale because it has been open 60 days with no activity. Remove stale label or comment or this will be closed automatically in 5 days.

[github-actions[bot]]

This issue is marked as stale because it has been open 60 days with no activity. Remove stale label or comment or this will be closed automatically in 5 days.

[jacksongoode]

Not stale?