perf - log slow running workbench contribs (microsoft#159656)

Author: bpasero

src/vs/workbench/api/browser/extensionHost.contribution.ts

@@ -89,4 +89,4 @@ export class ExtensionPoints implements IWorkbenchContribution {
 	}
 }
 
-Registry.as<IWorkbenchContributionsRegistry>(WorkbenchExtensions.Workbench).registerWorkbenchContribution(ExtensionPoints, LifecyclePhase.Starting);
+Registry.as<IWorkbenchContributionsRegistry>(WorkbenchExtensions.Workbench).registerWorkbenchContribution(ExtensionPoints, 'ExtensionPoints', LifecyclePhase.Starting);

src/vs/workbench/api/browser/viewsExtensionPoint.ts

@@ -643,4 +643,4 @@ class ViewsExtensionHandler implements IWorkbenchContribution {
 }
 
 const workbenchRegistry = Registry.as<IWorkbenchContributionsRegistry>(WorkbenchExtensions.Workbench);
-workbenchRegistry.registerWorkbenchContribution(ViewsExtensionHandler, LifecyclePhase.Starting);
+workbenchRegistry.registerWorkbenchContribution(ViewsExtensionHandler, 'ViewsExtensionHandler', LifecyclePhase.Starting);

src/vs/workbench/browser/actions/textInputActions.ts

@@ -99,4 +99,4 @@ export class TextInputActionsProvider extends Disposable implements IWorkbenchCo
 	}
 }
 
-Registry.as<IWorkbenchContributionsRegistry>(WorkbenchExtensions.Workbench).registerWorkbenchContribution(TextInputActionsProvider, LifecyclePhase.Ready);
+Registry.as<IWorkbenchContributionsRegistry>(WorkbenchExtensions.Workbench).registerWorkbenchContribution(TextInputActionsProvider, 'TextInputActionsProvider', LifecyclePhase.Ready);

src/vs/workbench/browser/parts/dialogs/dialog.web.contribution.ts

@@ -75,4 +75,4 @@ export class DialogHandlerContribution extends Disposable implements IWorkbenchC
 }
 
 const workbenchRegistry = Registry.as<IWorkbenchContributionsRegistry>(WorkbenchExtensions.Workbench);
-workbenchRegistry.registerWorkbenchContribution(DialogHandlerContribution, LifecyclePhase.Starting);
+workbenchRegistry.registerWorkbenchContribution(DialogHandlerContribution, 'DialogHandlerContribution', LifecyclePhase.Starting);

src/vs/workbench/browser/parts/editor/editor.contribution.ts

@@ -122,10 +122,10 @@ Registry.as<IEditorFactoryRegistry>(EditorExtensions.EditorFactory).registerEdit
 
 //#region Workbench Contributions
 
-Registry.as<IWorkbenchContributionsRegistry>(WorkbenchExtensions.Workbench).registerWorkbenchContribution(EditorAutoSave, LifecyclePhase.Ready);
-Registry.as<IWorkbenchContributionsRegistry>(WorkbenchExtensions.Workbench).registerWorkbenchContribution(EditorStatus, LifecyclePhase.Ready);
-Registry.as<IWorkbenchContributionsRegistry>(WorkbenchExtensions.Workbench).registerWorkbenchContribution(UntitledTextEditorWorkingCopyEditorHandler, LifecyclePhase.Ready);
-Registry.as<IWorkbenchContributionsRegistry>(WorkbenchExtensions.Workbench).registerWorkbenchContribution(DynamicEditorConfigurations, LifecyclePhase.Ready);
+Registry.as<IWorkbenchContributionsRegistry>(WorkbenchExtensions.Workbench).registerWorkbenchContribution(EditorAutoSave, 'EditorAutoSave', LifecyclePhase.Ready);
+Registry.as<IWorkbenchContributionsRegistry>(WorkbenchExtensions.Workbench).registerWorkbenchContribution(EditorStatus, 'EditorStatus', LifecyclePhase.Ready);
+Registry.as<IWorkbenchContributionsRegistry>(WorkbenchExtensions.Workbench).registerWorkbenchContribution(UntitledTextEditorWorkingCopyEditorHandler, 'UntitledTextEditorWorkingCopyEditorHandler', LifecyclePhase.Ready);
+Registry.as<IWorkbenchContributionsRegistry>(WorkbenchExtensions.Workbench).registerWorkbenchContribution(DynamicEditorConfigurations, 'DynamicEditorConfigurations', LifecyclePhase.Ready);
 
 registerEditorContribution(FloatingClickMenu.ID, FloatingClickMenu);
 registerEditorContribution(OpenWorkspaceButtonContribution.ID, OpenWorkspaceButtonContribution);

src/vs/workbench/browser/workbench.contribution.ts

@@ -18,7 +18,7 @@ const registry = Registry.as<IConfigurationRegistry>(ConfigurationExtensions.Con
 (function registerConfiguration(): void {
 
 	// Migration support
-	Registry.as<IWorkbenchContributionsRegistry>(WorkbenchExtensions.Workbench).registerWorkbenchContribution(ConfigurationMigrationWorkbenchContribution, LifecyclePhase.Eventually);
+	Registry.as<IWorkbenchContributionsRegistry>(WorkbenchExtensions.Workbench).registerWorkbenchContribution(ConfigurationMigrationWorkbenchContribution, 'ConfigurationMigrationWorkbenchContribution', LifecyclePhase.Eventually);
 
 	// Workbench
 	registry.registerConfiguration({

src/vs/workbench/common/contributions.ts

@@ -8,6 +8,7 @@ import { ILifecycleService, LifecyclePhase } from 'vs/workbench/services/lifecyc
 import { Registry } from 'vs/platform/registry/common/platform';
 import { runWhenIdle, IdleDeadline } from 'vs/base/common/async';
 import { mark } from 'vs/base/common/performance';
+import { ILogService } from 'vs/platform/log/common/log';
 
 /**
  * A workbench contribution that will be loaded when the workbench starts and disposed when the workbench shuts down.
@@ -22,15 +23,21 @@ export namespace Extensions {
 
 type IWorkbenchContributionSignature<Service extends BrandedService[]> = new (...services: Service) => IWorkbenchContribution;
 
+interface IWorkbenchContributionRegistration {
+	readonly id: string;
+	readonly ctor: IConstructorSignature<IWorkbenchContribution>;
+}
+
 export interface IWorkbenchContributionsRegistry {
 
 	/**
 	 * Registers a workbench contribution to the platform that will be loaded when the workbench starts and disposed when
 	 * the workbench shuts down.
 	 *
+	 * @param id the identifier of the contribution.
 	 * @param phase the lifecycle phase when to instantiate the contribution.
 	 */
-	registerWorkbenchContribution<Services extends BrandedService[]>(contribution: IWorkbenchContributionSignature<Services>, phase: LifecyclePhase): void;
+	registerWorkbenchContribution<Services extends BrandedService[]>(contribution: IWorkbenchContributionSignature<Services>, id: string, phase: LifecyclePhase): void;
 
 	/**
 	 * Starts the registry by providing the required services.
@@ -42,14 +49,16 @@ class WorkbenchContributionsRegistry implements IWorkbenchContributionsRegistry
 
 	private instantiationService: IInstantiationService | undefined;
 	private lifecycleService: ILifecycleService | undefined;
+	private logService: ILogService | undefined;
 
-	private readonly toBeInstantiated = new Map<LifecyclePhase, IConstructorSignature<IWorkbenchContribution>[]>();
+	private readonly toBeInstantiated = new Map<LifecyclePhase, IWorkbenchContributionRegistration[]>();
 
-	registerWorkbenchContribution(ctor: IConstructorSignature<IWorkbenchContribution>, phase: LifecyclePhase = LifecyclePhase.Starting): void {
+	registerWorkbenchContribution(ctor: IConstructorSignature<IWorkbenchContribution>, id: string, phase: LifecyclePhase = LifecyclePhase.Starting): void {
+		const contribution = { id, ctor };
 
 		// Instantiate directly if we are already matching the provided phase
-		if (this.instantiationService && this.lifecycleService && this.lifecycleService.phase >= phase) {
-			this.instantiationService.createInstance(ctor);
+		if (this.instantiationService && this.lifecycleService && this.logService && this.lifecycleService.phase >= phase) {
+			this.safeCreateInstance(this.instantiationService, this.logService, contribution, phase);
 		}
 
 		// Otherwise keep contributions by lifecycle phase
@@ -60,33 +69,34 @@ class WorkbenchContributionsRegistry implements IWorkbenchContributionsRegistry
 				this.toBeInstantiated.set(phase, toBeInstantiated);
 			}
 
-			toBeInstantiated.push(ctor as IConstructorSignature<IWorkbenchContribution>);
+			toBeInstantiated.push(contribution);
 		}
 	}
 
 	start(accessor: ServicesAccessor): void {
 		const instantiationService = this.instantiationService = accessor.get(IInstantiationService);
 		const lifecycleService = this.lifecycleService = accessor.get(ILifecycleService);
+		const logService = this.logService = accessor.get(ILogService);
 
-		[LifecyclePhase.Starting, LifecyclePhase.Ready, LifecyclePhase.Restored, LifecyclePhase.Eventually].forEach(phase => {
-			this.instantiateByPhase(instantiationService, lifecycleService, phase);
-		});
+		for (const phase of [LifecyclePhase.Starting, LifecyclePhase.Ready, LifecyclePhase.Restored, LifecyclePhase.Eventually]) {
+			this.instantiateByPhase(instantiationService, lifecycleService, logService, phase);
+		}
 	}
 
-	private instantiateByPhase(instantiationService: IInstantiationService, lifecycleService: ILifecycleService, phase: LifecyclePhase): void {
+	private instantiateByPhase(instantiationService: IInstantiationService, lifecycleService: ILifecycleService, logService: ILogService, phase: LifecyclePhase): void {
 
 		// Instantiate contributions directly when phase is already reached
 		if (lifecycleService.phase >= phase) {
-			this.doInstantiateByPhase(instantiationService, phase);
+			this.doInstantiateByPhase(instantiationService, logService, phase);
 		}
 
 		// Otherwise wait for phase to be reached
 		else {
-			lifecycleService.when(phase).then(() => this.doInstantiateByPhase(instantiationService, phase));
+			lifecycleService.when(phase).then(() => this.doInstantiateByPhase(instantiationService, logService, phase));
 		}
 	}
 
-	private doInstantiateByPhase(instantiationService: IInstantiationService, phase: LifecyclePhase): void {
+	private doInstantiateByPhase(instantiationService: IInstantiationService, logService: ILogService, phase: LifecyclePhase): void {
 		const toBeInstantiated = this.toBeInstantiated.get(phase);
 		if (toBeInstantiated) {
 			this.toBeInstantiated.delete(phase);
@@ -98,7 +108,7 @@ class WorkbenchContributionsRegistry implements IWorkbenchContributionsRegistry
 				mark(`code/willCreateWorkbenchContributions/${phase}`);
 
 				for (const ctor of toBeInstantiated) {
-					this.safeCreateInstance(instantiationService, ctor); // catch error so that other contributions are still considered
+					this.safeCreateInstance(instantiationService, logService, ctor, phase); // catch error so that other contributions are still considered
 				}
 
 				mark(`code/didCreateWorkbenchContributions/${phase}`);
@@ -113,7 +123,7 @@ class WorkbenchContributionsRegistry implements IWorkbenchContributionsRegistry
 				const instantiateSome = (idle: IdleDeadline) => {
 					while (i < toBeInstantiated.length) {
 						const ctor = toBeInstantiated[i++];
-						this.safeCreateInstance(instantiationService, ctor); // catch error so that other contributions are still considered
+						this.safeCreateInstance(instantiationService, logService, ctor, phase); // catch error so that other contributions are still considered
 						if (idle.timeRemaining() < 1) {
 							// time is up -> reschedule
 							runWhenIdle(instantiateSome, forcedTimeout);
@@ -126,11 +136,20 @@ class WorkbenchContributionsRegistry implements IWorkbenchContributionsRegistry
 		}
 	}
 
-	private safeCreateInstance(instantiationService: IInstantiationService, ctor: IConstructorSignature<IWorkbenchContribution>): void {
+	private safeCreateInstance(instantiationService: IInstantiationService, logService: ILogService, contribution: IWorkbenchContributionRegistration, phase: LifecyclePhase): void {
+		const now: number | undefined = phase < LifecyclePhase.Restored ? Date.now() : undefined;
+
 		try {
-			instantiationService.createInstance(ctor);
+			instantiationService.createInstance(contribution.ctor);
 		} catch (error) {
-			console.error(`Unable to instantiate workbench contribution ${ctor.name}.`, error);
+			logService.error(`Unable to instantiate workbench contribution ${contribution.id}.`, error);
+		}
+
+		if (typeof now === 'number') {
+			const time = Date.now() - now;
+			if (time > 5) {
+				logService.warn(`Workbench contribution ${contribution.id} blocked restore phase by ${time}ms.`);
+			}
 		}
 	}
 }

src/vs/workbench/contrib/audioCues/browser/audioCues.contribution.ts

@@ -17,8 +17,8 @@ import { LifecyclePhase } from 'vs/workbench/services/lifecycle/common/lifecycle
 
 registerSingleton(IAudioCueService, AudioCueService, false);
 
-Registry.as<IWorkbenchContributionsRegistry>(WorkbenchExtensions.Workbench).registerWorkbenchContribution(AudioCueLineFeatureContribution, LifecyclePhase.Restored);
-Registry.as<IWorkbenchContributionsRegistry>(WorkbenchExtensions.Workbench).registerWorkbenchContribution(AudioCueLineDebuggerContribution, LifecyclePhase.Restored);
+Registry.as<IWorkbenchContributionsRegistry>(WorkbenchExtensions.Workbench).registerWorkbenchContribution(AudioCueLineFeatureContribution, 'AudioCueLineFeatureContribution', LifecyclePhase.Restored);
+Registry.as<IWorkbenchContributionsRegistry>(WorkbenchExtensions.Workbench).registerWorkbenchContribution(AudioCueLineDebuggerContribution, 'AudioCueLineDebuggerContribution', LifecyclePhase.Restored);
 
 const audioCueFeatureBase: IConfigurationPropertySchema = {
 	'type': 'string',

src/vs/workbench/contrib/bracketPairColorizer2Telemetry/browser/bracketPairColorizer2Telemetry.contribution.ts

@@ -51,5 +51,5 @@ class BracketPairColorizer2TelemetryContribution {
 	}
 }
 
-Registry.as<IWorkbenchContributionsRegistry>(WorkbenchExtensions.Workbench).registerWorkbenchContribution(BracketPairColorizer2TelemetryContribution, LifecyclePhase.Restored);
+Registry.as<IWorkbenchContributionsRegistry>(WorkbenchExtensions.Workbench).registerWorkbenchContribution(BracketPairColorizer2TelemetryContribution, 'BracketPairColorizer2TelemetryContribution', LifecyclePhase.Restored);
 

src/vs/workbench/contrib/bulkEdit/browser/preview/bulkEdit.contribution.ts

@@ -323,7 +323,9 @@ registerAction2(class ToggleGrouping extends Action2 {
 });
 
 Registry.as<IWorkbenchContributionsRegistry>(WorkbenchExtensions.Workbench).registerWorkbenchContribution(
-	BulkEditPreviewContribution, LifecyclePhase.Ready
+	BulkEditPreviewContribution,
+	'BulkEditPreviewContribution',
+	LifecyclePhase.Ready
 );
 
 const refactorPreviewViewIcon = registerIcon('refactor-preview-view-icon', Codicon.lightbulb, localize('refactorPreviewViewIcon', 'View icon of the refactor preview view.'));