diff --git a/packages/amazonq/src/app/inline/completion.ts b/packages/amazonq/src/app/inline/completion.ts index be49a0654cc..9aaf40c4c43 100644 --- a/packages/amazonq/src/app/inline/completion.ts +++ b/packages/amazonq/src/app/inline/completion.ts @@ -198,7 +198,7 @@ export class InlineCompletionManager implements Disposable { } export class AmazonQInlineCompletionItemProvider implements InlineCompletionItemProvider { - private logger = getLogger('nextEditPrediction') + private logger = getLogger() constructor( private readonly languageClient: LanguageClient, private readonly recommendationService: RecommendationService, @@ -299,7 +299,8 @@ export class AmazonQInlineCompletionItemProvider implements InlineCompletionItem } // re-use previous suggestions as long as new typed prefix matches if (prevItemMatchingPrefix.length > 0) { - getLogger().debug(`Re-using suggestions that match user typed characters`) + logstr += `- not call LSP and reuse previous suggestions that match user typed characters + - duration between trigger to completion suggestion is displayed ${performance.now() - t0}` return prevItemMatchingPrefix } getLogger().debug(`Auto rejecting suggestions from previous session`) @@ -318,7 +319,6 @@ export class AmazonQInlineCompletionItemProvider implements InlineCompletionItem this.sessionManager.clear() } - // TODO: this line will take ~200ms each trigger, need to root cause and maybe better to disable it for now // tell the tutorial that completions has been triggered await this.inlineTutorialAnnotation.triggered(context.triggerKind) @@ -346,12 +346,13 @@ export class AmazonQInlineCompletionItemProvider implements InlineCompletionItem const t2 = performance.now() - logstr = logstr += `- number of suggestions: ${items.length} + logstr += `- number of suggestions: ${items.length} - sessionId: ${this.sessionManager.getActiveSession()?.sessionId} - first suggestion content (next line): ${itemLog} -- duration since trigger to before sending Flare call: ${t1 - t0}ms -- duration since trigger to receiving responses from Flare: ${t2 - t0}ms +- duration between trigger to before sending LSP call: ${t1 - t0}ms +- duration between trigger to after receiving LSP response: ${t2 - t0}ms +- duration between before sending LSP call to after receving LSP response: ${t2 - t1}ms ` const session = this.sessionManager.getActiveSession() @@ -361,16 +362,13 @@ ${itemLog} } if (!session || !items.length || !editor) { - getLogger().debug( - `Failed to produce inline suggestion results. Received ${items.length} items from service` - ) + logstr += `Failed to produce inline suggestion results. Received ${items.length} items from service` return [] } const cursorPosition = document.validatePosition(position) if (position.isAfter(editor.selection.active)) { - getLogger().debug(`Cursor moved behind trigger position. Discarding suggestion...`) const params: LogInlineCompletionSessionResultsParams = { sessionId: session.sessionId, completionSessionResult: { @@ -383,6 +381,7 @@ ${itemLog} } this.languageClient.sendNotification(this.logSessionResultMessageName, params) this.sessionManager.clear() + logstr += `- cursor moved behind trigger position. Discarding suggestion...` return [] } @@ -410,9 +409,7 @@ ${itemLog} // Check if Next Edit Prediction feature flag is enabled if (Experiments.instance.get('amazonqLSPNEP', true)) { await showEdits(item, editor, session, this.languageClient, this) - const t3 = performance.now() - logstr = logstr + `- duration since trigger to NEP suggestion is displayed: ${t3 - t0}ms` - this.logger.info(logstr) + logstr += `- duration between trigger to edits suggestion is displayed: ${performance.now() - t0}ms` } return [] } @@ -438,9 +435,6 @@ ${itemLog} // report discard if none of suggestions match typeahead if (itemsMatchingTypeahead.length === 0) { - getLogger().debug( - `Suggestion does not match user typeahead from insertion position. Discarding suggestion...` - ) const params: LogInlineCompletionSessionResultsParams = { sessionId: session.sessionId, completionSessionResult: { @@ -453,17 +447,21 @@ ${itemLog} } this.languageClient.sendNotification(this.logSessionResultMessageName, params) this.sessionManager.clear() + logstr += `- suggestion does not match user typeahead from insertion position. Discarding suggestion...` return [] } this.sessionManager.updateCodeReferenceAndImports() // suggestions returned here will be displayed on screen + logstr += `- duration between trigger to completion suggestion is displayed: ${performance.now() - t0}ms` return itemsMatchingTypeahead as InlineCompletionItem[] } catch (e) { getLogger('amazonqLsp').error('Failed to provide completion items: %O', e) + logstr += `- failed to provide completion items ${(e as Error).message}` return [] } finally { vsCodeState.isRecommendationsActive = false + this.logger.info(logstr) } } } diff --git a/packages/amazonq/src/app/inline/recommendationService.ts b/packages/amazonq/src/app/inline/recommendationService.ts index 1329c68a51c..c7ba5c3b4b7 100644 --- a/packages/amazonq/src/app/inline/recommendationService.ts +++ b/packages/amazonq/src/app/inline/recommendationService.ts @@ -92,13 +92,15 @@ export class RecommendationService { nextToken: request.partialResultToken, }, }) + const t0 = performance.now() const result: InlineCompletionListWithReferences = await languageClient.sendRequest( inlineCompletionWithReferencesRequestType.method, request, token ) - getLogger().info('Received inline completion response: %O', { + getLogger().info('Received inline completion response from LSP: %O', { sessionId: result.sessionId, + latency: performance.now() - t0, itemCount: result.items?.length || 0, items: result.items?.map((item) => ({ itemId: item.itemId, @@ -128,6 +130,7 @@ export class RecommendationService { const isInlineEdit = result.items.some((item) => item.isInlineEdit) + // TODO: question, is it possible that the first request returns empty suggestion but has non-empty next token? if (result.partialResultToken) { if (!isInlineEdit) { // If the suggestion is COMPLETIONS and there are more results to fetch, handle them in the background diff --git a/packages/amazonq/src/app/inline/tutorials/inlineTutorialAnnotation.ts b/packages/amazonq/src/app/inline/tutorials/inlineTutorialAnnotation.ts index bd12b1d28dd..ad0807df94c 100644 --- a/packages/amazonq/src/app/inline/tutorials/inlineTutorialAnnotation.ts +++ b/packages/amazonq/src/app/inline/tutorials/inlineTutorialAnnotation.ts @@ -5,13 +5,7 @@ import * as vscode from 'vscode' import * as os from 'os' -import { - AnnotationChangeSource, - AuthUtil, - inlinehintKey, - runtimeLanguageContext, - TelemetryHelper, -} from 'aws-core-vscode/codewhisperer' +import { AnnotationChangeSource, AuthUtil, inlinehintKey, runtimeLanguageContext } from 'aws-core-vscode/codewhisperer' import { editorUtilities, getLogger, globals, setContext, vscodeUtilities } from 'aws-core-vscode/shared' import { LinesChangeEvent, LineSelection, LineTracker } from '../stateTracker/lineTracker' import { telemetry } from 'aws-core-vscode/telemetry' @@ -296,28 +290,27 @@ export class InlineTutorialAnnotation implements vscode.Disposable { } async triggered(triggerType: vscode.InlineCompletionTriggerKind): Promise { - await telemetry.withTraceId(async () => { - if (!this._isReady) { - return - } - - if (this._currentState instanceof ManualtriggerState) { - if ( - triggerType === vscode.InlineCompletionTriggerKind.Invoke && - this._currentState.hasManualTrigger === false - ) { - this._currentState.hasManualTrigger = true - } - if ( - this.sessionManager.getActiveRecommendation().length > 0 && - this._currentState.hasValidResponse === false - ) { - this._currentState.hasValidResponse = true - } - } - - await this.refresh(vscode.window.activeTextEditor, 'codewhisperer') - }, TelemetryHelper.instance.traceId) + // TODO: this logic will take ~200ms each trigger, need to root cause and re-enable once it's fixed, or it should only be invoked when the tutorial is actually needed + // await telemetry.withTraceId(async () => { + // if (!this._isReady) { + // return + // } + // if (this._currentState instanceof ManualtriggerState) { + // if ( + // triggerType === vscode.InlineCompletionTriggerKind.Invoke && + // this._currentState.hasManualTrigger === false + // ) { + // this._currentState.hasManualTrigger = true + // } + // if ( + // this.sessionManager.getActiveRecommendation().length > 0 && + // this._currentState.hasValidResponse === false + // ) { + // this._currentState.hasValidResponse = true + // } + // } + // await this.refresh(vscode.window.activeTextEditor, 'codewhisperer') + // }, TelemetryHelper.instance.traceId) } isTutorialDone(): boolean {