Skip to content

Commit 227c103

Browse files
alexdimaalexdima
committed
Record extensions activation times and show them in the ShowStartupPerformance action
1 parent 5be69f3 commit 227c103

7 files changed

Lines changed: 160 additions & 30 deletions

File tree

‎src/vs/platform/extensions/common/extensions.ts‎

Lines changed: 17 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -40,6 +40,18 @@ export interface IExtensionsStatus {
4040
messages: IMessage[];
4141
}
4242

43+
export class ActivationTimes {
44+
public readonly codeLoadingTime: number;
45+
public readonly activateCallTime: number;
46+
public readonly activateResolvedTime: number;
47+
48+
constructor(codeLoadingTime: number, activateCallTime: number, activateResolvedTime: number) {
49+
this.codeLoadingTime = codeLoadingTime;
50+
this.activateCallTime = activateCallTime;
51+
this.activateResolvedTime = activateResolvedTime;
52+
}
53+
}
54+
4355
export class ExtensionPointContribution<T> {
4456
readonly description: IExtensionDescription;
4557
readonly value: T;
@@ -78,6 +90,11 @@ export interface IExtensionService {
7890
*/
7991
getExtensionsStatus(): { [id: string]: IExtensionsStatus };
8092

93+
/**
94+
* Get information about extension activation times.
95+
*/
96+
getExtensionsActivationTimes(): { [id: string]: ActivationTimes; };
97+
8198
/**
8299
* Restarts the extension host.
83100
*/

‎src/vs/workbench/api/electron-browser/mainThreadExtensionService.ts‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -30,7 +30,8 @@ export class MainThreadExtensionService implements MainThreadExtensionServiceSha
3030
$localShowMessage(severity: Severity, msg: string): void {
3131
this._extensionService._logOrShowMessage(severity, msg);
3232
}
33-
$onExtensionActivated(extensionId: string): void {
33+
$onExtensionActivated(extensionId: string, codeLoadingTime: number, activateCallTime: number, activateResolvedTime: number): void {
34+
this._extensionService._onExtensionActivated(extensionId, codeLoadingTime, activateCallTime, activateResolvedTime);
3435
}
3536
$onExtensionActivationFailed(extensionId: string): void {
3637
}

‎src/vs/workbench/api/node/extHost.protocol.ts‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -306,7 +306,7 @@ export interface MainThreadTaskShape extends IDisposable {
306306

307307
export interface MainThreadExtensionServiceShape extends IDisposable {
308308
$localShowMessage(severity: Severity, msg: string): void;
309-
$onExtensionActivated(extensionId: string): void;
309+
$onExtensionActivated(extensionId: string, codeLoadingTime: number, activateCallTime: number, activateResolvedTime: number): void;
310310
$onExtensionActivationFailed(extensionId: string): void;
311311
}
312312

‎src/vs/workbench/api/node/extHostExtensionActivator.ts‎

Lines changed: 95 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -43,30 +43,111 @@ export interface IExtensionAPI {
4343
// _extensionAPIBrand: any;
4444
}
4545

46-
export class ActivatedExtension {
46+
export class ExtensionActivationTimes {
4747

48-
activationFailed: boolean;
49-
module: IExtensionModule;
50-
exports: IExtensionAPI;
51-
subscriptions: IDisposable[];
48+
public static NONE = new ExtensionActivationTimes(-1, -1, -1);
49+
50+
public readonly codeLoadingTime: number;
51+
public readonly activateCallTime: number;
52+
public readonly activateResolvedTime: number;
5253

53-
constructor(activationFailed: boolean, module: IExtensionModule, exports: IExtensionAPI, subscriptions: IDisposable[]) {
54+
constructor(codeLoadingTime: number, activateCallTime: number, activateResolvedTime: number) {
55+
this.codeLoadingTime = codeLoadingTime;
56+
this.activateCallTime = activateCallTime;
57+
this.activateResolvedTime = activateResolvedTime;
58+
}
59+
}
60+
61+
export class ExtensionActivationTimesBuilder {
62+
63+
private _codeLoadingStart: number;
64+
private _codeLoadingStop: number;
65+
private _activateCallStart: number;
66+
private _activateCallStop: number;
67+
private _activateResolveStart: number;
68+
private _activateResolveStop: number;
69+
70+
constructor() {
71+
this._codeLoadingStart = -1;
72+
this._codeLoadingStop = -1;
73+
this._activateCallStart = -1;
74+
this._activateCallStop = -1;
75+
this._activateResolveStart = -1;
76+
this._activateResolveStop = -1;
77+
}
78+
79+
private _delta(start: number, stop: number): number {
80+
if (start === -1 || stop === -1) {
81+
return -1;
82+
}
83+
return stop - start;
84+
}
85+
86+
public build(): ExtensionActivationTimes {
87+
return new ExtensionActivationTimes(
88+
this._delta(this._codeLoadingStart, this._codeLoadingStop),
89+
this._delta(this._activateCallStart, this._activateCallStop),
90+
this._delta(this._activateResolveStart, this._activateResolveStop)
91+
);
92+
}
93+
94+
public codeLoadingStart(): void {
95+
this._codeLoadingStart = Date.now();
96+
}
97+
98+
public codeLoadingStop(): void {
99+
this._codeLoadingStop = Date.now();
100+
}
101+
102+
public activateCallStart(): void {
103+
this._activateCallStart = Date.now();
104+
}
105+
106+
public activateCallStop(): void {
107+
this._activateCallStop = Date.now();
108+
}
109+
110+
public activateResolveStart(): void {
111+
this._activateResolveStart = Date.now();
112+
}
113+
114+
public activateResolveStop(): void {
115+
this._activateResolveStop = Date.now();
116+
}
117+
}
118+
119+
export class ActivatedExtension {
120+
121+
public readonly activationFailed: boolean;
122+
public readonly activationTimes: ExtensionActivationTimes;
123+
public readonly module: IExtensionModule;
124+
public readonly exports: IExtensionAPI;
125+
public readonly subscriptions: IDisposable[];
126+
127+
constructor(
128+
activationFailed: boolean,
129+
activationTimes: ExtensionActivationTimes,
130+
module: IExtensionModule,
131+
exports: IExtensionAPI,
132+
subscriptions: IDisposable[]
133+
) {
54134
this.activationFailed = activationFailed;
135+
this.activationTimes = activationTimes;
55136
this.module = module;
56137
this.exports = exports;
57138
this.subscriptions = subscriptions;
58139
}
59140
}
60141

61142
export class EmptyExtension extends ActivatedExtension {
62-
constructor() {
63-
super(false, { activate: undefined, deactivate: undefined }, undefined, []);
143+
constructor(activationTimes: ExtensionActivationTimes) {
144+
super(false, activationTimes, { activate: undefined, deactivate: undefined }, undefined, []);
64145
}
65146
}
66147

67148
export class FailedExtension extends ActivatedExtension {
68-
constructor() {
69-
super(true, { activate: undefined, deactivate: undefined }, undefined, []);
149+
constructor(activationTimes: ExtensionActivationTimes) {
150+
super(true, activationTimes, { activate: undefined, deactivate: undefined }, undefined, []);
70151
}
71152
}
72153

@@ -140,7 +221,7 @@ export class ExtensionsActivator {
140221
if (!depDesc) {
141222
// Error condition 1: unknown dependency
142223
this._host.showMessage(Severity.Error, nls.localize('unknownDep', "Extension `{1}` failed to activate. Reason: unknown dependency `{0}`.", depId, currentExtension.id));
143-
this._activatedExtensions[currentExtension.id] = new FailedExtension();
224+
this._activatedExtensions[currentExtension.id] = new FailedExtension(ExtensionActivationTimes.NONE);
144225
return;
145226
}
146227

@@ -149,7 +230,7 @@ export class ExtensionsActivator {
149230
if (dep.activationFailed) {
150231
// Error condition 2: a dependency has already failed activation
151232
this._host.showMessage(Severity.Error, nls.localize('failedDep1', "Extension `{1}` failed to activate. Reason: dependency `{0}` failed to activate.", depId, currentExtension.id));
152-
this._activatedExtensions[currentExtension.id] = new FailedExtension();
233+
this._activatedExtensions[currentExtension.id] = new FailedExtension(ExtensionActivationTimes.NONE);
153234
return;
154235
}
155236
} else {
@@ -182,7 +263,7 @@ export class ExtensionsActivator {
182263
for (let i = 0, len = extensionDescriptions.length; i < len; i++) {
183264
// Error condition 3: dependency loop
184265
this._host.showMessage(Severity.Error, nls.localize('failedDep2', "Extension `{0}` failed to activate. Reason: more than 10 levels of dependencies (most likely a dependency loop).", extensionDescriptions[i].id));
185-
this._activatedExtensions[extensionDescriptions[i].id] = new FailedExtension();
266+
this._activatedExtensions[extensionDescriptions[i].id] = new FailedExtension(ExtensionActivationTimes.NONE);
186267
}
187268
return TPromise.as(void 0);
188269
}
@@ -230,7 +311,7 @@ export class ExtensionsActivator {
230311
console.error('Activating extension `' + extensionDescription.id + '` failed: ', err.message);
231312
console.log('Here is the error stack: ', err.stack);
232313
// Treat the extension as being empty
233-
return new FailedExtension();
314+
return new FailedExtension(ExtensionActivationTimes.NONE);
234315
}).then((x: ActivatedExtension) => {
235316
this._activatedExtensions[extensionDescription.id] = x;
236317
delete this._activatingExtensions[extensionDescription.id];

‎src/vs/workbench/api/node/extHostExtensionService.ts‎

Lines changed: 25 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -14,7 +14,7 @@ import { IExtensionDescription } from 'vs/platform/extensions/common/extensions'
1414
import { ExtHostStorage } from 'vs/workbench/api/node/extHostStorage';
1515
import { createApiFactory, initializeExtensionApi } from 'vs/workbench/api/node/extHost.api.impl';
1616
import { MainContext, MainThreadExtensionServiceShape, IWorkspaceData, IEnvironment, IInitData, ExtHostExtensionServiceShape, MainThreadTelemetryShape } from './extHost.protocol';
17-
import { IExtensionMemento, ExtensionsActivator, ActivatedExtension, IExtensionAPI, IExtensionContext, EmptyExtension, IExtensionModule } from 'vs/workbench/api/node/extHostExtensionActivator';
17+
import { IExtensionMemento, ExtensionsActivator, ActivatedExtension, IExtensionAPI, IExtensionContext, EmptyExtension, IExtensionModule, ExtensionActivationTimesBuilder, ExtensionActivationTimes } from 'vs/workbench/api/node/extHostExtensionActivator';
1818
import { Barrier } from 'vs/workbench/services/extensions/node/barrier';
1919
import { ExtHostThreadService } from 'vs/workbench/services/thread/node/extHostThreadService';
2020
import { realpath } from 'fs';
@@ -270,7 +270,8 @@ export class ExtHostExtensionService implements ExtHostExtensionServiceShape {
270270

271271
private _activateExtension(extensionDescription: IExtensionDescription): TPromise<ActivatedExtension> {
272272
return this._doActivateExtension(extensionDescription).then((activatedExtension) => {
273-
this._proxy.$onExtensionActivated(extensionDescription.id);
273+
const activationTimes = activatedExtension.activationTimes;
274+
this._proxy.$onExtensionActivated(extensionDescription.id, activationTimes.codeLoadingTime, activationTimes.activateCallTime, activationTimes.activateResolvedTime);
274275
return activatedExtension;
275276
}, (err) => {
276277
this._proxy.$onExtensionActivationFailed(extensionDescription.id);
@@ -283,13 +284,15 @@ export class ExtHostExtensionService implements ExtHostExtensionServiceShape {
283284
this._mainThreadTelemetry.$publicLog('activatePlugin', event);
284285
if (!extensionDescription.main) {
285286
// Treat the extension as being empty => NOT AN ERROR CASE
286-
return TPromise.as(new EmptyExtension());
287+
return TPromise.as(new EmptyExtension(ExtensionActivationTimes.NONE));
287288
}
289+
290+
const activationTimesBuilder = new ExtensionActivationTimesBuilder();
288291
return TPromise.join<any>([
289-
loadCommonJSModule(extensionDescription.main),
292+
loadCommonJSModule(extensionDescription.main, activationTimesBuilder),
290293
this._loadExtensionContext(extensionDescription)
291294
]).then(values => {
292-
return ExtHostExtensionService._callActivate(<IExtensionModule>values[0], <IExtensionContext>values[1]);
295+
return ExtHostExtensionService._callActivate(<IExtensionModule>values[0], <IExtensionContext>values[1], activationTimesBuilder);
293296
}, (errors: any[]) => {
294297
// Avoid failing with an array of errors, fail with a single error
295298
if (errors[0]) {
@@ -323,22 +326,30 @@ export class ExtHostExtensionService implements ExtHostExtensionServiceShape {
323326
});
324327
}
325328

326-
private static _callActivate(extensionModule: IExtensionModule, context: IExtensionContext): TPromise<ActivatedExtension> {
329+
private static _callActivate(extensionModule: IExtensionModule, context: IExtensionContext, activationTimesBuilder: ExtensionActivationTimesBuilder): TPromise<ActivatedExtension> {
327330
// Make sure the extension's surface is not undefined
328331
extensionModule = extensionModule || {
329332
activate: undefined,
330333
deactivate: undefined
331334
};
332335

333-
return this._callActivateOptional(extensionModule, context).then((extensionExports) => {
334-
return new ActivatedExtension(false, extensionModule, extensionExports, context.subscriptions);
336+
return this._callActivateOptional(extensionModule, context, activationTimesBuilder).then((extensionExports) => {
337+
return new ActivatedExtension(false, activationTimesBuilder.build(), extensionModule, extensionExports, context.subscriptions);
335338
});
336339
}
337340

338-
private static _callActivateOptional(extensionModule: IExtensionModule, context: IExtensionContext): TPromise<IExtensionAPI> {
341+
private static _callActivateOptional(extensionModule: IExtensionModule, context: IExtensionContext, activationTimesBuilder: ExtensionActivationTimesBuilder): TPromise<IExtensionAPI> {
339342
if (typeof extensionModule.activate === 'function') {
340343
try {
341-
return TPromise.as(extensionModule.activate.apply(global, [context]));
344+
activationTimesBuilder.activateCallStart();
345+
const activateResult = extensionModule.activate.apply(global, [context]);
346+
activationTimesBuilder.activateCallStop();
347+
348+
activationTimesBuilder.activateResolveStart();
349+
return TPromise.as(activateResult).then((value) => {
350+
activationTimesBuilder.activateResolveStop();
351+
return value;
352+
});
342353
} catch (err) {
343354
return TPromise.wrapError(err);
344355
}
@@ -355,12 +366,15 @@ export class ExtHostExtensionService implements ExtHostExtensionServiceShape {
355366
}
356367
}
357368

358-
function loadCommonJSModule<T>(modulePath: string): TPromise<T> {
369+
function loadCommonJSModule<T>(modulePath: string, activationTimesBuilder: ExtensionActivationTimesBuilder): TPromise<T> {
359370
let r: T = null;
371+
activationTimesBuilder.codeLoadingStart();
360372
try {
361373
r = require.__$__nodeRequire<T>(modulePath);
362374
} catch (e) {
363375
return TPromise.wrapError<T>(e);
376+
} finally {
377+
activationTimesBuilder.codeLoadingStop();
364378
}
365379
return TPromise.as(r);
366380
}

‎src/vs/workbench/electron-browser/actions.ts‎

Lines changed: 7 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -45,6 +45,7 @@ import { IPanel } from 'vs/workbench/common/panel';
4545
import { IWorkspaceIdentifier, getWorkspaceLabel, ISingleFolderWorkspaceIdentifier, isSingleFolderWorkspaceIdentifier } from 'vs/platform/workspaces/common/workspaces';
4646
import { FileKind } from 'vs/platform/files/common/files';
4747
import { IInstantiationService } from 'vs/platform/instantiation/common/instantiation';
48+
import { IExtensionService } from 'vs/platform/extensions/common/extensions';
4849

4950
// --- actions
5051

@@ -325,7 +326,8 @@ export class ShowStartupPerformance extends Action {
325326
label: string,
326327
@IWindowService private windowService: IWindowService,
327328
@ITimerService private timerService: ITimerService,
328-
@IEnvironmentService private environmentService: IEnvironmentService
329+
@IEnvironmentService private environmentService: IEnvironmentService,
330+
@IExtensionService private extensionService: IExtensionService
329331
) {
330332
super(id, label);
331333
}
@@ -368,6 +370,10 @@ export class ShowStartupPerformance extends Action {
368370
}
369371

370372
(<any>console).groupEnd();
373+
374+
(<any>console).group('Extension Activation Stats');
375+
(<any>console).table(this.extensionService.getExtensionsActivationTimes());
376+
(<any>console).groupEnd();
371377
}, 1000);
372378

373379
return TPromise.as(true);

‎src/vs/workbench/services/extensions/electron-browser/extensionService.ts‎

Lines changed: 13 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -12,7 +12,7 @@ import pkg from 'vs/platform/node/package';
1212
import * as path from 'path';
1313
import URI from 'vs/base/common/uri';
1414
import { ExtensionDescriptionRegistry } from 'vs/workbench/services/extensions/node/extensionDescriptionRegistry';
15-
import { IMessage, IExtensionDescription, IExtensionsStatus, IExtensionService, ExtensionPointContribution } from 'vs/platform/extensions/common/extensions';
15+
import { IMessage, IExtensionDescription, IExtensionsStatus, IExtensionService, ExtensionPointContribution, ActivationTimes } from 'vs/platform/extensions/common/extensions';
1616
import { IExtensionEnablementService } from 'vs/platform/extensionManagement/common/extensionManagement';
1717
import { areSameExtensions, getGloballyDisabledExtensions } from 'vs/platform/extensionManagement/common/extensionManagementUtil';
1818
import { ExtensionsRegistry, ExtensionPoint, IExtensionPointUser, ExtensionMessageCollector, IExtensionPoint } from 'vs/platform/extensions/common/extensionsRegistry';
@@ -65,6 +65,7 @@ export class ExtensionService implements IExtensionService {
6565
* A map of already activated events to speed things up if the same activation event is triggered multiple times.
6666
*/
6767
private _extensionHostProcessFinishedActivateEvents: { [activationEvent: string]: boolean; };
68+
private _extensionHostProcessActivationTimes: { [id: string]: ActivationTimes; };
6869
private _extensionHostProcessWorker: ExtensionHostProcessWorker;
6970
private _extensionHostProcessThreadService: MainThreadService;
7071
private _extensionHostProcessCustomers: IDisposable[];
@@ -89,6 +90,7 @@ export class ExtensionService implements IExtensionService {
8990
this._allRequestedActivateEvents = Object.create(null);
9091

9192
this._extensionHostProcessFinishedActivateEvents = Object.create(null);
93+
this._extensionHostProcessActivationTimes = Object.create(null);
9294
this._extensionHostProcessWorker = null;
9395
this._extensionHostProcessThreadService = null;
9496
this._extensionHostProcessCustomers = [];
@@ -105,6 +107,7 @@ export class ExtensionService implements IExtensionService {
105107

106108
private _stopExtensionHostProcess(): void {
107109
this._extensionHostProcessFinishedActivateEvents = Object.create(null);
110+
this._extensionHostProcessActivationTimes = Object.create(null);
108111
if (this._extensionHostProcessWorker) {
109112
this._extensionHostProcessWorker.dispose();
110113
this._extensionHostProcessWorker = null;
@@ -263,10 +266,14 @@ export class ExtensionService implements IExtensionService {
263266
});
264267
}
265268

266-
public getExtensionsStatus(): { [id: string]: IExtensionsStatus } {
269+
public getExtensionsStatus(): { [id: string]: IExtensionsStatus; } {
267270
return this._extensionsStatus;
268271
}
269272

273+
public getExtensionsActivationTimes(): { [id: string]: ActivationTimes; } {
274+
return this._extensionHostProcessActivationTimes;
275+
}
276+
270277
// ---- end IExtensionService
271278

272279
// --- impl
@@ -411,6 +418,10 @@ export class ExtensionService implements IExtensionService {
411418
this._logMessageInConsole(severity, msg);
412419
}
413420
}
421+
422+
public _onExtensionActivated(extensionId: string, codeLoadingTime: number, activateCallTime: number, activateResolvedTime: number): void {
423+
this._extensionHostProcessActivationTimes[extensionId] = new ActivationTimes(codeLoadingTime, activateCallTime, activateResolvedTime);
424+
}
414425
}
415426

416427
export class Logger implements ILog {

0 commit comments

Comments
 (0)