feat(codewhisperer): Add Client component latency telemetry (#3090)

Problem:

Adding a new telemetry : Client component latency for codewhisperer.

telemetry definition in:
aws/aws-toolkit-common@618a9fb

A client component latency metric is emitted only once for each complete
GenerationRecommendation pagination session if the suggestion is shown to the
user.

        {
            "name": "codewhispererFirstCompletionLatency",
            "type": "double",
            "description": "The time it takes for the response to be received after the plugin makes a first GenerateCompletions API call."
        },
        {
            "name": "codewhispererEndToEndLatency",
            "type": "double",
            "description": "The time it takes for the first completion to be shown in the IDE after the user performs the CW trigger action."
        },
        {
            "name": "codewhispererAllCompletionsLatency",
            "type": "double",
            "description": "The time it takes for the last GenerateCompletions response to be received after plugin makes a first call to GenerateCompletions API."
        },
        {
            "name": "codewhispererPostprocessingLatency",
            "type": "double",
            "description": "The time it takes for the first completions to be displayed in the IDE after the plugin receives the initial Completions object."
        },
        {
            "name": "codewhispererPreprocessingLatency",
            "type": "double",
            "description": "The time it takes for the plugin to make the first GenerateCompletions API call after the user performs the CW trigger action."
        },
        {
            "name": "codewhispererCredentialFetchingLatency",
            "type": "double",
            "description": "The time it takes to get the Sono/SSO credential for the invocation."
        },

Solution:
Record timestamp and compare the timestamp to build the Client component latency
metric and report it to service.

Author: leigaol

package-lock.json

@@ -3518,7 +3518,7 @@
         "report": "nyc report --reporter=html --reporter=json"
     },
     "devDependencies": {
-        "@aws-toolkits/telemetry": "^1.0.82",
+        "@aws-toolkits/telemetry": "^1.0.87",
         "@cspotcode/source-map-support": "^0.8.1",
         "@sinonjs/fake-timers": "^8.1.0",
         "@types/adm-zip": "^0.4.34",

package.json

@@ -20,6 +20,7 @@ import { getLogger } from '../../shared/logger'
 import { throttle } from 'lodash'
 import { Credentials } from 'aws-sdk'
 import { AuthUtil } from '../util/authUtil'
+import { TelemetryHelper } from '../util/telemetryHelper'
 
 const refreshCredentials = throttle(() => {
     getLogger().verbose('codewhisperer: invalidating expired credentials')
@@ -135,7 +136,9 @@ export class DefaultCodeWhispererClient {
 
     async createUserSdkClient(): Promise<CodeWhispererUserClient> {
         const isOptedOut = CodeWhispererSettings.instance.isOptoutEnabled()
+        TelemetryHelper.instance.setFetchCredentialStartTime()
         const bearerToken = await AuthUtil.instance.getBearerToken()
+        TelemetryHelper.instance.setSdkApiCallStartTime()
         return (await globals.sdkClientBuilder.createAwsService(
             Service,
             {

src/codewhisperer/client/codewhisperer.ts

@@ -14,6 +14,7 @@ import { KeyStrokeHandler } from '../service/keyStrokeHandler'
 import { isInlineCompletionEnabled } from '../util/commonUtil'
 import { InlineCompletionService } from '../service/inlineCompletionService'
 import { AuthUtil } from '../util/authUtil'
+import { TelemetryHelper } from '../util/telemetryHelper'
 
 /**
  * This function is for manual trigger CodeWhisperer
@@ -81,7 +82,8 @@ export async function invokeRecommendation(
             if (AuthUtil.instance.isConnectionExpired()) {
                 await AuthUtil.instance.showReauthenticatePrompt()
             }
-            InlineCompletionService.instance.getPaginatedRecommendation(client, editor, 'OnDemand', config)
+            TelemetryHelper.instance.setInvokeSuggestionStartTime()
+            await InlineCompletionService.instance.getPaginatedRecommendation(client, editor, 'OnDemand', config)
         } else {
             if (
                 !vsCodeState.isCodeWhispererEditing &&

src/codewhisperer/commands/invokeRecommendation.ts

@@ -174,6 +174,8 @@ class CodeWhispererInlineCompletionItemProvider implements vscode.InlineCompleti
                 r.references
             )
             this.nextMove = 0
+            TelemetryHelper.instance.setFirstSuggestionShowTime()
+            TelemetryHelper.instance.tryRecordClientComponentLatency(document.languageId)
             this._onDidShow.fire()
             if (matchedCount >= 2 || RecommendationHandler.instance.hasNextToken()) {
                 return [item, { insertText: 'x' }]
@@ -368,6 +370,7 @@ export class InlineCompletionService {
                 showTimedMessage(CodeWhispererConstants.noSuggestions, 2000)
             }
         }
+        TelemetryHelper.instance.tryRecordClientComponentLatency(editor.document.languageId)
     }
 
     async showRecommendation(indexShift: number, isFirstRecommendation: boolean = false) {

src/codewhisperer/service/inlineCompletionService.ts

@@ -15,6 +15,7 @@ import { CodewhispererAutomatedTriggerType } from '../../shared/telemetry/teleme
 import { getTabSizeSetting } from '../../shared/utilities/editorUtilities'
 import { isInlineCompletionEnabled } from '../util/commonUtil'
 import { InlineCompletionService } from './inlineCompletionService'
+import { TelemetryHelper } from '../util/telemetryHelper'
 
 const performance = globalThis.performance ?? require('perf_hooks').performance
 
@@ -155,7 +156,8 @@ export class KeyStrokeHandler {
                     RecommendationHandler.instance.isGenerateRecommendationInProgress = false
                 }
             } else if (isInlineCompletionEnabled()) {
-                InlineCompletionService.instance.getPaginatedRecommendation(
+                TelemetryHelper.instance.setInvokeSuggestionStartTime()
+                await InlineCompletionService.instance.getPaginatedRecommendation(
                     client,
                     editor,
                     'AutoTrigger',

src/codewhisperer/service/keyStrokeHandler.ts

@@ -179,6 +179,7 @@ export class RecommendationHandler {
                     page === 0,
                     codewhispererPromise
                 )
+                TelemetryHelper.instance.setSdkApiCallEndTime()
                 latency = startTime !== 0 ? performance.now() - startTime : 0
                 if ('recommendations' in resp) {
                     recommendation = (resp && resp.recommendations) || []
@@ -199,6 +200,11 @@ export class RecommendationHandler {
                 requestId = resp?.$response && resp?.$response?.requestId
                 nextToken = resp?.nextToken ? resp?.nextToken : ''
                 sessionId = resp?.$response?.httpResponse?.headers['x-amzn-sessionid']
+                TelemetryHelper.instance.setFirstResponseRequestId(requestId)
+                TelemetryHelper.instance.setSessionId(sessionId)
+                if (nextToken === '') {
+                    TelemetryHelper.instance.setAllPaginationEndTime()
+                }
             } else {
                 getLogger().info('Invalid Request : ', JSON.stringify(req, undefined, EditorContext.getTabSize()))
                 getLogger().verbose(`Invalid Request : ${JSON.stringify(req, undefined, EditorContext.getTabSize())}`)

src/codewhisperer/service/recommendationHandler.ts

@@ -35,12 +35,23 @@ export class TelemetryHelper {
 
     public startUrl: string | undefined
 
+    // variables for client component latency
+    private invokeSuggestionStartTime = 0
+    private fetchCredentialStartTime = 0
+    private sdkApiCallStartTime = 0
+    private sdkApiCallEndTime = 0
+    private firstSuggestionShowTime = 0
+    private allPaginationEndTime = 0
+    private firstResponseRequestId = ''
+    private sessionId = ''
+
     constructor() {
         this.triggerType = 'OnDemand'
         this.CodeWhispererAutomatedtriggerType = 'KeyStrokeCount'
         this.completionType = 'Line'
         this.cursorOffset = 0
         this.startUrl = ''
+        this.sessionId = ''
     }
 
     static #instance: TelemetryHelper
@@ -137,4 +148,84 @@ export class TelemetryHelper {
     public isTelemetryEnabled(): boolean {
         return globals.telemetry.telemetryEnabled
     }
+
+    public resetClientComponentLatencyTime() {
+        this.invokeSuggestionStartTime = 0
+        this.sdkApiCallStartTime = 0
+        this.sdkApiCallEndTime = 0
+        this.fetchCredentialStartTime = 0
+        this.firstSuggestionShowTime = 0
+        this.allPaginationEndTime = 0
+        this.firstResponseRequestId = ''
+        this.sessionId = ''
+    }
+
+    /** This method is assumed to be invoked first at the start of execution **/
+    public setInvokeSuggestionStartTime() {
+         this.resetClientComponentLatencyTime()
+         this.invokeSuggestionStartTime = performance.now()
+    }
+
+    public setFetchCredentialStartTime() {
+        if (this.fetchCredentialStartTime === 0 && this.invokeSuggestionStartTime !== 0) {
+            this.fetchCredentialStartTime = performance.now()
+        }
+    }
+
+    public setSdkApiCallStartTime() {
+        if (this.sdkApiCallStartTime === 0 && this.fetchCredentialStartTime !== 0) {
+            this.sdkApiCallStartTime = performance.now()
+        }
+    }
+
+    public setSdkApiCallEndTime() {
+        if (this.sdkApiCallEndTime === 0 && this.sdkApiCallStartTime !== 0) {
+            this.sdkApiCallEndTime = performance.now()
+        }
+    }
+
+    public setAllPaginationEndTime() {
+        if (this.allPaginationEndTime === 0 && this.sdkApiCallEndTime !== 0) {
+            this.allPaginationEndTime = performance.now()
+        }
+    }
+
+    public setFirstSuggestionShowTime() {
+        if (this.firstSuggestionShowTime === 0 && this.sdkApiCallEndTime !== 0) {
+            this.firstSuggestionShowTime = performance.now()
+        }
+    }
+
+    public setFirstResponseRequestId(requestId: string) {
+        if (this.firstResponseRequestId === '') {
+            this.firstResponseRequestId = requestId
+        }
+    }
+
+    public setSessionId(sessionId: string) {
+        this.sessionId = sessionId
+    }
+
+    // report client component latency after all pagination call finish
+    // and at least one suggestion is shown to the user
+    public tryRecordClientComponentLatency(languageId: string) {
+        if (this.firstSuggestionShowTime === 0 || this.allPaginationEndTime === 0) {
+            return
+        }
+        telemetry.codewhisperer_clientComponentLatency.emit({
+            codewhispererRequestId: this.firstResponseRequestId,
+            codewhispererSessionId: this.sessionId,
+            codewhispererFirstCompletionLatency: this.sdkApiCallEndTime - this.sdkApiCallStartTime,
+            codewhispererEndToEndLatency: this.firstSuggestionShowTime - this.invokeSuggestionStartTime,
+            codewhispererAllCompletionsLatency: this.allPaginationEndTime - this.sdkApiCallStartTime,
+            codewhispererPostprocessingLatency: this.firstSuggestionShowTime - this.sdkApiCallEndTime,
+            codewhispererCredentialFetchingLatency: this.sdkApiCallStartTime - this.fetchCredentialStartTime,
+            codewhispererPreprocessingLatency: this.fetchCredentialStartTime - this.invokeSuggestionStartTime,
+            codewhispererCompletionType: this.completionType,
+            codewhispererTriggerType: this.triggerType,
+            codewhispererLanguage: runtimeLanguageContext.getLanguageContext(languageId).language,
+            credentialStartUrl: this.startUrl,
+        })
+        this.resetClientComponentLatencyTime()
+    }
 }