From a9c618839602997fb79737d365dd24945dd4807e Mon Sep 17 00:00:00 2001 From: Will Lo Date: Wed, 8 Jan 2025 09:35:37 -0800 Subject: [PATCH 1/2] fix incorrect clientComponentLatency@preprocessLatency --- .../src/codewhisperer/service/recommendationHandler.ts | 2 ++ .../src/codewhisperer/util/codeWhispererSession.ts | 1 + .../core/src/codewhisperer/util/telemetryHelper.ts | 10 +++++++++- 3 files changed, 12 insertions(+), 1 deletion(-) diff --git a/packages/core/src/codewhisperer/service/recommendationHandler.ts b/packages/core/src/codewhisperer/service/recommendationHandler.ts index 57accdfe44f..72e130a5bed 100644 --- a/packages/core/src/codewhisperer/service/recommendationHandler.ts +++ b/packages/core/src/codewhisperer/service/recommendationHandler.ts @@ -207,6 +207,8 @@ export class RecommendationHandler { session.requestContext = await EditorContext.buildGenerateRecommendationRequest(editor as vscode.TextEditor) } const request = session.requestContext.request + // record preprocessing end time + TelemetryHelper.instance.setPreprocessEndTime() // set start pos for non pagination call or first pagination call if (!pagination || (pagination && page === 0)) { diff --git a/packages/core/src/codewhisperer/util/codeWhispererSession.ts b/packages/core/src/codewhisperer/util/codeWhispererSession.ts index e5daae22d17..042cd947124 100644 --- a/packages/core/src/codewhisperer/util/codeWhispererSession.ts +++ b/packages/core/src/codewhisperer/util/codeWhispererSession.ts @@ -41,6 +41,7 @@ class CodeWhispererSession { fetchCredentialStartTime = 0 sdkApiCallStartTime = 0 invokeSuggestionStartTime = 0 + preprocessEndTime = 0 timeToFirstRecommendation = 0 firstSuggestionShowTime = 0 perceivedLatency = 0 diff --git a/packages/core/src/codewhisperer/util/telemetryHelper.ts b/packages/core/src/codewhisperer/util/telemetryHelper.ts index 6505e248f28..dcfdacfc438 100644 --- a/packages/core/src/codewhisperer/util/telemetryHelper.ts +++ b/packages/core/src/codewhisperer/util/telemetryHelper.ts @@ -582,6 +582,7 @@ export class TelemetryHelper { public resetClientComponentLatencyTime() { session.invokeSuggestionStartTime = 0 + session.preprocessEndTime = 0 session.sdkApiCallStartTime = 0 this.sdkApiCallEndTime = 0 session.fetchCredentialStartTime = 0 @@ -590,6 +591,13 @@ export class TelemetryHelper { this.firstResponseRequestId = '' } + public setPreprocessEndTime() { + if (session.preprocessEndTime !== 0) { + getLogger().warn(`inline completion preprocessEndTime has been set and not reset correctly`) + } + session.preprocessEndTime = performance.now() + } + /** This method is assumed to be invoked first at the start of execution **/ public setInvokeSuggestionStartTime() { this.resetClientComponentLatencyTime() @@ -635,7 +643,7 @@ export class TelemetryHelper { codewhispererFirstCompletionLatency: this.sdkApiCallEndTime - session.sdkApiCallStartTime, codewhispererLanguage: session.language, codewhispererPostprocessingLatency: session.firstSuggestionShowTime - this.sdkApiCallEndTime, - codewhispererPreprocessingLatency: session.fetchCredentialStartTime - session.invokeSuggestionStartTime, + codewhispererPreprocessingLatency: session.preprocessEndTime - session.invokeSuggestionStartTime, codewhispererRequestId: this.firstResponseRequestId, codewhispererSessionId: session.sessionId, codewhispererTriggerType: session.triggerType, From 00e41bee636cee119e999a2893a09838a2ed7f77 Mon Sep 17 00:00:00 2001 From: Will Lo Date: Wed, 8 Jan 2025 10:02:52 -0800 Subject: [PATCH 2/2] test --- .../util/telemetryHelper.test.ts | 42 +++++++++++++++++ .../src/codewhisperer/util/telemetryHelper.ts | 45 +++++++++++-------- 2 files changed, 69 insertions(+), 18 deletions(-) diff --git a/packages/amazonq/test/unit/codewhisperer/util/telemetryHelper.test.ts b/packages/amazonq/test/unit/codewhisperer/util/telemetryHelper.test.ts index d6190a6c0fd..e042b1d43a2 100644 --- a/packages/amazonq/test/unit/codewhisperer/util/telemetryHelper.test.ts +++ b/packages/amazonq/test/unit/codewhisperer/util/telemetryHelper.test.ts @@ -11,6 +11,7 @@ import { CodewhispererSuggestionState, CodewhispererUserDecision, } from 'aws-core-vscode/shared' +import sinon from 'sinon' // TODO: improve and move the following test utils to codewhisperer/testUtils.ts function aUserDecision( @@ -38,6 +39,47 @@ function aCompletion(): Completion { } describe('telemetryHelper', function () { + describe('clientComponentLatency', function () { + let sut: TelemetryHelper + + beforeEach(function () { + sut = new TelemetryHelper() + }) + + afterEach(function () { + sinon.restore() + }) + + it('resetClientComponentLatencyTime should reset state variables', function () { + session.invokeSuggestionStartTime = 100 + session.preprocessEndTime = 200 + session.sdkApiCallStartTime = 300 + session.fetchCredentialStartTime = 400 + session.firstSuggestionShowTime = 500 + + sut.setSdkApiCallEndTime() + sut.setAllPaginationEndTime() + sut.setFirstResponseRequestId('aFakeRequestId') + + sut.resetClientComponentLatencyTime() + + assert.strictEqual(session.invokeSuggestionStartTime, 0) + assert.strictEqual(session.preprocessEndTime, 0) + assert.strictEqual(session.sdkApiCallStartTime, 0) + assert.strictEqual(session.fetchCredentialStartTime, 0) + assert.strictEqual(session.firstSuggestionShowTime, 0) + assert.strictEqual(sut.sdkApiCallEndTime, 0) + assert.strictEqual(sut.allPaginationEndTime, 0) + assert.strictEqual(sut.firstResponseRequestId, '') + }) + + it('setInvocationSuggestionStartTime should call resetClientComponentLatencyTime', function () { + const resetStub = sinon.stub(sut, 'resetClientComponentLatencyTime') + sut.setInvokeSuggestionStartTime() + assert.ok(resetStub.calledOnce) + }) + }) + describe('aggregateUserDecisionByRequest', function () { let sut: TelemetryHelper diff --git a/packages/core/src/codewhisperer/util/telemetryHelper.ts b/packages/core/src/codewhisperer/util/telemetryHelper.ts index dcfdacfc438..a34deb0cdca 100644 --- a/packages/core/src/codewhisperer/util/telemetryHelper.ts +++ b/packages/core/src/codewhisperer/util/telemetryHelper.ts @@ -31,9 +31,18 @@ import { Session } from '../../amazonqTest/chat/session/session' export class TelemetryHelper { // Some variables for client component latency - private sdkApiCallEndTime = 0 - private allPaginationEndTime = 0 - private firstResponseRequestId = '' + private _sdkApiCallEndTime = 0 + get sdkApiCallEndTime(): number { + return this._sdkApiCallEndTime + } + private _allPaginationEndTime = 0 + get allPaginationEndTime(): number { + return this._allPaginationEndTime + } + private _firstResponseRequestId = '' + get firstResponseRequestId(): string { + return this._firstResponseRequestId + } // variables for user trigger decision // these will be cleared after a invocation session private sessionDecisions: CodewhispererUserTriggerDecision[] = [] @@ -584,11 +593,11 @@ export class TelemetryHelper { session.invokeSuggestionStartTime = 0 session.preprocessEndTime = 0 session.sdkApiCallStartTime = 0 - this.sdkApiCallEndTime = 0 + this._sdkApiCallEndTime = 0 session.fetchCredentialStartTime = 0 session.firstSuggestionShowTime = 0 - this.allPaginationEndTime = 0 - this.firstResponseRequestId = '' + this._allPaginationEndTime = 0 + this._firstResponseRequestId = '' } public setPreprocessEndTime() { @@ -605,46 +614,46 @@ export class TelemetryHelper { } public setSdkApiCallEndTime() { - if (this.sdkApiCallEndTime === 0 && session.sdkApiCallStartTime !== 0) { - this.sdkApiCallEndTime = performance.now() + if (this._sdkApiCallEndTime === 0 && session.sdkApiCallStartTime !== 0) { + this._sdkApiCallEndTime = performance.now() } } public setAllPaginationEndTime() { - if (this.allPaginationEndTime === 0 && this.sdkApiCallEndTime !== 0) { - this.allPaginationEndTime = performance.now() + if (this._allPaginationEndTime === 0 && this._sdkApiCallEndTime !== 0) { + this._allPaginationEndTime = performance.now() } } public setFirstSuggestionShowTime() { - if (session.firstSuggestionShowTime === 0 && this.sdkApiCallEndTime !== 0) { + if (session.firstSuggestionShowTime === 0 && this._sdkApiCallEndTime !== 0) { session.firstSuggestionShowTime = performance.now() } } public setFirstResponseRequestId(requestId: string) { - if (this.firstResponseRequestId === '') { - this.firstResponseRequestId = requestId + if (this._firstResponseRequestId === '') { + this._firstResponseRequestId = requestId } } // report client component latency after all pagination call finish // and at least one suggestion is shown to the user public tryRecordClientComponentLatency() { - if (session.firstSuggestionShowTime === 0 || this.allPaginationEndTime === 0) { + if (session.firstSuggestionShowTime === 0 || this._allPaginationEndTime === 0) { return } telemetry.codewhisperer_clientComponentLatency.emit({ - codewhispererAllCompletionsLatency: this.allPaginationEndTime - session.sdkApiCallStartTime, + codewhispererAllCompletionsLatency: this._allPaginationEndTime - session.sdkApiCallStartTime, codewhispererCompletionType: 'Line', codewhispererCredentialFetchingLatency: session.sdkApiCallStartTime - session.fetchCredentialStartTime, codewhispererCustomizationArn: getSelectedCustomization().arn, codewhispererEndToEndLatency: session.firstSuggestionShowTime - session.invokeSuggestionStartTime, - codewhispererFirstCompletionLatency: this.sdkApiCallEndTime - session.sdkApiCallStartTime, + codewhispererFirstCompletionLatency: this._sdkApiCallEndTime - session.sdkApiCallStartTime, codewhispererLanguage: session.language, - codewhispererPostprocessingLatency: session.firstSuggestionShowTime - this.sdkApiCallEndTime, + codewhispererPostprocessingLatency: session.firstSuggestionShowTime - this._sdkApiCallEndTime, codewhispererPreprocessingLatency: session.preprocessEndTime - session.invokeSuggestionStartTime, - codewhispererRequestId: this.firstResponseRequestId, + codewhispererRequestId: this._firstResponseRequestId, codewhispererSessionId: session.sessionId, codewhispererTriggerType: session.triggerType, credentialStartUrl: AuthUtil.instance.startUrl,