From 824a1b86579b4d1cc55eeab4f91cce1d8ee36211 Mon Sep 17 00:00:00 2001 From: Alex Dima Date: Thu, 7 Dec 2017 15:26:50 +0100 Subject: [PATCH] #37677: Add tracing in the extension host around activating extensions --- .../api/node/extHostExtensionService.ts | 19 +++++++++++++------ src/vs/workbench/node/extensionHostMain.ts | 17 +++++++++++------ 2 files changed, 24 insertions(+), 12 deletions(-) diff --git a/src/vs/workbench/api/node/extHostExtensionService.ts b/src/vs/workbench/api/node/extHostExtensionService.ts index fbda73fac6c..6d15e7a8675 100644 --- a/src/vs/workbench/api/node/extHostExtensionService.ts +++ b/src/vs/workbench/api/node/extHostExtensionService.ts @@ -118,6 +118,7 @@ export class ExtHostExtensionService implements ExtHostExtensionServiceShape { private readonly _storage: ExtHostStorage; private readonly _storagePath: ExtensionStoragePath; private readonly _proxy: MainThreadExtensionServiceShape; + private readonly _logService: ILogService; private _activator: ExtensionsActivator; private _extensionPathIndex: TPromise>; /** @@ -132,6 +133,7 @@ export class ExtHostExtensionService implements ExtHostExtensionServiceShape { this._barrier = new Barrier(); this._registry = new ExtensionDescriptionRegistry(initData.extensions); this._threadService = threadService; + this._logService = logService; this._mainThreadTelemetry = threadService.get(MainContext.MainThreadTelemetry); this._storage = new ExtHostStorage(threadService); this._storagePath = new ExtensionStoragePath(initData.workspace, initData.environment); @@ -308,12 +310,14 @@ export class ExtHostExtensionService implements ExtHostExtensionServiceShape { return TPromise.as(new EmptyExtension(ExtensionActivationTimes.NONE)); } + this._logService.info(`ExtensionService#_doActivateExtension ${extensionDescription.id} ${JSON.stringify(reason)}`); + const activationTimesBuilder = new ExtensionActivationTimesBuilder(reason.startup); return TPromise.join([ - loadCommonJSModule(extensionDescription.main, activationTimesBuilder), + loadCommonJSModule(this._logService, extensionDescription.main, activationTimesBuilder), this._loadExtensionContext(extensionDescription) ]).then(values => { - return ExtHostExtensionService._callActivate(values[0], values[1], activationTimesBuilder); + return ExtHostExtensionService._callActivate(this._logService, extensionDescription.id, values[0], values[1], activationTimesBuilder); }, (errors: any[]) => { // Avoid failing with an array of errors, fail with a single error if (errors[0]) { @@ -331,6 +335,7 @@ export class ExtHostExtensionService implements ExtHostExtensionServiceShape { let globalState = new ExtensionMemento(extensionDescription.id, true, this._storage); let workspaceState = new ExtensionMemento(extensionDescription.id, false, this._storage); + this._logService.trace(`ExtensionService#loadExtensionContext ${extensionDescription.id}`); return TPromise.join([ globalState.whenReady, workspaceState.whenReady, @@ -347,22 +352,23 @@ export class ExtHostExtensionService implements ExtHostExtensionServiceShape { }); } - private static _callActivate(extensionModule: IExtensionModule, context: IExtensionContext, activationTimesBuilder: ExtensionActivationTimesBuilder): Thenable { + private static _callActivate(logService: ILogService, extensionId: string, extensionModule: IExtensionModule, context: IExtensionContext, activationTimesBuilder: ExtensionActivationTimesBuilder): Thenable { // Make sure the extension's surface is not undefined extensionModule = extensionModule || { activate: undefined, deactivate: undefined }; - return this._callActivateOptional(extensionModule, context, activationTimesBuilder).then((extensionExports) => { + return this._callActivateOptional(logService, extensionId, extensionModule, context, activationTimesBuilder).then((extensionExports) => { return new ActivatedExtension(false, activationTimesBuilder.build(), extensionModule, extensionExports, context.subscriptions); }); } - private static _callActivateOptional(extensionModule: IExtensionModule, context: IExtensionContext, activationTimesBuilder: ExtensionActivationTimesBuilder): Thenable { + private static _callActivateOptional(logService: ILogService, extensionId: string, extensionModule: IExtensionModule, context: IExtensionContext, activationTimesBuilder: ExtensionActivationTimesBuilder): Thenable { if (typeof extensionModule.activate === 'function') { try { activationTimesBuilder.activateCallStart(); + logService.trace(`ExtensionService#_callActivateOptional ${extensionId}`); const activateResult: TPromise = extensionModule.activate.apply(global, [context]); activationTimesBuilder.activateCallStop(); @@ -387,9 +393,10 @@ export class ExtHostExtensionService implements ExtHostExtensionServiceShape { } } -function loadCommonJSModule(modulePath: string, activationTimesBuilder: ExtensionActivationTimesBuilder): TPromise { +function loadCommonJSModule(logService: ILogService, modulePath: string, activationTimesBuilder: ExtensionActivationTimesBuilder): TPromise { let r: T = null; activationTimesBuilder.codeLoadingStart(); + logService.info(`ExtensionService#loadCommonJSModule ${modulePath}`); try { r = require.__$__nodeRequire(modulePath); } catch (e) { diff --git a/src/vs/workbench/node/extensionHostMain.ts b/src/vs/workbench/node/extensionHostMain.ts index f3b21a60a98..952ef7e4f96 100644 --- a/src/vs/workbench/node/extensionHostMain.ts +++ b/src/vs/workbench/node/extensionHostMain.ts @@ -25,6 +25,7 @@ import { ExtensionActivatedByEvent } from 'vs/workbench/api/node/extHostExtensio import { EnvironmentService } from 'vs/platform/environment/node/environmentService'; import { createLogService } from 'vs/platform/log/node/spdlogService'; import { IDisposable, dispose } from 'vs/base/common/lifecycle'; +import { ILogService } from 'vs/platform/log/common/log'; // const nativeExit = process.exit.bind(process); function patchProcess(allowExit: boolean) { @@ -76,6 +77,7 @@ export class ExtensionHostMain { private _environment: IEnvironment; private _extensionService: ExtHostExtensionService; private _extHostConfiguration: ExtHostConfiguration; + private _logService: ILogService; private disposables: IDisposable[] = []; constructor(rpcProtocol: RPCProtocol, initData: IInitData) { @@ -89,14 +91,14 @@ export class ExtensionHostMain { const threadService = new ExtHostThreadService(rpcProtocol); const extHostWorkspace = new ExtHostWorkspace(threadService, initData.workspace); const environmentService = new EnvironmentService(initData.args, initData.execPath); - const logService = createLogService(`exthost${initData.windowId}`, environmentService); - this.disposables.push(logService); + this._logService = createLogService(`exthost${initData.windowId}`, environmentService); + this.disposables.push(this._logService); - logService.info('extension host started'); - logService.trace('initData', initData); + this._logService.info('extension host started'); + this._logService.trace('initData', initData); this._extHostConfiguration = new ExtHostConfiguration(threadService.get(MainContext.MainThreadConfiguration), extHostWorkspace, initData.configuration); - this._extensionService = new ExtHostExtensionService(initData, threadService, extHostWorkspace, this._extHostConfiguration, logService); + this._extensionService = new ExtHostExtensionService(initData, threadService, extHostWorkspace, this._extHostConfiguration, this._logService); // error forwarding and stack trace scanning const extensionErrors = new WeakMap(); @@ -138,7 +140,10 @@ export class ExtensionHostMain { public start(): TPromise { return this._extensionService.onExtensionAPIReady() .then(() => this.handleEagerExtensions()) - .then(() => this.handleExtensionTests()); + .then(() => this.handleExtensionTests()) + .then(() => { + this._logService.info(`eager extensions activated`); + }); } public terminate(): void { -- GitLab