Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Autocomplete: Overhaul telemetry and fix various corner cases #412

Merged
merged 6 commits into from
Jul 31, 2023
Merged

Autocomplete: Overhaul telemetry and fix various corner cases #412

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
cdf9f9a
Autocomplete: Overhaul telemetry and fix various corner cases
philipp-spiess Jul 27, 2023
6016a89
Merge remote-tracking branch 'origin/main' into ps/autocomplete-telem…
philipp-spiess Jul 27, 2023
59cb305
Fixes
philipp-spiess Jul 27, 2023
64c1978
Fixes
philipp-spiess Jul 27, 2023
77757b2
Merge remote-tracking branch 'origin/main' into ps/autocomplete-telem…
philipp-spiess Jul 28, 2023
ab7e49e
Remove impossible case
philipp-spiess Jul 31, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
10 changes: 10 additions & 0 deletions vscode/src/completions/cache.test.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -84,4 +84,14 @@ describe('CompletionsCache', () => {
})
expect(cache.get('foo\n ', false)).toEqual(undefined)
})

it('updates the log id for all cached entries', () => {
const cache = new CompletionsCache()
cache.add('id1', [{ prefix: 'foo \n ', content: 'bar' }])
cache.updateLogId('id1', 'id2')

expect(cache.get('foo \n ', true)?.logId).toBe('id2')
expect(cache.get('foo \n ', true)?.logId).toBe('id2')
expect(cache.get('foo \n', true)?.logId).toBe('id2')
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

why 3 expect calls? Just to make sure that there is no toggle state behind the CompleationsCache?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah I wanted to make sure all occurrences are updated.

})
})
9 changes: 9 additions & 0 deletions vscode/src/completions/cache.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -78,6 +78,15 @@ export class CompletionsCache {
}
}

public updateLogId(oldLogId: string, newLogId: string): void {
const entries = this.cache.values()
for (const value of entries) {
if (value && 'logId' in value && value.logId === oldLogId) {
value.logId = newLogId
}
}
}

private insertCompletion(key: string, logId: string, completion: Completion, isExactPrefix: boolean): void {
let existingCompletions: Completion[] = []
if (this.cache.has(key)) {
Expand Down
228 changes: 142 additions & 86 deletions vscode/src/completions/index.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -50,6 +50,7 @@ export class CodyCompletionItemProvider implements vscode.InlineCompletionItemPr
private readonly config: Required<CodyCompletionItemProviderConfig>

private requestManager: RequestManager
private previousCompletionLogId?: string

constructor({
responsePercentage = 0.1,
Expand Down Expand Up @@ -134,13 +135,12 @@ export class CodyCompletionItemProvider implements vscode.InlineCompletionItemPr
tracer?.({ error: error.toString() })
this.stopLoading()

if (isAbortError(error)) {
return { items: [] }
if (!isAbortError(error)) {
console.error(error)
debug('CodyCompletionProvider:inline:error', `${error.toString()}\n${error.stack}`)
}

console.error(error)
debug('CodyCompletionProvider:inline:error', `${error.toString()}\n${error.stack}`)
return { items: [] }
return emptyCompletions()
}
}

Expand All @@ -160,15 +160,13 @@ export class CodyCompletionItemProvider implements vscode.InlineCompletionItemPr
this.abortOpenCompletions = () => abortController.abort()
}

CompletionLogger.clear()
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Clearing the completion logger will flush all "open" completions, potentially logging completions that are being visible. This is used to measure for how long completions are necessary and thus we want to delay it as long as possible so we can get the most accurate timing.

Previously, every new completion request would immediately flush the queue. Now, however, a cache hit that matches the properties that I outlined in the PR description and is this "completed forward" won't, so we'll have a more accurate number of how long such completions are visible.


if (!vscode.window.activeTextEditor || document.uri.scheme === 'cody') {
return { items: [] }
return emptyCompletions()
}

const docContext = getCurrentDocContext(document, position, this.maxPrefixChars, this.maxSuffixChars)
if (!docContext) {
return { items: [] }
return emptyCompletions()
}

const { prefix, suffix, prevNonEmptyLine } = docContext
Expand All @@ -188,6 +186,36 @@ export class CodyCompletionItemProvider implements vscode.InlineCompletionItemPr
this.config.providerConfig.enableExtendedMultilineTriggers
)

// Don't show completions if we are in the process of writing a word.
const cursorAtWord = /\w$/.test(sameLinePrefix)
if (cursorAtWord && !this.config.triggerMoreEagerly) {
return emptyCompletions()
}
const triggeredMoreEagerly = this.config.triggerMoreEagerly && cursorAtWord

let triggeredForSuggestWidgetSelection: string | undefined
if (context.selectedCompletionInfo) {
if (this.config.completeSuggestWidgetSelection) {
triggeredForSuggestWidgetSelection = context.selectedCompletionInfo.text
} else {
// Don't show completions if the suggest widget (which shows language autocomplete)
// is showing.
return emptyCompletions()
}
}

// If we have a suffix in the same line as the cursor and the suffix contains any word
// characters, do not attempt to make a completion. This means we only make completions if
// we have a suffix in the same line for special characters like `)]}` etc.
//
// VS Code will attempt to merge the remainder of the current line by characters but for
// words this will easily get very confusing.
if (/\w/.test(sameLineSuffix)) {
return emptyCompletions()
}

let cachedCompletions: CachedCompletions | undefined

// Avoid showing completions when we're deleting code (Cody can only insert code at the
// moment)
const lastChange = this.lastContentChanges.get(document.fileName) ?? 'add'
Expand All @@ -196,36 +224,69 @@ export class CodyCompletionItemProvider implements vscode.InlineCompletionItemPr
// untruncated prefix matches. This fixes some weird issues where the completion would
// render if you insert whitespace but not on the original place when you delete it
// again
const cachedCompletions = this.config.cache?.get(prefix, false)
if (cachedCompletions?.isExactPrefix) {
tracer?.({ cacheHit: true })
return this.handleCacheHit(
cachedCompletions,
document,
context,
position,
prefix,
suffix,
multiline,
document.languageId,
abortController.signal
)
cachedCompletions = this.config.cache?.get(prefix, false)
if (cachedCompletions && !cachedCompletions.isExactPrefix) {
return emptyCompletions()
}
return { items: [] }
}

const cachedCompletions = this.config.cache?.get(prefix)
// If cachedCompletions was already set by the above logic, we don't have to query the cache
// again.
cachedCompletions = cachedCompletions ?? this.config.cache?.get(prefix)

// We create a log entry after determining if we have a potential cache hit. This is
// necessary to make sure that typing text of a displayed completion will not log a new
// completion on every keystroke
//
// However we only log a completion as started if it's either served from cache _or_ the
// debounce interval has passed to ensure we don't log too many start events where we end up
// not doing any work at all
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The completion logger now has a separate create and start method. This fixes an issue where we haven't properly measured end to end latencies in our completions because we only started it when we actively start to do some work, which happens after both the pre-defined debounce times (30ms) and context retrieval (few ms).

I don't expect this to have a big impact on the overall latencies, certainly not over 50ms, but we should aim to be as close to the real-user experience as possible with these logs.

This won't change the overall amount of events logged, though, because nothing is being logged until the start method is called. We just start the timers a bit earlier.

const useLogIdFromPreviousCompletion =
cachedCompletions?.logId && cachedCompletions?.logId === this.previousCompletionLogId
Comment on lines +244 to +245
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This line makes sure that "forwarding completions" don't get a new analytics event assigned. In the future, we might be able to do that with the new enableForwardStability option

if (!useLogIdFromPreviousCompletion) {
CompletionLogger.clear()
}
const logId = useLogIdFromPreviousCompletion
? cachedCompletions!.logId
: CompletionLogger.create({
multiline,
providerIdentifier: this.config.providerConfig.identifier,
languageId: document.languageId,
triggeredMoreEagerly,
triggeredForSuggestWidgetSelection: triggeredForSuggestWidgetSelection !== undefined,
settings: {
autocompleteExperimentalTriggerMoreEagerly: this.config.triggerMoreEagerly,
autocompleteExperimentalCompleteSuggestWidgetSelection: Boolean(
this.config.completeSuggestWidgetSelection
),
},
})
this.previousCompletionLogId = logId

if (cachedCompletions) {
// When we serve a completion from the cache and create a new log
// id, we want to ensure to only refer to the new id for future
// cache retrievals. If we don't do this, every subsequent cache hit
// would otherwise no longer match the previous completion ID and we
// would log a new completion each time, even if the user just
// continues typing on the currently displayed completion.
if (logId !== cachedCompletions.logId) {
this.config.cache?.updateLogId(cachedCompletions.logId, logId)
}
Comment on lines +267 to +275
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pretty much a corner case but updating the ids in our cache is necessary in the following scenario:

  • We start a completion request with ID 1 and display it, cool.
  • Now the user does something else which will start and show other completion requests.
  • Eventually, the prefix matches the first completion request again. The cache will retrieve the item with id 1 however that won't match the previousCompletionLogId.
  • This will cause the above code to create a new ID, say 3.
  • On the next forward request, the cache would again resolve with the id 1 when the previousCompletionLogId would be 3 which would create yet another completion request...

To fix this, we update the cache to refer to the new log id's whenever they're changed.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think this is working as you described, I think this comment from me here isn't a blocker, but if we take a step back maybe we should have some centralised system about logId. It looks like that we're trying to sync log and cache IDs in order to avoid double logging when cache is actually the same, maybe we could use some cache encode function for this kind of purpose? In this case there won't be possible to have different ids if prefixes are the same.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah I don't like this bookkeeping either. It's going to be interesting to see what @sqs will come up in #442 where he's currently seemingly not using a cache at all!

The only reason why we need to keep the log id around is to make sure we can detect cases where the same completion is resolve again after some suffix changes. Maybe we can instead just store the whole completion somewhere and compare that instead of the generated ID?


tracer?.({ cacheHit: true })
return this.handleCacheHit(
cachedCompletions,
CompletionLogger.start(logId)
return this.prepareCompletions(
logId,
cachedCompletions.completions,
document,
context,
position,
prefix,
suffix,
multiline,
document.languageId,
true,
abortController.signal
)
}
Expand All @@ -234,34 +295,6 @@ export class CodyCompletionItemProvider implements vscode.InlineCompletionItemPr
const completers: Provider[] = []
let timeout: number

// Don't show completions if we are in the process of writing a word.
const cursorAtWord = /\w$/.test(sameLinePrefix)
if (cursorAtWord && !this.config.triggerMoreEagerly) {
return { items: [] }
}
const triggeredMoreEagerly = this.config.triggerMoreEagerly && cursorAtWord

let triggeredForSuggestWidgetSelection: string | undefined
if (context.selectedCompletionInfo) {
if (this.config.completeSuggestWidgetSelection) {
triggeredForSuggestWidgetSelection = context.selectedCompletionInfo.text
} else {
// Don't show completions if the suggest widget (which shows language autocomplete)
// is showing.
return { items: [] }
}
}

// If we have a suffix in the same line as the cursor and the suffix contains any word
// characters, do not attempt to make a completion. This means we only make completions if
// we have a suffix in the same line for special characters like `)]}` etc.
//
// VS Code will attempt to merge the remainder of the current line by characters but for
// words this will easily get very confusing.
if (/\w/.test(sameLineSuffix)) {
return { items: [] }
}

const sharedProviderOptions: Omit<ProviderOptions, 'id' | 'n' | 'multiline'> = {
prefix,
suffix,
Expand Down Expand Up @@ -310,9 +343,11 @@ export class CodyCompletionItemProvider implements vscode.InlineCompletionItemPr
// We don't need to make a request at all if the signal is already aborted after the
// debounce
if (abortController.signal.aborted) {
return { items: [] }
return emptyCompletions()
}

CompletionLogger.start(logId)

const contextResult = await this.config.contextFetcher({
document,
prefix,
Expand All @@ -324,25 +359,12 @@ export class CodyCompletionItemProvider implements vscode.InlineCompletionItemPr
isEmbeddingsContextEnabled: this.config.isEmbeddingsContextEnabled,
})
if (abortController.signal.aborted) {
return { items: [] }
return emptyCompletions()
}
tracer?.({ context: contextResult })

const logId = CompletionLogger.start({
type: 'inline',
multiline,
providerIdentifier: this.config.providerConfig.identifier,
languageId: document.languageId,
contextSummary: contextResult.logSummary,
triggeredMoreEagerly,
triggeredForSuggestWidgetSelection: triggeredForSuggestWidgetSelection !== undefined,
settings: {
autocompleteExperimentalTriggerMoreEagerly: this.config.triggerMoreEagerly,
autocompleteExperimentalCompleteSuggestWidgetSelection: Boolean(
this.config.completeSuggestWidgetSelection
),
},
})
CompletionLogger.networkRequestStarted(logId, contextResult.logSummary)
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We previously appended the context summary in the completion started event. Now, however, we log these events before the context is fetched so I decided to split this into a separate event. We haven't used any of these yet, though.


const stopLoading = this.config.statusBar.startLoading('Completions are being generated')
this.stopLoading = stopLoading

Expand All @@ -363,31 +385,36 @@ export class CodyCompletionItemProvider implements vscode.InlineCompletionItemPr
tracer ? createCompletionProviderTracer(tracer) : undefined
)

// Shared post-processing logic
const processedCompletions = processCompletions(completions, prefix, suffix, multiline, document.languageId)
stopLoading()

if (processedCompletions.length > 0) {
CompletionLogger.suggest(logId)
return toInlineCompletionItems(logId, document, position, processedCompletions)
}

CompletionLogger.noResponse(logId)
return { items: [] }
return this.prepareCompletions(
logId,
completions,
document,
context,
position,
prefix,
suffix,
multiline,
document.languageId,
false,
abortController.signal
)
}

private async handleCacheHit(
cachedCompletions: CachedCompletions,
private async prepareCompletions(
logId: string,
completions: Completion[],
document: vscode.TextDocument,
context: vscode.InlineCompletionContext,
position: vscode.Position,
prefix: string,
suffix: string,
multiline: boolean,
languageId: string,
isCacheHit: boolean,
abortSignal: AbortSignal
): Promise<vscode.InlineCompletionList> {
const results = processCompletions(cachedCompletions.completions, prefix, suffix, multiline, languageId)
const results = processCompletions(completions, prefix, suffix, multiline, languageId)

// We usually resolve cached results instantly. However, if the inserted completion would
// include more than one line, this can create a lot of visible UI churn. To avoid this, we
Expand All @@ -398,6 +425,7 @@ export class CodyCompletionItemProvider implements vscode.InlineCompletionItemPr
// have network latency for cache completion
const visibleResult = results[0]
if (
isCacheHit &&
visibleResult?.content.includes('\n') &&
!this.config.disableTimeouts &&
context.triggerKind !== vscode.InlineCompletionTriggerKind.Invoke
Expand All @@ -408,7 +436,30 @@ export class CodyCompletionItemProvider implements vscode.InlineCompletionItemPr
}
}

return toInlineCompletionItems(cachedCompletions.logId, document, position, results)
if (results.length > 0) {
// When the VS Code completion popup is open and we suggest a completion that does not match
// the currently selected completion, VS Code won't display it. For now we make sure to not
// log these completions as displayed.
//
// TODO: Take this into account when creating the completion prefix.
let isCompletionVisible = true
if (context.selectedCompletionInfo) {
const currentText = document.getText(context.selectedCompletionInfo.range)
const selectedText = context.selectedCompletionInfo.text
if (!(currentText + results[0].content).startsWith(selectedText)) {
isCompletionVisible = false
}
}

if (isCompletionVisible) {
CompletionLogger.suggest(logId, isCompletionVisible)
}

return toInlineCompletionItems(logId, document, position, results)
}

CompletionLogger.noResponse(logId)
return emptyCompletions()
}
}

Expand Down Expand Up @@ -488,6 +539,11 @@ function createTracerForInvocation(tracer: ProvideInlineCompletionItemsTracer):
}
}

function emptyCompletions(): vscode.InlineCompletionList {
CompletionLogger.clear()
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Whenever we early return, we want to flush the completions queue. This conceptually makes sense because if we return an empty array at any point, it means no completions form us are visible anymore anyways.

return { items: [] }
}

function createCompletionProviderTracer(tracer: SingleInvocationTracer): CompletionProviderTracer {
return {
params: data => tracer({ completionProviderCallParams: data }),
Expand Down
Loading
Loading