Skip to content

Commit 68c6d14

Browse files
Will-ShaoHuaWill-ShaoHua
authored
fix: inline latency telemetry should account for preprocess time (aws#2323)
1 parent b31cf67 commit 68c6d14

File tree

9 files changed

+55
-24
lines changed

9 files changed

+55
-24
lines changed

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

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1479,6 +1479,7 @@ describe('CodeWhisperer Server', () => {
14791479

14801480
const sessionData: SessionData = {
14811481
document: TextDocument.create('file:///rightContext.cs', 'csharp', 1, HELLO_WORLD_IN_CSHARP),
1482+
startPreprocessTimestamp: 0,
14821483
startPosition: { line: 0, character: 0 },
14831484
triggerType: 'OnDemand',
14841485
language: 'csharp',

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

Lines changed: 7 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -225,6 +225,8 @@ export const CodewhispererServerFactory =
225225
const maxResults = isAutomaticLspTriggerKind ? 1 : 5
226226
const selectionRange = params.context.selectedCompletionInfo?.range
227227

228+
const startPreprocessTimestamp = Date.now()
229+
228230
// For Jupyter Notebook in VSC, the language server does not have access to
229231
// its internal states including current active cell index, etc
230232
// we rely on VSC to calculate file context
@@ -256,7 +258,7 @@ export const CodewhispererServerFactory =
256258
const previousSession = completionSessionManager.getPreviousSession()
257259
// Only refer to decisions in the past 2 mins
258260
const previousDecisionForClassifier =
259-
previousSession && performance.now() - previousSession.decisionMadeTimestamp <= 2 * 60 * 1000
261+
previousSession && Date.now() - previousSession.decisionMadeTimestamp <= 2 * 60 * 1000
260262
? previousSession.getAggregatedUserTriggerDecision()
261263
: undefined
262264
let ideCategory: string | undefined = ''
@@ -357,6 +359,7 @@ export const CodewhispererServerFactory =
357359

358360
const newSession = completionSessionManager.createSession({
359361
document: textDocument,
362+
startPreprocessTimestamp: startPreprocessTimestamp,
360363
startPosition: params.position,
361364
triggerType: isAutomaticLspTriggerKind ? 'AutoTrigger' : 'OnDemand',
362365
language: fileContext.programmingLanguage.languageName as CodewhispererLanguage,
@@ -425,7 +428,7 @@ export const CodewhispererServerFactory =
425428
session.suggestions = suggestionResponse.suggestions
426429
session.responseContext = suggestionResponse.responseContext
427430
session.codewhispererSessionId = suggestionResponse.responseContext.codewhispererSessionId
428-
session.timeToFirstRecommendation = new Date().getTime() - session.startTime
431+
session.setTimeToFirstRecommendation()
429432
session.predictionType = SuggestionType.COMPLETION
430433
} else {
431434
session.suggestions = [...session.suggestions, ...suggestionResponse.suggestions]
@@ -843,9 +846,9 @@ export const CodewhispererServerFactory =
843846

844847
// Record last user modification time for any document
845848
if (lastUserModificationTime) {
846-
timeSinceLastUserModification = new Date().getTime() - lastUserModificationTime
849+
timeSinceLastUserModification = Date.now() - lastUserModificationTime
847850
}
848-
lastUserModificationTime = new Date().getTime()
851+
lastUserModificationTime = Date.now()
849852

850853
documentChangedListener.onDocumentChanged(p)
851854
editCompletionHandler.documentChanged()

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

Lines changed: 6 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -128,6 +128,7 @@ export class EditCompletionHandler {
128128

129129
// Not ideally to rely on a state, should improve it and simply make it a debounced API
130130
this.isInProgress = true
131+
const startPreprocessTimestamp = Date.now()
131132

132133
if (params.partialResultToken && currentSession) {
133134
// Close ACTIVE session. We shouldn't record Discard trigger decision for trigger with nextToken.
@@ -138,6 +139,7 @@ export class EditCompletionHandler {
138139
const newSession = this.sessionManager.createSession({
139140
document: textDocument,
140141
startPosition: params.position,
142+
startPreprocessTimestamp: startPreprocessTimestamp,
141143
triggerType: 'AutoTrigger',
142144
language: currentSession.language,
143145
requestContext: currentSession.requestContext,
@@ -174,6 +176,7 @@ export class EditCompletionHandler {
174176
this.isWaiting = true
175177
const result = await this._invoke(
176178
params,
179+
startPreprocessTimestamp,
177180
token,
178181
textDocument,
179182
inferredLanguageId,
@@ -205,6 +208,7 @@ export class EditCompletionHandler {
205208

206209
async _invoke(
207210
params: InlineCompletionWithReferencesParams,
211+
startPreprocessTimestamp: number,
208212
token: CancellationToken,
209213
textDocument: TextDocument,
210214
inferredLanguageId: CodewhispererLanguage,
@@ -298,6 +302,7 @@ export class EditCompletionHandler {
298302

299303
const newSession = this.sessionManager.createSession({
300304
document: textDocument,
305+
startPreprocessTimestamp: startPreprocessTimestamp,
301306
startPosition: params.position,
302307
triggerType: isAutomaticLspTriggerKind ? 'AutoTrigger' : 'OnDemand',
303308
language: fileContext.programmingLanguage.languageName,
@@ -340,7 +345,7 @@ export class EditCompletionHandler {
340345
session.suggestions = suggestionResponse.suggestions
341346
session.responseContext = suggestionResponse.responseContext
342347
session.codewhispererSessionId = suggestionResponse.responseContext.codewhispererSessionId
343-
session.timeToFirstRecommendation = new Date().getTime() - session.startTime
348+
session.setTimeToFirstRecommendation()
344349
session.predictionType = SuggestionType.EDIT
345350
} else {
346351
session.suggestions = [...session.suggestions, ...suggestionResponse.suggestions]

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

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -28,6 +28,7 @@ describe('CodeWhispererSession', function () {
2828

2929
const data: SessionData = {
3030
document: TextDocument.create('file:///rightContext.cs', 'csharp', 1, HELLO_WORLD_IN_CSHARP),
31+
startPreprocessTimestamp: 0,
3132
startPosition: { line: 0, character: 0 },
3233
triggerType: 'OnDemand',
3334
language: 'csharp',
@@ -510,6 +511,7 @@ describe('SessionManager', function () {
510511
}
511512
const data: SessionData = {
512513
document: TextDocument.create('file:///rightContext.cs', 'csharp', 1, HELLO_WORLD_IN_CSHARP),
514+
startPreprocessTimestamp: 0,
513515
startPosition: { line: 0, character: 0 },
514516
triggerType: 'OnDemand',
515517
language: 'csharp',

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

Lines changed: 22 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -25,6 +25,7 @@ interface CachedSuggestion extends Suggestion {
2525

2626
export interface SessionData {
2727
document: TextDocument
28+
startPreprocessTimestamp: number
2829
startPosition: Position
2930
triggerType: CodewhispererTriggerType
3031
autoTriggerType?: CodewhispererAutomatedTriggerType
@@ -42,6 +43,13 @@ export class CodeWhispererSession {
4243
id: string
4344
document: TextDocument
4445
startTime: number
46+
private _endPreprocessTimestamp: number
47+
get endPreprocessTimestamp() {
48+
return this._endPreprocessTimestamp
49+
}
50+
get preprocessLatency() {
51+
return this.endPreprocessTimestamp - this.startTime
52+
}
4553
// Time when Session was closed and final state of user decisions is recorded in suggestionsStates
4654
closeTime?: number = 0
4755
private _state: SessionState
@@ -77,7 +85,14 @@ export class CodeWhispererSession {
7785
language: CodewhispererLanguage
7886
requestContext: GenerateSuggestionsRequest
7987
supplementalMetadata?: CodeWhispererSupplementalContext
80-
timeToFirstRecommendation: number = 0
88+
private _timeToFirstRecommendation: number = 0
89+
get timeToFirstRecommendation() {
90+
return this._timeToFirstRecommendation
91+
}
92+
setTimeToFirstRecommendation() {
93+
this._timeToFirstRecommendation = Date.now() - this.startTime
94+
}
95+
8196
credentialStartUrl?: string
8297
completionSessionResult?: {
8398
[itemId: string]: InlineCompletionStates
@@ -111,8 +126,9 @@ export class CodeWhispererSession {
111126
this.customizationArn = data.customizationArn
112127
this.supplementalMetadata = data.supplementalMetadata
113128
this._state = 'REQUESTING'
114-
115-
this.startTime = new Date().getTime()
129+
this.startTime = data.startPreprocessTimestamp
130+
// Current implementation is the session will be created when preprocess is done
131+
this._endPreprocessTimestamp = Date.now()
116132
}
117133

118134
// This function makes it possible to stub uuidv4 calls in tests
@@ -147,7 +163,7 @@ export class CodeWhispererSession {
147163
}
148164
}
149165

150-
this.closeTime = new Date().getTime()
166+
this.closeTime = Date.now()
151167

152168
this.state = 'CLOSED'
153169
}
@@ -162,11 +178,12 @@ export class CodeWhispererSession {
162178
this.suggestionsStates.set(suggestion.itemId, 'Discard')
163179
}
164180

165-
this.closeTime = new Date().getTime()
181+
this.closeTime = Date.now()
166182

167183
this.state = 'DISCARD'
168184
}
169185

186+
// Should use epoch time for firstCompletionDisplayLatency, totalSessionDisplayTime
170187
setClientResultData(
171188
completionSessionResult: { [itemId: string]: InlineCompletionStates },
172189
firstCompletionDisplayLatency?: number,

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

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -482,7 +482,7 @@ export class CodeWhispererServiceToken extends CodeWhispererServiceBase {
482482
tokenRequest.customizationArn = this.customizationArn
483483
}
484484

485-
const beforeApiCall = performance.now()
485+
const beforeApiCall = Date.now()
486486
let recentEditsLogStr = ''
487487
const recentEdits = tokenRequest.supplementalContexts?.filter(it => it.type === 'PreviousEditorState')
488488
if (recentEdits) {
@@ -528,7 +528,7 @@ export class CodeWhispererServiceToken extends CodeWhispererServiceBase {
528528
"response.completions.length": ${response.completions?.length ?? 0},
529529
"response.predictions.length": ${response.predictions?.length ?? 0},
530530
"predictionType": ${tokenRequest.predictionTypes?.toString() ?? ''},
531-
"latency": ${performance.now() - beforeApiCall},
531+
"latency": ${Date.now() - beforeApiCall},
532532
"response.nextToken": ${response.nextToken},
533533
"firstSuggestion": ${firstSuggestionLogstr}`
534534

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

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -30,7 +30,7 @@ export async function fetchSupplementalContext(
3030
cancellationToken: CancellationToken,
3131
openTabFiles?: string[]
3232
): Promise<CodeWhispererSupplementalContext | undefined> {
33-
const timesBeforeFetching = performance.now()
33+
const timesBeforeFetching = Date.now()
3434

3535
const isUtg = unitTestIntentDetector.detectUnitTestIntent(document)
3636

@@ -55,7 +55,7 @@ export async function fetchSupplementalContext(
5555
},
5656
],
5757
contentsLength: srcContent.length,
58-
latency: performance.now() - timesBeforeFetching,
58+
latency: Date.now() - timesBeforeFetching,
5959
strategy: 'NEW_UTG',
6060
}
6161
}
@@ -87,7 +87,7 @@ export async function fetchSupplementalContext(
8787
(acc, curr) => acc + curr.content.length,
8888
0
8989
),
90-
latency: performance.now() - timesBeforeFetching,
90+
latency: Date.now() - timesBeforeFetching,
9191
strategy: supplementalContextValue.strategy,
9292
}
9393

@@ -119,7 +119,7 @@ export async function fetchSupplementalContext(
119119
isProcessTimeout: true,
120120
supplementalContextItems: [],
121121
contentsLength: 0,
122-
latency: performance.now() - timesBeforeFetching,
122+
latency: Date.now() - timesBeforeFetching,
123123
strategy: 'Empty',
124124
}
125125
} else {

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

Lines changed: 9 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -179,7 +179,8 @@ export class TelemetryService {
179179
if (this.modelId !== undefined) {
180180
request.modelId = this.modelId
181181
}
182-
await this.getService().sendTelemetryEvent(request)
182+
const r = await this.getService().sendTelemetryEvent(request)
183+
this.logging.log(`SendTelemetryEvent succeeded, requestId: ${r.$response.requestId}`)
183184
} catch (error) {
184185
this.logSendTelemetryEventFailure(error)
185186
}
@@ -199,7 +200,7 @@ export class TelemetryService {
199200
removedIdeDiagnostics?: IdeDiagnostic[],
200201
streakLength?: number
201202
) {
202-
session.decisionMadeTimestamp = performance.now()
203+
session.decisionMadeTimestamp = Date.now()
203204
// Toolkit telemetry API
204205
if (this.enableTelemetryEventsToDestination) {
205206
const data: CodeWhispererUserTriggerDecisionEvent = {
@@ -269,9 +270,7 @@ export class TelemetryService {
269270
completionType:
270271
session.suggestions.length > 0 ? getCompletionType(session.suggestions[0]).toUpperCase() : 'LINE',
271272
suggestionState: this.getSuggestionState(userTriggerDecision),
272-
recommendationLatencyMilliseconds: session.firstCompletionDisplayLatency
273-
? session.firstCompletionDisplayLatency
274-
: 0,
273+
recommendationLatencyMilliseconds: session.firstCompletionDisplayLatency ?? 0,
275274
timestamp: new Date(Date.now()),
276275
triggerToResponseLatencyMilliseconds: session.timeToFirstRecommendation,
277276
suggestionReferenceCount: referenceCount,
@@ -286,14 +285,16 @@ export class TelemetryService {
286285
streakLength: streakLength ?? 0,
287286
suggestionType: session.predictionType,
288287
}
289-
this.logging.info(`Invoking SendTelemetryEvent:UserTriggerDecisionEvent with:
288+
this.logging.info(`Invoking SendTelemetryEvent:UserTriggerDecisionEvent:
290289
"requestId": ${event.requestId}
291290
"suggestionState": ${event.suggestionState}
292291
"acceptedCharacterCount": ${event.acceptedCharacterCount}
293292
"addedCharacterCount": ${event.addedCharacterCount}
294293
"deletedCharacterCount": ${event.deletedCharacterCount}
295-
"streakLength": ${event.streakLength}
296-
"firstCompletionDisplayLatency: ${event.recommendationLatencyMilliseconds}
294+
"streakLength": ${event.streakLength},
295+
"preprocessLatency": ${session.preprocessLatency},
296+
"triggerToResponseLatencyMilliseconds: ${event.triggerToResponseLatencyMilliseconds}",
297+
"firstCompletionDisplayLatency: ${event.recommendationLatencyMilliseconds},
297298
"suggestionType": ${event.suggestionType}`)
298299
return this.invokeSendTelemetryEvent({
299300
userTriggerDecisionEvent: event,

‎server/aws-lsp-codewhisperer/src/shared/testUtils.ts‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -251,6 +251,7 @@ export const EMPTY_RESULT = { items: [], sessionId: '' }
251251

252252
export const SAMPLE_SESSION_DATA: SessionData = {
253253
document: SOME_FILE,
254+
startPreprocessTimestamp: 0,
254255
startPosition: {
255256
line: 0,
256257
character: 0,
@@ -270,6 +271,7 @@ export const SAMPLE_SESSION_DATA: SessionData = {
270271

271272
export const SAMPLE_SESSION_DATA_WITH_EXTRA_LEFT_CONTENT: SessionData = {
272273
document: SOME_INCOMPLETE_FILE,
274+
startPreprocessTimestamp: 0,
273275
startPosition: {
274276
line: 1,
275277
character: 0,

0 commit comments

Comments
 (0)