fix: improve inline completion api latency measurement precision

server/aws-lsp-codewhisperer/src/language-server/inline-completion/codeWhispererServer.test.ts

@@ -2147,7 +2147,7 @@ describe('CodeWhisperer Server', () => {
                     suggestions: activeSession.suggestions,
                     responseContext: activeSession.responseContext,
                     codewhispererSessionId: activeSession.codewhispererSessionId,
-                    timeToFirstRecommendation: activeSession.timeToFirstRecommendation,
+                    timeToFirstRecommendation: activeSession.triggerToResponseLatency,
                 },
                 expectedSessionData
             )

server/aws-lsp-codewhisperer/src/language-server/inline-completion/codeWhispererServer.ts

@@ -236,9 +236,9 @@ export const CodewhispererServerFactory =
 
             // Record last user modification time for any document
             if (lastUserModificationTime) {
-                timeSinceLastUserModification = Date.now() - lastUserModificationTime
+                timeSinceLastUserModification = performance.now() - lastUserModificationTime
             }
-            lastUserModificationTime = Date.now()
+            lastUserModificationTime = performance.now()
 
             documentChangedListener.onDocumentChanged(p)
             editCompletionHandler.documentChanged()

server/aws-lsp-codewhisperer/src/language-server/inline-completion/handler/editCompletionHandler.ts

@@ -129,7 +129,7 @@ export class EditCompletionHandler {
 
         // Not ideally to rely on a state, should improve it and simply make it a debounced API
         this.isInProgress = true
-        const startPreprocessTimestamp = Date.now()
+        const startPreprocessTimestamp = performance.now()
 
         if (params.partialResultToken && currentSession) {
             // Close ACTIVE session. We shouldn't record Discard trigger decision for trigger with nextToken.

server/aws-lsp-codewhisperer/src/language-server/inline-completion/handler/inlineCompletionHandler.ts

@@ -168,7 +168,7 @@ export class InlineCompletionHandler {
         const maxResults = isAutomaticLspTriggerKind ? 1 : 5
         const selectionRange = params.context.selectedCompletionInfo?.range
 
-        const startPreprocessTimestamp = Date.now()
+        const startPreprocessTimestamp = performance.now()
 
         // For Jupyter Notebook in VSC, the language server does not have access to
         // its internal states including current active cell index, etc
@@ -199,7 +199,7 @@ export class InlineCompletionHandler {
         const previousSession = this.completionSessionManager.getPreviousSession()
         // Only refer to decisions in the past 2 mins
         const previousDecisionForClassifier =
-            previousSession && Date.now() - previousSession.decisionMadeTimestamp <= 2 * 60 * 1000
+            previousSession && performance.now() - previousSession.decisionMadeTimestamp <= 2 * 60 * 1000
                 ? previousSession.getAggregatedUserTriggerDecision()
                 : undefined
         let ideCategory: string | undefined = ''

server/aws-lsp-codewhisperer/src/language-server/inline-completion/session/sessionManager.ts

@@ -85,12 +85,12 @@ export class CodeWhispererSession {
     language: CodewhispererLanguage
     requestContext: GenerateSuggestionsRequest
     supplementalMetadata?: CodeWhispererSupplementalContext
-    private _timeToFirstRecommendation: number = 0
-    get timeToFirstRecommendation() {
-        return this._timeToFirstRecommendation
+    private _triggerToResponseLatency: number = 0
+    get triggerToResponseLatency() {
+        return this._triggerToResponseLatency
     }
     setTimeToFirstRecommendation() {
-        this._timeToFirstRecommendation = Date.now() - this.startTime
+        this._triggerToResponseLatency = performance.now() - this.startTime
     }
 
     credentialStartUrl?: string
@@ -128,7 +128,7 @@ export class CodeWhispererSession {
         this._state = 'REQUESTING'
         this.startTime = data.startPreprocessTimestamp
         // Current implementation is the session will be created when preprocess is done
-        this._endPreprocessTimestamp = Date.now()
+        this._endPreprocessTimestamp = performance.now()
     }
 
     // This function makes it possible to stub uuidv4 calls in tests
@@ -163,7 +163,7 @@ export class CodeWhispererSession {
             }
         }
 
-        this.closeTime = Date.now()
+        this.closeTime = performance.now()
 
         this.state = 'CLOSED'
     }
@@ -178,7 +178,7 @@ export class CodeWhispererSession {
             this.suggestionsStates.set(suggestion.itemId, 'Discard')
         }
 
-        this.closeTime = Date.now()
+        this.closeTime = performance.now()
 
         this.state = 'DISCARD'
     }

server/aws-lsp-codewhisperer/src/shared/codeWhispererService.ts

@@ -521,7 +521,6 @@ export class CodeWhispererServiceToken extends CodeWhispererServiceBase {
                 tokenRequest.customizationArn = this.customizationArn
             }
 
-            const beforeApiCall = Date.now()
             // TODO: Should make context log as a dev option, too noisy, comment it out temporarily
             // let recentEditsLogStr = ''
             // const recentEdits = tokenRequest.supplementalContexts?.filter(it => it.type === 'PreviousEditorState')
@@ -549,8 +548,9 @@ export class CodeWhispererServiceToken extends CodeWhispererServiceBase {
     "request.nextToken": ${tokenRequest.nextToken}`
             // "recentEdits": ${recentEditsLogStr}\n`
 
+            const beforeApiCall = performance.now()
             const response = await this.client.generateCompletions(this.withProfileArn(tokenRequest)).promise()
-
+            const apiLatency = performance.now() - beforeApiCall
             const responseContext = {
                 requestId: response?.$response?.requestId,
                 codewhispererSessionId: response?.$response?.httpResponse?.headers['x-amzn-sessionid'],
@@ -568,7 +568,7 @@ export class CodeWhispererServiceToken extends CodeWhispererServiceBase {
     "response.completions.length": ${response.completions?.length ?? 0},
     "response.predictions.length": ${response.predictions?.length ?? 0},
     "predictionType": ${tokenRequest.predictionTypes?.toString() ?? 'Not specified (COMPLETIONS)'},
-    "latency": ${Date.now() - beforeApiCall},
+    "latency": ${apiLatency},
     "response.nextToken": ${response.nextToken},
     "firstSuggestion": ${firstSuggestionLogstr}`
 

server/aws-lsp-codewhisperer/src/shared/supplementalContextUtil/supplementalContextUtil.ts

@@ -30,7 +30,7 @@ export async function fetchSupplementalContext(
     cancellationToken: CancellationToken,
     openTabFiles?: string[]
 ): Promise<CodeWhispererSupplementalContext | undefined> {
-    const timesBeforeFetching = Date.now()
+    const timesBeforeFetching = performance.now()
 
     const isUtg = unitTestIntentDetector.detectUnitTestIntent(document)
 
@@ -55,7 +55,7 @@ export async function fetchSupplementalContext(
                                 },
                             ],
                             contentsLength: srcContent.length,
-                            latency: Date.now() - timesBeforeFetching,
+                            latency: performance.now() - timesBeforeFetching,
                             strategy: 'NEW_UTG',
                         }
                     }
@@ -87,7 +87,7 @@ export async function fetchSupplementalContext(
                     (acc, curr) => acc + curr.content.length,
                     0
                 ),
-                latency: Date.now() - timesBeforeFetching,
+                latency: performance.now() - timesBeforeFetching,
                 strategy: supplementalContextValue.strategy,
             }
 
@@ -119,7 +119,7 @@ export async function fetchSupplementalContext(
                 isProcessTimeout: true,
                 supplementalContextItems: [],
                 contentsLength: 0,
-                latency: Date.now() - timesBeforeFetching,
+                latency: performance.now() - timesBeforeFetching,
                 strategy: 'Empty',
             }
         } else {

server/aws-lsp-codewhisperer/src/shared/telemetry/telemetryService.test.ts

@@ -100,7 +100,7 @@ describe('TelemetryService', () => {
         },
         acceptedSuggestionId: 'item-id-1',
         firstCompletionDisplayLatency: 100,
-        timeToFirstRecommendation: 200,
+        triggerToResponseLatency: 200,
         getAggregatedUserTriggerDecision: () => 'Accept',
         startPosition: {
             line: 12,

server/aws-lsp-codewhisperer/src/shared/telemetry/telemetryService.ts

@@ -200,7 +200,7 @@ export class TelemetryService {
         removedIdeDiagnostics?: IdeDiagnostic[],
         streakLength?: number
     ) {
-        session.decisionMadeTimestamp = Date.now()
+        session.decisionMadeTimestamp = performance.now()
         // Toolkit telemetry API
         if (this.enableTelemetryEventsToDestination) {
             const data: CodeWhispererUserTriggerDecisionEvent = {
@@ -227,7 +227,7 @@ export class TelemetryService {
                 codewhispererTimeSinceLastUserDecision: session.previousTriggerDecisionTime
                     ? session.startTime - session.previousTriggerDecisionTime
                     : undefined,
-                codewhispererTimeToFirstRecommendation: session.timeToFirstRecommendation,
+                codewhispererTimeToFirstRecommendation: session.triggerToResponseLatency,
                 codewhispererPreviousSuggestionState: session.previousTriggerDecision,
                 codewhispererSupplementalContextTimeout: session.supplementalMetadata?.isProcessTimeout,
                 codewhispererSupplementalContextIsUtg: session.supplementalMetadata?.isUtg,
@@ -256,7 +256,7 @@ export class TelemetryService {
         const acceptedCharacterCount =
             acceptedSuggestion && acceptedSuggestion.content ? acceptedSuggestion.content.length : 0
         const perceivedLatencyMilliseconds =
-            session.triggerType === 'OnDemand' ? session.timeToFirstRecommendation : timeSinceLastUserModification
+            session.triggerType === 'OnDemand' ? session.triggerToResponseLatency : timeSinceLastUserModification
         const isInlineEdit = session.predictionType === SuggestionType.EDIT
 
         // RTS STE API
@@ -270,9 +270,10 @@ export class TelemetryService {
             completionType:
                 session.suggestions.length > 0 ? getCompletionType(session.suggestions[0]).toUpperCase() : 'LINE',
             suggestionState: this.getSuggestionState(userTriggerDecision),
+            // TODO: firstCompletionDisplayLatency is directly send from ides (vscode/jb), what's difference against perceivedLatencyMilliseconds?
             recommendationLatencyMilliseconds: session.firstCompletionDisplayLatency ?? 0,
             timestamp: new Date(Date.now()),
-            triggerToResponseLatencyMilliseconds: session.timeToFirstRecommendation,
+            triggerToResponseLatencyMilliseconds: session.triggerToResponseLatency,
             suggestionReferenceCount: referenceCount,
             generatedLine: generatedLines,
             numberOfRecommendations: session.suggestions.length,