From cf293c056e5956f4a8da42e38e7bd0866bd5d0ef Mon Sep 17 00:00:00 2001 From: Valery Bugakov Date: Mon, 14 Oct 2024 14:56:09 +0800 Subject: [PATCH] VS Code: improve characters logger (#5855) This update fixes data discrepancies in calculating the percentage of code written by Cody events by increasing the accuracy of the `CharactersLogger`. Previously, the logger was counting character changes not directly typed by the user. Now, document changes are grouped by sources, providing flexibility in handling this data as needed. The new `cody.characters` telemetry event structure: ```json { "normal_inserted": 0, "normal_deleted": 0, "undo_inserted": 0, "undo_deleted": 0, "redo_inserted": 0, "redo_deleted": 0, "windowNotFocused_inserted": 0, "windowNotFocused_deleted": 0, "nonVisibleDocument_inserted": 3, "nonVisibleDocument_deleted": 0, "inactiveSelection_inserted": 0, "inactiveSelection_deleted": 0, "rapidLargeChange_inserted": 0, "rapidLargeChange_deleted": 0 } ``` --- agent/src/AgentWorkspaceDocuments.ts | 2 +- vscode/src/services/CharactersLogger.test.ts | 348 +++++++++++++++---- vscode/src/services/CharactersLogger.ts | 132 ++++++- 3 files changed, 410 insertions(+), 72 deletions(-) diff --git a/agent/src/AgentWorkspaceDocuments.ts b/agent/src/AgentWorkspaceDocuments.ts index e46fe09614d8..03a48b2ab4d4 100644 --- a/agent/src/AgentWorkspaceDocuments.ts +++ b/agent/src/AgentWorkspaceDocuments.ts @@ -80,7 +80,7 @@ export class AgentWorkspaceDocuments implements vscode_shim.WorkspaceDocuments { } // We have seen this document before, which means we mutate the existing - // document to reflect the latest chagnes. For each URI, we keep a + // document to reflect the latest changes. For each URI, we keep a // singleton document so that `AgentTextDocument.getText()` always // reflects the latest value. const contentChanges: vscode.TextDocumentContentChangeEvent[] = [] diff --git a/vscode/src/services/CharactersLogger.test.ts b/vscode/src/services/CharactersLogger.test.ts index 9aae823c34db..7ce7889aad61 100644 --- a/vscode/src/services/CharactersLogger.test.ts +++ b/vscode/src/services/CharactersLogger.test.ts @@ -1,141 +1,367 @@ +import type { Writable } from 'type-fest' import { type MockInstance, afterEach, beforeEach, describe, expect, it, vi } from 'vitest' import type * as vscode from 'vscode' import { telemetryRecorder } from '@sourcegraph/cody-shared' + import { document } from '../completions/test-helpers' import { range } from '../testutils/textDocument' -import { CharactersLogger, LOG_INTERVAL } from './CharactersLogger' + +import { + CharactersLogger, + DEFAULT_COUNTERS, + type DocumentChangeCounters, + LOG_INTERVAL, +} from './CharactersLogger' const testDocument = document('foo') + describe('CharactersLogger', () => { let recordSpy: MockInstance let tracker: CharactersLogger + let onDidChangeTextDocument: (event: vscode.TextDocumentChangeEvent) => void + let onDidChangeWindowState: (state: vscode.WindowState) => void + let onDidChangeVisibleTextEditors: (editors: vscode.TextEditor[]) => void + let onDidChangeTextEditorSelection: (event: vscode.TextEditorSelectionChangeEvent) => void + + let mockWindowState: Writable + let mockVisibleTextEditors: vscode.TextEditor[] + let mockTextEditorSelectionEvent: vscode.TextEditorSelectionChangeEvent + beforeEach(() => { vi.useFakeTimers() + vi.setSystemTime(0) // Start at timestamp 0 for consistency recordSpy = vi.spyOn(telemetryRecorder, 'recordEvent') - tracker = new CharactersLogger({ - onDidChangeTextDocument(listener) { - onDidChangeTextDocument = listener - return { dispose: () => {} } + // Mock functions and variables + mockWindowState = { focused: true } + mockVisibleTextEditors = [{ document: testDocument } as vscode.TextEditor] + + mockTextEditorSelectionEvent = { + textEditor: { document: testDocument } as vscode.TextEditor, + selections: [], + kind: undefined, + } + + tracker = new CharactersLogger( + { + onDidChangeTextDocument(listener) { + onDidChangeTextDocument = listener + return { dispose: () => {} } + }, }, - }) + { + onDidChangeWindowState(listener) { + onDidChangeWindowState = listener + return { dispose: () => {} } + }, + onDidChangeVisibleTextEditors(listener) { + onDidChangeVisibleTextEditors = listener + return { dispose: () => {} } + }, + onDidChangeTextEditorSelection(listener) { + onDidChangeTextEditorSelection = listener + return { dispose: () => {} } + }, + visibleTextEditors: mockVisibleTextEditors, + } + ) }) + afterEach(() => { tracker.dispose() vi.clearAllTimers() + vi.resetAllMocks() }) - function createChange( - text: string, - range: vscode.Range, + function createChange({ + text, + range, + rangeLength, + document = testDocument, + reason, + }: { + text: string + range: vscode.Range rangeLength: number - ): vscode.TextDocumentChangeEvent { + document?: vscode.TextDocument + reason?: vscode.TextDocumentChangeReason + }): vscode.TextDocumentChangeEvent { return { - document: testDocument, - reason: undefined, + document, + reason, contentChanges: [ { text, range, rangeLength, - rangeOffset: range.start.character, + rangeOffset: document.offsetAt(range.start), }, ], } } - it('returns 0 after LOG_INTERVAL', () => { - vi.advanceTimersByTime(LOG_INTERVAL - 1) - expect(recordSpy).not.toHaveBeenCalled() - vi.advanceTimersByTime(1) + // Helper function to create default metadata counters with expected values + function expectedCounters(expected: Partial): Record { + return { ...DEFAULT_COUNTERS, ...expected } + } + + it('logs inserted and deleted characters for user edits', () => { + onDidChangeTextEditorSelection(mockTextEditorSelectionEvent) + onDidChangeTextDocument(createChange({ text: 'foo', range: range(0, 0, 0, 0), rangeLength: 0 })) + onDidChangeTextEditorSelection(mockTextEditorSelectionEvent) + onDidChangeTextDocument(createChange({ text: 'bar', range: range(0, 3, 0, 3), rangeLength: 0 })) + + vi.advanceTimersByTime(LOG_INTERVAL) + expect(recordSpy).toHaveBeenCalledWith('cody.characters', 'flush', { - metadata: { - insertedCharacters: 0, - deletedCharacters: 0, - }, + metadata: expectedCounters({ + normal_inserted: 6, + normal_deleted: 0, + }), }) }) - it('returns number of inserted characters', () => { - onDidChangeTextDocument(createChange('foo', range(0, 0, 0, 0), 0)) - onDidChangeTextDocument(createChange('bar', range(0, 3, 0, 3), 0)) + it('logs changes under "windowNotFocused" when window is not focused', () => { + onDidChangeTextEditorSelection(mockTextEditorSelectionEvent) + onDidChangeTextDocument(createChange({ text: 'foo', range: range(0, 0, 0, 0), rangeLength: 0 })) + + // Simulate window losing focus + mockWindowState.focused = false + onDidChangeWindowState(mockWindowState) + + onDidChangeTextDocument(createChange({ text: 'bar', range: range(0, 3, 0, 3), rangeLength: 0 })) vi.advanceTimersByTime(LOG_INTERVAL) + // Changes while focused and not focused are logged under different types expect(recordSpy).toHaveBeenCalledWith('cody.characters', 'flush', { - metadata: { - insertedCharacters: 6, - deletedCharacters: 0, - }, + metadata: expectedCounters({ + normal_inserted: 3, + normal_deleted: 0, + windowNotFocused_inserted: 3, + windowNotFocused_deleted: 0, + }), }) }) - it('returns number of deleted characters', () => { - onDidChangeTextDocument(createChange('', range(0, 0, 0, 3), 3)) - onDidChangeTextDocument(createChange('', range(0, 0, 0, 3), 3)) + it('logs changes under "nonVisibleDocument" when in non-visible documents', () => { + // Remove testDocument from visible editors + mockVisibleTextEditors = [] + onDidChangeVisibleTextEditors(mockVisibleTextEditors) + + onDidChangeTextEditorSelection(mockTextEditorSelectionEvent) + onDidChangeTextDocument(createChange({ text: 'foo', range: range(0, 0, 0, 0), rangeLength: 0 })) vi.advanceTimersByTime(LOG_INTERVAL) + // Change is logged under 'nonVisibleDocument' expect(recordSpy).toHaveBeenCalledWith('cody.characters', 'flush', { - metadata: { - insertedCharacters: 0, - deletedCharacters: 6, - }, + metadata: expectedCounters({ + nonVisibleDocument_inserted: 3, + nonVisibleDocument_deleted: 0, + }), }) }) - it('calculates the number of actually changed characters', () => { - // replacing `foo` with `fob` should result in 3 deletions and 3 insertions - onDidChangeTextDocument(createChange('fob', range(0, 0, 0, 3), 3)) + it('logs changes under "inactiveSelection" when there has been no recent cursor movement', () => { + // Simulate last selection happened 6 seconds ago + onDidChangeTextEditorSelection(mockTextEditorSelectionEvent) + vi.advanceTimersByTime(6000) + + onDidChangeTextDocument(createChange({ text: 'foo', range: range(0, 0, 0, 0), rangeLength: 0 })) + + vi.advanceTimersByTime(LOG_INTERVAL - 6000) + + // Change is logged under 'inactiveSelection' + expect(recordSpy).toHaveBeenCalledWith('cody.characters', 'flush', { + metadata: expectedCounters({ + inactiveSelection_inserted: 3, + inactiveSelection_deleted: 0, + }), + }) + }) + + it('logs undo and redo changes under their respective types', () => { + onDidChangeTextEditorSelection(mockTextEditorSelectionEvent) + const textDocumentChangeReason = { + undo: 1, + redo: 2, + } + + // Simulate undo change + onDidChangeTextDocument( + createChange({ + text: '', + range: range(0, 3, 0, 0), + rangeLength: 3, + document: testDocument, + reason: textDocumentChangeReason.undo, + }) + ) + + // Simulate redo change + onDidChangeTextDocument( + createChange({ + text: 'foo', + range: range(0, 0, 0, 0), + rangeLength: 0, + document: testDocument, + reason: textDocumentChangeReason.redo, + }) + ) + vi.advanceTimersByTime(LOG_INTERVAL) + // Changes are logged under 'undo' and 'redo' expect(recordSpy).toHaveBeenCalledWith('cody.characters', 'flush', { - metadata: { - insertedCharacters: 3, - deletedCharacters: 3, - }, + metadata: expectedCounters({ + undo_inserted: 0, + undo_deleted: 3, + redo_inserted: 3, + redo_deleted: 0, + }), }) }) - it('handles multi-line changes', () => { - // Delete 2 lines and insert 1 line - onDidChangeTextDocument(createChange('new line', range(0, 0, 2, 0), 20)) + it('logs rapid, large changes under "rapidLargeChange"', () => { + onDidChangeTextEditorSelection(mockTextEditorSelectionEvent) + + // Simulate large change (e.g., 2000 characters inserted) + const largeText = 'a'.repeat(2000) + onDidChangeTextDocument( + createChange({ text: largeText, range: range(0, 0, 0, 0), rangeLength: 0 }) + ) + vi.advanceTimersByTime(LOG_INTERVAL) + // Change is logged under 'rapidLargeChange' expect(recordSpy).toHaveBeenCalledWith('cody.characters', 'flush', { - metadata: { - insertedCharacters: 8, - deletedCharacters: 20, - }, + metadata: expectedCounters({ + rapidLargeChange_inserted: 2000, + rapidLargeChange_deleted: 0, + }), + }) + }) + + it('counts large changes as "normal" if they are not rapid', () => { + onDidChangeTextEditorSelection(mockTextEditorSelectionEvent) + + // Simulate large change after some time has passed + vi.advanceTimersByTime(2000) // Advance time beyond LARGE_CHANGE_TIMEOUT + const largeText = 'a'.repeat(2000) + onDidChangeTextDocument( + createChange({ text: largeText, range: range(0, 0, 0, 0), rangeLength: 0 }) + ) + + vi.advanceTimersByTime(LOG_INTERVAL - 2000) + + // The large change is logged under 'normal' + expect(recordSpy).toHaveBeenCalledWith('cody.characters', 'flush', { + metadata: expectedCounters({ + normal_inserted: 2000, + normal_deleted: 0, + }), }) }) it('resets counter after flushing', () => { - onDidChangeTextDocument(createChange('foo', range(0, 0, 0, 0), 0)) - onDidChangeTextDocument(createChange('bar', range(0, 3, 0, 3), 0)) - onDidChangeTextDocument(createChange('', range(0, 0, 0, 3), 3)) + onDidChangeTextEditorSelection(mockTextEditorSelectionEvent) + onDidChangeTextDocument(createChange({ text: 'foo', range: range(0, 0, 0, 0), rangeLength: 0 })) vi.advanceTimersByTime(LOG_INTERVAL) + expect(recordSpy).toHaveBeenCalledTimes(1) expect(recordSpy).toHaveBeenCalledWith('cody.characters', 'flush', { - metadata: { - insertedCharacters: 6, - deletedCharacters: 3, - }, + metadata: expectedCounters({ + normal_inserted: 3, + normal_deleted: 0, + }), }) - onDidChangeTextDocument(createChange('baz', range(0, 3, 0, 3), 0)) + onDidChangeTextEditorSelection(mockTextEditorSelectionEvent) + onDidChangeTextDocument(createChange({ text: 'bar', range: range(0, 3, 0, 3), rangeLength: 0 })) vi.advanceTimersByTime(LOG_INTERVAL) + expect(recordSpy).toHaveBeenCalledTimes(2) expect(recordSpy).toHaveBeenCalledWith('cody.characters', 'flush', { - metadata: { - insertedCharacters: 3, - deletedCharacters: 0, - }, + metadata: expectedCounters({ + normal_inserted: 3, + normal_deleted: 0, + }), + }) + }) + + it('logs user typing under "normal" after cursor movement', () => { + // Simulate user moving the cursor + onDidChangeTextEditorSelection(mockTextEditorSelectionEvent) + + // Simulate user typing + onDidChangeTextDocument(createChange({ text: 'foo', range: range(0, 0, 0, 0), rangeLength: 0 })) + + vi.advanceTimersByTime(LOG_INTERVAL) + + // Changes are logged under 'normal' + expect(recordSpy).toHaveBeenCalledWith('cody.characters', 'flush', { + metadata: expectedCounters({ + normal_inserted: 3, + normal_deleted: 0, + }), + }) + }) + + it('handles multiple documents and selections', () => { + const anotherDocument = document('bar') + mockVisibleTextEditors.push({ + document: anotherDocument, + } as vscode.TextEditor) + onDidChangeVisibleTextEditors(mockVisibleTextEditors) + + // Simulate cursor movement in both documents + onDidChangeTextEditorSelection({ + textEditor: { + document: testDocument, + } as vscode.TextEditor, + selections: [], + kind: undefined, + }) + onDidChangeTextEditorSelection({ + textEditor: { + document: anotherDocument, + } as vscode.TextEditor, + selections: [], + kind: undefined, + }) + + // Simulate changes in both documents + onDidChangeTextDocument( + createChange({ + text: 'foo', + range: range(0, 0, 0, 0), + rangeLength: 0, + document: testDocument, + }) + ) + onDidChangeTextDocument( + createChange({ + text: 'baz', + range: range(0, 0, 0, 0), + rangeLength: 0, + document: anotherDocument, + }) + ) + + vi.advanceTimersByTime(LOG_INTERVAL) + + // Changes in both documents should be counted under 'normal' + expect(recordSpy).toHaveBeenCalledWith('cody.characters', 'flush', { + metadata: expectedCounters({ + normal_inserted: 6, + normal_deleted: 0, + }), }) }) }) diff --git a/vscode/src/services/CharactersLogger.ts b/vscode/src/services/CharactersLogger.ts index fef1573834d3..f561c9c3103d 100644 --- a/vscode/src/services/CharactersLogger.ts +++ b/vscode/src/services/CharactersLogger.ts @@ -4,54 +4,166 @@ import * as vscode from 'vscode' import { telemetryRecorder } from '@sourcegraph/cody-shared' export const LOG_INTERVAL = 30 * 60 * 1000 // 30 minutes +const LARGE_CHANGE_THRESHOLD = 1000 +const LARGE_CHANGE_TIMEOUT = 1000 // Ignore large changes happened within this time. +const SELECTION_TIMEOUT = 5000 // 5 seconds + +const DOCUMENT_CHANGE_TYPES = [ + 'normal', + 'undo', + 'redo', + 'windowNotFocused', + 'nonVisibleDocument', + 'inactiveSelection', + 'rapidLargeChange', +] as const + +type DocumentChangeType = (typeof DOCUMENT_CHANGE_TYPES)[number] + +// This flat structure is required by the 'metadata' field type in the telemetry event. +export type DocumentChangeCounters = { + [K in `${DocumentChangeType}_${'inserted' | 'deleted'}`]: number +} + +export const DEFAULT_COUNTERS: DocumentChangeCounters = DOCUMENT_CHANGE_TYPES.reduce( + (acc, changeType) => { + acc[`${changeType}_inserted`] = 0 + acc[`${changeType}_deleted`] = 0 + return acc + }, + {} as DocumentChangeCounters +) export class CharactersLogger implements vscode.Disposable { private disposables: vscode.Disposable[] = [] - private inserted = 0 - private deleted = 0 + private changeCounters: DocumentChangeCounters = { ...DEFAULT_COUNTERS } private nextTimeoutId: NodeJS.Timeout | null = null - constructor(workspace: Pick = vscode.workspace) { + private windowFocused = true + private visibleDocuments = new Set() + private lastChangeTimestamp = 0 + private lastSelectionTimestamps = new Map() + + constructor( + workspace: Pick = vscode.workspace, + window: Pick< + typeof vscode.window, + | 'onDidChangeWindowState' + | 'onDidChangeVisibleTextEditors' + | 'onDidChangeTextEditorSelection' + | 'visibleTextEditors' + > = vscode.window + ) { this.disposables.push(workspace.onDidChangeTextDocument(this.onDidChangeTextDocument.bind(this))) + this.disposables.push(window.onDidChangeWindowState(this.onDidChangeWindowState.bind(this))) + this.disposables.push( + window.onDidChangeVisibleTextEditors(this.onDidChangeVisibleTextEditors.bind(this)) + ) + this.disposables.push( + window.onDidChangeTextEditorSelection(this.onDidChangeTextEditorSelection.bind(this)) + ) + + this.updateVisibleDocuments(window.visibleTextEditors) this.nextTimeoutId = setTimeout(() => this.flush(), LOG_INTERVAL) } public flush(): void { this.nextTimeoutId = null - const insertedCharacters = this.inserted - const deletedCharacters = this.deleted - this.inserted = 0 - this.deleted = 0 telemetryRecorder.recordEvent('cody.characters', 'flush', { - metadata: { insertedCharacters, deletedCharacters }, + metadata: { ...this.changeCounters }, }) + this.changeCounters = { ...DEFAULT_COUNTERS } this.nextTimeoutId = setTimeout(() => this.flush(), LOG_INTERVAL) } + + private onDidChangeWindowState(state: vscode.WindowState): void { + this.windowFocused = state.focused + } + + private onDidChangeVisibleTextEditors(editors: Readonly): void { + this.updateVisibleDocuments(editors) + } + + private onDidChangeTextEditorSelection(event: vscode.TextEditorSelectionChangeEvent): void { + const documentUri = event.textEditor.document.uri.toString() + this.lastSelectionTimestamps.set(documentUri, Date.now()) + } + private onDidChangeTextDocument(event: vscode.TextDocumentChangeEvent): void { if (!isFileURI(event.document.uri)) { return } + + const changeType = this.getDocumentChangeType(event) + for (const change of event.contentChanges) { // We use change.rangeLength for deletions because: // 1. It represents the length of the text being replaced, including newline characters. // 2. It accurately accounts for multi-line deletions. // 3. For pure deletions (without insertions), this will be the number of characters removed. // 4. For replacements, this represents the "old" text that's being replaced. - this.deleted += change.rangeLength + this.changeCounters[`${changeType}_deleted`] += change.rangeLength // We use change.text.length for insertions because: // 1. It represents the length of the new text being inserted, including newline characters. // 2. It accurately accounts for multi-line insertions. // 3. For pure insertions (without deletions), this will be the number of characters added. // 4. For replacements, this represents the "new" text that's replacing the old. - this.inserted += change.text.length + this.changeCounters[`${changeType}_inserted`] += change.text.length // Note: In the case of replacements, both deleted and inserted will be incremented. // This accurately represents that some text was removed and some was added, even if // the lengths are the same. } + + this.lastChangeTimestamp = Date.now() + } + + private getDocumentChangeType(event: vscode.TextDocumentChangeEvent): DocumentChangeType { + const currentTimestamp = Date.now() + const documentUri = event.document.uri.toString() + + if (event.reason === vscode.TextDocumentChangeReason.Undo) { + return 'undo' + } + if (event.reason === vscode.TextDocumentChangeReason.Redo) { + return 'redo' + } + + if (!this.windowFocused) { + return 'windowNotFocused' + } + if (!this.visibleDocuments.has(documentUri)) { + return 'nonVisibleDocument' + } + + const lastSelectionTimestamp = this.lastSelectionTimestamps.get(documentUri) || 0 + const timeSinceLastSelection = currentTimestamp - lastSelectionTimestamp + + if (timeSinceLastSelection > SELECTION_TIMEOUT) { + return 'inactiveSelection' + } + + const timeSinceLastChange = currentTimestamp - this.lastChangeTimestamp + const totalChangeSize = event.contentChanges.reduce((sum, change) => { + return sum + Math.abs(change.rangeLength) + Math.abs(change.text.length) + }, 0) + + if (totalChangeSize > LARGE_CHANGE_THRESHOLD && timeSinceLastChange < LARGE_CHANGE_TIMEOUT) { + return 'rapidLargeChange' + } + + return 'normal' + } + + private updateVisibleDocuments(editors: Readonly): void { + this.visibleDocuments.clear() + for (const editor of editors) { + const uri = editor.document.uri.toString() + this.visibleDocuments.add(uri) + } } public dispose(): void {