report command exec duration, include info about async additional edits with the main telemetry event (microsoft#185851)

Author: jrieken

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

@@ -334,6 +334,10 @@ export class SuggestController implements IEditorContribution {
 
 		const isResolved = item.isResolved;
 
+		// telemetry data points: duration of command execution, info about async additional edits (-1=n/a, -2=none, 1=success, 0=failed)
+		let _commandExectionDuration = -1;
+		let _additionalEditsAppliedAsync = -1;
+
 		if (Array.isArray(item.completion.additionalTextEdits)) {
 
 			// cancel -> stops all listening and closes widget
@@ -399,21 +403,7 @@ export class SuggestController implements IEditorContribution {
 				return true;
 			}).then(applied => {
 				this._logService.trace('[suggest] async resolving of edits DONE (ms, applied?)', sw.elapsed(), applied);
-				type AsyncSuggestEdits = { extensionId: string; providerId: string; applied: boolean };
-				type AsyncSuggestEditsClassification = {
-					owner: 'jrieken';
-					comment: 'Information about async additional text edits';
-					extensionId: { classification: 'PublicNonPersonalData'; purpose: 'FeatureInsight'; comment: 'Extension contributing the completions item' };
-					providerId: { classification: 'PublicNonPersonalData'; purpose: 'FeatureInsight'; comment: 'Provider of the completions item' };
-					applied: { classification: 'SystemMetaData'; purpose: 'FeatureInsight'; isMeasurement: true; comment: 'If async additional text edits could be applied' };
-				};
-				if (typeof applied === 'boolean') {
-					this._telemetryService.publicLog2<AsyncSuggestEdits, AsyncSuggestEditsClassification>('suggest.asyncAdditionalEdits', {
-						extensionId: item.extensionId?.value ?? 'unknown',
-						providerId: item.provider._debugDisplayName ?? 'unknown',
-						applied
-					});
-				}
+				_additionalEditsAppliedAsync = applied === true ? 1 : applied === false ? 0 : -2;
 			}).finally(() => {
 				docListener.dispose();
 				typeListener.dispose();
@@ -448,12 +438,15 @@ export class SuggestController implements IEditorContribution {
 				this.model.trigger({ auto: true, retrigger: true });
 			} else {
 				// exec command, done
+				const sw = new StopWatch();
 				tasks.push(this._commandService.executeCommand(item.completion.command.id, ...(item.completion.command.arguments ? [...item.completion.command.arguments] : [])).catch(e => {
 					if (item.completion.extensionId) {
 						onUnexpectedExternalError(e);
 					} else {
 						onUnexpectedError(e);
 					}
+				}).finally(() => {
+					_commandExectionDuration = sw.elapsed();
 				}));
 			}
 		}
@@ -484,14 +477,14 @@ export class SuggestController implements IEditorContribution {
 
 		// clear only now - after all tasks are done
 		Promise.all(tasks).finally(() => {
-			this._reportSuggestionAcceptedTelemetry(item, model, isResolved);
+			this._reportSuggestionAcceptedTelemetry(item, model, isResolved, _commandExectionDuration, _additionalEditsAppliedAsync);
 
 			this.model.clear();
 			cts.dispose();
 		});
 	}
 
-	private _reportSuggestionAcceptedTelemetry(item: CompletionItem, model: ITextModel, itemResolved: boolean) {
+	private _reportSuggestionAcceptedTelemetry(item: CompletionItem, model: ITextModel, itemResolved: boolean, commandExectionDuration: number, additionalEditsAppliedAsync: number) {
 
 		if (Math.floor(Math.random() * 100) === 0) {
 			// throttle telemetry event because accepting completions happens a lot
@@ -502,6 +495,8 @@ export class SuggestController implements IEditorContribution {
 			extensionId: string; providerId: string;
 			fileExtension: string; languageId: string; basenameHash: string; kind: number;
 			resolveInfo: number; resolveDuration: number;
+			commandDuration: number;
+			additionalEditsAsync: number;
 		};
 		type AcceptedSuggestionClassification = {
 			owner: 'jrieken';
@@ -514,6 +509,8 @@ export class SuggestController implements IEditorContribution {
 			kind: { classification: 'SystemMetaData'; purpose: 'FeatureInsight'; isMeasurement: true; comment: 'The completion item kind' };
 			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' };
+			commandDuration: { classification: 'SystemMetaData'; purpose: 'FeatureInsight'; isMeasurement: true; comment: 'How long a completion item command took' };
+			additionalEditsAsync: { classification: 'SystemMetaData'; purpose: 'FeatureInsight'; isMeasurement: true; comment: 'Info about asynchronously applying additional edits' };
 		};
 
 		this._telemetryService.publicLog2<AcceptedSuggestion, AcceptedSuggestionClassification>('suggest.acceptedSuggestion', {
@@ -524,7 +521,9 @@ export class SuggestController implements IEditorContribution {
 			languageId: model.getLanguageId(),
 			fileExtension: extname(model.uri),
 			resolveInfo: !item.provider.resolveCompletionItem ? -1 : itemResolved ? 1 : 0,
-			resolveDuration: item.resolveDuration
+			resolveDuration: item.resolveDuration,
+			commandDuration: commandExectionDuration,
+			additionalEditsAsync: additionalEditsAppliedAsync
 		});
 	}