telemetry(inline-suggestion): Fix incorrect clientComponentLatency@preprocessLatency (aws#6320)

## Problem

t1: user trigger inline suggestion either automatically or manually
t2: start building request with editor context
t3: done building request
t4: call service API

PreprocessLatency is supposed to denote `t3 - t1`, whereas current
implementation isn't which has been using
`codewhispererPreprocessingLatency: session.fetchCredentialStartTime -
session.invokeSuggestionStartTime,`












## Solution


---

- Treat all work as PUBLIC. Private `feature/x` branches will not be
squash-merged at release time.
- Your code changes must meet the guidelines in
[CONTRIBUTING.md](https://github.com/aws/aws-toolkit-vscode/blob/master/CONTRIBUTING.md#guidelines).
- License: I confirm that my contribution is made under the terms of the
Apache 2.0 license.

Author: Will-ShaoHua

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
 

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)) {

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

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[] = []
@@ -582,12 +591,20 @@ export class TelemetryHelper {
 
     public resetClientComponentLatencyTime() {
         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() {
+        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 **/
@@ -597,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,
-            codewhispererPreprocessingLatency: session.fetchCredentialStartTime - session.invokeSuggestionStartTime,
-            codewhispererRequestId: this.firstResponseRequestId,
+            codewhispererPostprocessingLatency: session.firstSuggestionShowTime - this._sdkApiCallEndTime,
+            codewhispererPreprocessingLatency: session.preprocessEndTime - session.invokeSuggestionStartTime,
+            codewhispererRequestId: this._firstResponseRequestId,
             codewhispererSessionId: session.sessionId,
             codewhispererTriggerType: session.triggerType,
             credentialStartUrl: AuthUtil.instance.startUrl,