Skip to content

Commit

Permalink
Improves logging (#234587)
Browse files Browse the repository at this point in the history 
* Improves logging
  • Loading branch information
@hediet
hediet authored Nov 27, 2024
1 parent 709e28f commit f68cdda
Show file tree
Hide file tree
Showing 2 changed files with 64 additions and 24 deletions.
22 changes: 12 additions & 10 deletions src/vs/editor/contrib/inlineCompletions/browser/model/changeRecorder.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -5,24 +5,24 @@

import { Disposable } from '../../../../../base/common/lifecycle.js';
import { autorunWithStore } from '../../../../../base/common/observable.js';
import { IContextKeyService } from '../../../../../platform/contextkey/common/contextkey.js';
import { ILogService } from '../../../../../platform/log/common/log.js';
import { IInstantiationService } from '../../../../../platform/instantiation/common/instantiation.js';
import { ICodeEditor } from '../../../../browser/editorBrowser.js';
import { CodeEditorWidget } from '../../../../browser/widget/codeEditor/codeEditorWidget.js';
import { formatRecordableLogEntry, IRecordableEditorLogEntry, observableContextKey } from './inlineCompletionsSource.js';
import { IRecordableEditorLogEntry, StructuredLogger } from './inlineCompletionsSource.js';

export class TextModelChangeRecorder extends Disposable {
private readonly _recordingLoggingEnabled = observableContextKey('editor.inlineSuggest.logChangeReason', this._contextKeyService).recomputeInitiallyAndOnChange(this._store);
private readonly _structuredLogger = this._register(this._instantiationService.createInstance(StructuredLogger.cast<IRecordableEditorLogEntry & { source: string }>(),
'editor.inlineSuggest.logChangeReason.commandId'
));

constructor(
private readonly _editor: ICodeEditor,
@IContextKeyService private readonly _contextKeyService: IContextKeyService,
@ILogService private readonly _logService: ILogService
@IInstantiationService private readonly _instantiationService: IInstantiationService,
) {
super();
this._register(autorunWithStore((reader, store) => {
if (!(this._editor instanceof CodeEditorWidget)) { return; }
if (!this._recordingLoggingEnabled.read(reader)) { return; }
if (!this._structuredLogger.isEnabled.read(reader)) { return; }

const sources: string[] = [];

Expand All @@ -36,12 +36,14 @@ export class TextModelChangeRecorder extends Disposable {
const tm = this._editor.getModel();
if (!tm) { return; }
for (const source of sources) {
this._logService.info(formatRecordableLogEntry<IRecordableEditorLogEntry & { source: string }>('TextModel.setChangeReason', {
const data: IRecordableEditorLogEntry & { source: string } = {
sourceId: 'TextModel.setChangeReason',
source: source,
time: Date.now(),
modelUri: tm.uri.toString(),
modelVersion: tm.getVersionId(),
source: source,
}));
};
this._structuredLogger.log(data);
}
sources.length = 0;
}));
Expand Down
66 changes: 52 additions & 14 deletions src/vs/editor/contrib/inlineCompletions/browser/model/inlineCompletionsSource.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -8,8 +8,10 @@ import { equalsIfDefined, itemEquals } from '../../../../../base/common/equals.j
import { matchesSubString } from '../../../../../base/common/filters.js';
import { Disposable, IDisposable, MutableDisposable } from '../../../../../base/common/lifecycle.js';
import { IObservable, IReader, ITransaction, derivedOpts, disposableObservableValue, observableFromEvent, observableValue, transaction } from '../../../../../base/common/observable.js';
import { ICommandService } from '../../../../../platform/commands/common/commands.js';
import { IConfigurationService } from '../../../../../platform/configuration/common/configuration.js';
import { IContextKeyService } from '../../../../../platform/contextkey/common/contextkey.js';
import { IInstantiationService } from '../../../../../platform/instantiation/common/instantiation.js';
import { ILogService } from '../../../../../platform/log/common/log.js';
import { observableConfigValue } from '../../../../../platform/observable/common/platformObservableUtils.js';
import { Position } from '../../../../common/core/position.js';
Expand All @@ -32,7 +34,12 @@ export class InlineCompletionsSource extends Disposable {
public readonly suggestWidgetInlineCompletions = disposableObservableValue<UpToDateInlineCompletions | undefined>('suggestWidgetInlineCompletions', undefined);

private readonly _loggingEnabled = observableConfigValue('editor.inlineSuggest.logFetch', false, this._configurationService).recomputeInitiallyAndOnChange(this._store);
private readonly _recordingLoggingEnabled = observableContextKey('editor.inlineSuggest.logFetch', this._contextKeyService).recomputeInitiallyAndOnChange(this._store);
private readonly _structuredFetchLogger = this._register(this._instantiationService.createInstance(StructuredLogger.cast<
{ kind: 'start'; requestId: number; context: unknown } & IRecordableEditorLogEntry
| { kind: 'end'; error: any; durationMs: number; result: unknown; requestId: number } & IRecordableLogEntry
>(),
'editor.inlineSuggest.logFetch.commandId'
));

constructor(
private readonly _textModel: ITextModel,
Expand All @@ -42,7 +49,7 @@ export class InlineCompletionsSource extends Disposable {
@ILanguageConfigurationService private readonly _languageConfigurationService: ILanguageConfigurationService,
@ILogService private readonly _logService: ILogService,
@IConfigurationService private readonly _configurationService: IConfigurationService,
@IContextKeyService private readonly _contextKeyService: IContextKeyService,
@IInstantiationService private readonly _instantiationService: IInstantiationService,
) {
super();

Expand All @@ -52,10 +59,13 @@ export class InlineCompletionsSource extends Disposable {
}

private _log(entry:
{ kind: 'start'; requestId: number; context: unknown } & IRecordableEditorLogEntry
| { kind: 'end'; error: any; durationMs: number; result: unknown; requestId: number } & IRecordableLogEntry
{ sourceId: string; kind: 'start'; requestId: number; context: unknown } & IRecordableEditorLogEntry
| { sourceId: string; kind: 'end'; error: any; durationMs: number; result: unknown; requestId: number } & IRecordableLogEntry
) {
this._logService.info(formatRecordableLogEntry('InlineCompletions.fetch', entry));
if (this._loggingEnabled.get()) {
this._logService.info(formatRecordableLogEntry(entry));
}
this._structuredFetchLogger.log(entry);
}

public readonly loading = observableValue(this, false);
Expand Down Expand Up @@ -90,8 +100,8 @@ export class InlineCompletionsSource extends Disposable {
}

const requestId = InlineCompletionsSource._requestId++;
if (this._loggingEnabled.get() || this._recordingLoggingEnabled.get()) {
this._log({ kind: 'start', requestId, modelUri: this._textModel.uri.toString(), modelVersion: this._textModel.getVersionId(), context: { triggerKind: context.triggerKind }, time: Date.now() });
if (this._loggingEnabled.get() || this._structuredFetchLogger.isEnabled.get()) {
this._log({ sourceId: 'InlineCompletions.fetch', kind: 'start', requestId, modelUri: this._textModel.uri.toString(), modelVersion: this._textModel.getVersionId(), context: { triggerKind: context.triggerKind }, time: Date.now() });
}

const startTime = new Date();
Expand All @@ -110,8 +120,8 @@ export class InlineCompletionsSource extends Disposable {
error = e;
throw e;
} finally {
if (this._loggingEnabled.get() || this._recordingLoggingEnabled.get()) {
if (source.token.isCancellationRequested) {
if (this._loggingEnabled.get() || this._structuredFetchLogger.isEnabled.get()) {
if (source.token.isCancellationRequested || this._store.isDisposed || this._textModel.getVersionId() !== request.versionId) {
error = 'canceled';
}
const result = updatedCompletions?.completions.map(c => ({
Expand All @@ -120,7 +130,7 @@ export class InlineCompletionsSource extends Disposable {
isInlineEdit: !!c.sourceInlineCompletion.isInlineEdit,
source: c.source.provider.groupId,
}));
this._log({ kind: 'end', requestId, durationMs: (Date.now() - startTime.getTime()), error, result, time: Date.now() });
this._log({ sourceId: 'InlineCompletions.fetch', kind: 'end', requestId, durationMs: (Date.now() - startTime.getTime()), error, result, time: Date.now() });
}
}

Expand Down Expand Up @@ -375,6 +385,7 @@ export class InlineCompletionWithUpdatedRange {
const emptyRange = new Range(1, 1, 1, 1);

interface IRecordableLogEntry {
sourceId: string;
time: number;
}

Expand All @@ -386,10 +397,37 @@ export interface IRecordableEditorLogEntry extends IRecordableLogEntry {
/**
* The sourceLabel must not contain '@'!
*/
export function formatRecordableLogEntry<T extends IRecordableLogEntry>(sourceId: string, entry: T): string {
return sourceId + ' @@ ' + JSON.stringify(entry);
export function formatRecordableLogEntry<T extends IRecordableLogEntry>(entry: T): string {
return entry.sourceId + ' @@ ' + JSON.stringify({ ...entry, sourceId: undefined });
}

export class StructuredLogger<T extends IRecordableLogEntry> extends Disposable {
public static cast<T extends IRecordableLogEntry>(): typeof StructuredLogger<T> {
return this as typeof StructuredLogger<T>;
}

private readonly _contextKeyValue = observableContextKey<string>(this._contextKey, this._contextKeyService).recomputeInitiallyAndOnChange(this._store);

constructor(
private readonly _contextKey: string,
@IContextKeyService private readonly _contextKeyService: IContextKeyService,
@ICommandService private readonly _commandService: ICommandService,
) {
super();
}

public readonly isEnabled = this._contextKeyValue.map(v => v !== undefined);

public log(data: T): boolean {
const commandId = this._contextKeyValue.get();
if (!commandId) {
return false;
}
this._commandService.executeCommand(commandId, data);
return true;
}
}

export function observableContextKey(key: string, contextKeyService: IContextKeyService): IObservable<unknown> {
return observableFromEvent(contextKeyService.onDidChangeContext, () => contextKeyService.getContextKeyValue(key));
export function observableContextKey<T>(key: string, contextKeyService: IContextKeyService): IObservable<T | undefined> {
return observableFromEvent(contextKeyService.onDidChangeContext, () => contextKeyService.getContextKeyValue<T>(key));
}

0 comments on commit f68cdda

Please sign in to comment.