diff --git a/server/aws-lsp-codewhisperer/src/language-server/inline-completion/codeWhispererServer.test.ts b/server/aws-lsp-codewhisperer/src/language-server/inline-completion/codeWhispererServer.test.ts index 18a68d1676..6a38c7b85d 100644 --- a/server/aws-lsp-codewhisperer/src/language-server/inline-completion/codeWhispererServer.test.ts +++ b/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 ) diff --git a/server/aws-lsp-codewhisperer/src/language-server/inline-completion/codeWhispererServer.ts b/server/aws-lsp-codewhisperer/src/language-server/inline-completion/codeWhispererServer.ts index 3e8461a576..6a604a0a60 100644 --- a/server/aws-lsp-codewhisperer/src/language-server/inline-completion/codeWhispererServer.ts +++ b/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() diff --git a/server/aws-lsp-codewhisperer/src/language-server/inline-completion/handler/editCompletionHandler.ts b/server/aws-lsp-codewhisperer/src/language-server/inline-completion/handler/editCompletionHandler.ts index 42a45f1f8c..5e027e14ed 100644 --- a/server/aws-lsp-codewhisperer/src/language-server/inline-completion/handler/editCompletionHandler.ts +++ b/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. diff --git a/server/aws-lsp-codewhisperer/src/language-server/inline-completion/handler/inlineCompletionHandler.ts b/server/aws-lsp-codewhisperer/src/language-server/inline-completion/handler/inlineCompletionHandler.ts index ed125e08ac..704afa2fc3 100644 --- a/server/aws-lsp-codewhisperer/src/language-server/inline-completion/handler/inlineCompletionHandler.ts +++ b/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 = '' diff --git a/server/aws-lsp-codewhisperer/src/language-server/inline-completion/session/sessionManager.ts b/server/aws-lsp-codewhisperer/src/language-server/inline-completion/session/sessionManager.ts index cdeb441f80..557f8a7154 100644 --- a/server/aws-lsp-codewhisperer/src/language-server/inline-completion/session/sessionManager.ts +++ b/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' } diff --git a/server/aws-lsp-codewhisperer/src/shared/codeWhispererService.ts b/server/aws-lsp-codewhisperer/src/shared/codeWhispererService.ts index 27dac024af..026169d01d 100644 --- a/server/aws-lsp-codewhisperer/src/shared/codeWhispererService.ts +++ b/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}` diff --git a/server/aws-lsp-codewhisperer/src/shared/supplementalContextUtil/supplementalContextUtil.ts b/server/aws-lsp-codewhisperer/src/shared/supplementalContextUtil/supplementalContextUtil.ts index 18fb5a7686..8e0902452f 100644 --- a/server/aws-lsp-codewhisperer/src/shared/supplementalContextUtil/supplementalContextUtil.ts +++ b/server/aws-lsp-codewhisperer/src/shared/supplementalContextUtil/supplementalContextUtil.ts @@ -30,7 +30,7 @@ export async function fetchSupplementalContext( cancellationToken: CancellationToken, openTabFiles?: string[] ): Promise { - 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 { diff --git a/server/aws-lsp-codewhisperer/src/shared/telemetry/telemetryService.test.ts b/server/aws-lsp-codewhisperer/src/shared/telemetry/telemetryService.test.ts index 8c7975c5ce..d4b2f9fe3b 100644 --- a/server/aws-lsp-codewhisperer/src/shared/telemetry/telemetryService.test.ts +++ b/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, diff --git a/server/aws-lsp-codewhisperer/src/shared/telemetry/telemetryService.ts b/server/aws-lsp-codewhisperer/src/shared/telemetry/telemetryService.ts index 3fef1bec68..14078cbc3a 100644 --- a/server/aws-lsp-codewhisperer/src/shared/telemetry/telemetryService.ts +++ b/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,