tweak resolve info so that we know if resolve was needed and if it already finished, also make telemetry gate more fair (microsoft#185327)

* tweak resolve info so that we know if resolve was needed and if it already finished, also make telemetry gate more fair

* also log the resolve duration

Author: jrieken

src/vs/editor/contrib/suggest/browser/suggest.ts

@@ -73,7 +73,7 @@ export class CompletionItem {
 	readonly extensionId?: ExtensionIdentifier;
 
 	// resolving
-	private _isResolved?: boolean;
+	private _resolveDuration?: number;
 	private _resolveCache?: Promise<void>;
 
 	constructor(
@@ -122,32 +122,37 @@ export class CompletionItem {
 		// create the suggestion resolver
 		if (typeof provider.resolveCompletionItem !== 'function') {
 			this._resolveCache = Promise.resolve();
-			this._isResolved = true;
+			this._resolveDuration = 0;
 		}
 	}
 
 	// ---- resolving
 
 	get isResolved(): boolean {
-		return !!this._isResolved;
+		return this._resolveDuration !== undefined;
+	}
+
+	get resolveDuration(): number {
+		return this._resolveDuration !== undefined ? this._resolveDuration : -1;
 	}
 
 	async resolve(token: CancellationToken) {
 		if (!this._resolveCache) {
 			const sub = token.onCancellationRequested(() => {
 				this._resolveCache = undefined;
-				this._isResolved = false;
+				this._resolveDuration = undefined;
 			});
+			const sw = new StopWatch(true);
 			this._resolveCache = Promise.resolve(this.provider.resolveCompletionItem!(this.completion, token)).then(value => {
 				Object.assign(this.completion, value);
-				this._isResolved = true;
+				this._resolveDuration = sw.elapsed();
 				sub.dispose();
 			}, err => {
 				if (isCancellationError(err)) {
 					// the IPC queue will reject the request with the
 					// cancellation error -> reset cached
 					this._resolveCache = undefined;
-					this._isResolved = false;
+					this._resolveDuration = undefined;
 				}
 			});
 		}

src/vs/editor/contrib/suggest/browser/suggestController.ts

@@ -482,20 +482,24 @@ export class SuggestController implements IEditorContribution {
 
 		// clear only now - after all tasks are done
 		Promise.all(tasks).finally(() => {
-			this._reportSuggestionAcceptedTelemetry(item, model, event, isResolved);
+			this._reportSuggestionAcceptedTelemetry(item, model, isResolved);
 
 			this.model.clear();
 			cts.dispose();
 		});
 	}
 
-	private _telemetryGate: number = 0;
-	private _reportSuggestionAcceptedTelemetry(item: CompletionItem, model: ITextModel, acceptedSuggestion: ISelectedSuggestion, itemResolved: boolean) {
-		if (this._telemetryGate++ % 100 !== 0) {
+	private _reportSuggestionAcceptedTelemetry(item: CompletionItem, model: ITextModel, itemResolved: boolean) {
+
+		if (Math.floor(Math.random() * 100) === 0) {
+			// throttle telemetry event because accepting completions happens a lot
 			return;
 		}
 
-		type AcceptedSuggestion = { providerId: string; fileExtension: string; languageId: string; basenameHash: string; kind: number; itemResolved: boolean };
+		type AcceptedSuggestion = {
+			providerId: string; fileExtension: string; languageId: string; basenameHash: string; kind: number;
+			resolveInfo: number; resolveDuration: number;
+		};
 		type AcceptedSuggestionClassification = {
 			owner: 'jrieken';
 			comment: 'Information accepting completion items';
@@ -504,18 +508,18 @@ export class SuggestController implements IEditorContribution {
 			fileExtension: { classification: 'SystemMetaData'; purpose: 'FeatureInsight'; comment: 'File extension of the file into which the completion was inserted' };
 			languageId: { classification: 'SystemMetaData'; purpose: 'FeatureInsight'; comment: 'Language type of the file into which the completion was inserted' };
 			kind: { classification: 'SystemMetaData'; purpose: 'FeatureInsight'; isMeasurement: true; comment: 'The completion item kind' };
-			itemResolved: { classification: 'SystemMetaData'; purpose: 'FeatureInsight'; isMeasurement: true; comment: 'If the item was inserted before resolving was done' };
+			resolveInfo: { classification: 'SystemMetaData'; purpose: 'FeatureInsight'; isMeasurement: true; comment: 'If the item was inserted before resolving was done' };
+			resolveDuration: { classification: 'SystemMetaData'; purpose: 'FeatureInsight'; isMeasurement: true; comment: 'How long resolving took to finish' };
 		};
-		// _debugDisplayName looks like `vscode.css-language-features(/-:)`, where the last bit is the trigger chars
-		// normalize it to just the extension ID and lowercase
-		const providerId = item.extensionId ? item.extensionId.value : (acceptedSuggestion.item.provider._debugDisplayName ?? 'unknown').split('(', 1)[0].toLowerCase();
+
 		this._telemetryService.publicLog2<AcceptedSuggestion, AcceptedSuggestionClassification>('suggest.acceptedSuggestion', {
-			providerId,
+			providerId: item.extensionId?.value ?? 'unknown',
 			kind: item.completion.kind,
 			basenameHash: hash(basename(model.uri)).toString(16),
 			languageId: model.getLanguageId(),
 			fileExtension: extname(model.uri),
-			itemResolved
+			resolveInfo: !item.provider.resolveCompletionItem ? -1 : itemResolved ? 1 : 0,
+			resolveDuration: item.resolveDuration
 		});
 	}