Record extensions activation times and show them in the ShowStartupPerformance action

This commit is contained in:
Alex Dima
2017-08-25 11:30:10 +02:00
parent 5be69f3e65
commit 227c103348
7 changed files with 159 additions and 29 deletions

View File

@@ -306,7 +306,7 @@ export interface MainThreadTaskShape extends IDisposable {
export interface MainThreadExtensionServiceShape extends IDisposable {
$localShowMessage(severity: Severity, msg: string): void;
$onExtensionActivated(extensionId: string): void;
$onExtensionActivated(extensionId: string, codeLoadingTime: number, activateCallTime: number, activateResolvedTime: number): void;
$onExtensionActivationFailed(extensionId: string): void;
}

View File

@@ -43,15 +43,96 @@ export interface IExtensionAPI {
// _extensionAPIBrand: any;
}
export class ExtensionActivationTimes {
public static NONE = new ExtensionActivationTimes(-1, -1, -1);
public readonly codeLoadingTime: number;
public readonly activateCallTime: number;
public readonly activateResolvedTime: number;
constructor(codeLoadingTime: number, activateCallTime: number, activateResolvedTime: number) {
this.codeLoadingTime = codeLoadingTime;
this.activateCallTime = activateCallTime;
this.activateResolvedTime = activateResolvedTime;
}
}
export class ExtensionActivationTimesBuilder {
private _codeLoadingStart: number;
private _codeLoadingStop: number;
private _activateCallStart: number;
private _activateCallStop: number;
private _activateResolveStart: number;
private _activateResolveStop: number;
constructor() {
this._codeLoadingStart = -1;
this._codeLoadingStop = -1;
this._activateCallStart = -1;
this._activateCallStop = -1;
this._activateResolveStart = -1;
this._activateResolveStop = -1;
}
private _delta(start: number, stop: number): number {
if (start === -1 || stop === -1) {
return -1;
}
return stop - start;
}
public build(): ExtensionActivationTimes {
return new ExtensionActivationTimes(
this._delta(this._codeLoadingStart, this._codeLoadingStop),
this._delta(this._activateCallStart, this._activateCallStop),
this._delta(this._activateResolveStart, this._activateResolveStop)
);
}
public codeLoadingStart(): void {
this._codeLoadingStart = Date.now();
}
public codeLoadingStop(): void {
this._codeLoadingStop = Date.now();
}
public activateCallStart(): void {
this._activateCallStart = Date.now();
}
public activateCallStop(): void {
this._activateCallStop = Date.now();
}
public activateResolveStart(): void {
this._activateResolveStart = Date.now();
}
public activateResolveStop(): void {
this._activateResolveStop = Date.now();
}
}
export class ActivatedExtension {
activationFailed: boolean;
module: IExtensionModule;
exports: IExtensionAPI;
subscriptions: IDisposable[];
public readonly activationFailed: boolean;
public readonly activationTimes: ExtensionActivationTimes;
public readonly module: IExtensionModule;
public readonly exports: IExtensionAPI;
public readonly subscriptions: IDisposable[];
constructor(activationFailed: boolean, module: IExtensionModule, exports: IExtensionAPI, subscriptions: IDisposable[]) {
constructor(
activationFailed: boolean,
activationTimes: ExtensionActivationTimes,
module: IExtensionModule,
exports: IExtensionAPI,
subscriptions: IDisposable[]
) {
this.activationFailed = activationFailed;
this.activationTimes = activationTimes;
this.module = module;
this.exports = exports;
this.subscriptions = subscriptions;
@@ -59,14 +140,14 @@ export class ActivatedExtension {
}
export class EmptyExtension extends ActivatedExtension {
constructor() {
super(false, { activate: undefined, deactivate: undefined }, undefined, []);
constructor(activationTimes: ExtensionActivationTimes) {
super(false, activationTimes, { activate: undefined, deactivate: undefined }, undefined, []);
}
}
export class FailedExtension extends ActivatedExtension {
constructor() {
super(true, { activate: undefined, deactivate: undefined }, undefined, []);
constructor(activationTimes: ExtensionActivationTimes) {
super(true, activationTimes, { activate: undefined, deactivate: undefined }, undefined, []);
}
}
@@ -140,7 +221,7 @@ export class ExtensionsActivator {
if (!depDesc) {
// Error condition 1: unknown dependency
this._host.showMessage(Severity.Error, nls.localize('unknownDep', "Extension `{1}` failed to activate. Reason: unknown dependency `{0}`.", depId, currentExtension.id));
this._activatedExtensions[currentExtension.id] = new FailedExtension();
this._activatedExtensions[currentExtension.id] = new FailedExtension(ExtensionActivationTimes.NONE);
return;
}
@@ -149,7 +230,7 @@ export class ExtensionsActivator {
if (dep.activationFailed) {
// Error condition 2: a dependency has already failed activation
this._host.showMessage(Severity.Error, nls.localize('failedDep1', "Extension `{1}` failed to activate. Reason: dependency `{0}` failed to activate.", depId, currentExtension.id));
this._activatedExtensions[currentExtension.id] = new FailedExtension();
this._activatedExtensions[currentExtension.id] = new FailedExtension(ExtensionActivationTimes.NONE);
return;
}
} else {
@@ -182,7 +263,7 @@ export class ExtensionsActivator {
for (let i = 0, len = extensionDescriptions.length; i < len; i++) {
// Error condition 3: dependency loop
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));
this._activatedExtensions[extensionDescriptions[i].id] = new FailedExtension();
this._activatedExtensions[extensionDescriptions[i].id] = new FailedExtension(ExtensionActivationTimes.NONE);
}
return TPromise.as(void 0);
}
@@ -230,7 +311,7 @@ export class ExtensionsActivator {
console.error('Activating extension `' + extensionDescription.id + '` failed: ', err.message);
console.log('Here is the error stack: ', err.stack);
// Treat the extension as being empty
return new FailedExtension();
return new FailedExtension(ExtensionActivationTimes.NONE);
}).then((x: ActivatedExtension) => {
this._activatedExtensions[extensionDescription.id] = x;
delete this._activatingExtensions[extensionDescription.id];

View File

@@ -14,7 +14,7 @@ import { IExtensionDescription } from 'vs/platform/extensions/common/extensions'
import { ExtHostStorage } from 'vs/workbench/api/node/extHostStorage';
import { createApiFactory, initializeExtensionApi } from 'vs/workbench/api/node/extHost.api.impl';
import { MainContext, MainThreadExtensionServiceShape, IWorkspaceData, IEnvironment, IInitData, ExtHostExtensionServiceShape, MainThreadTelemetryShape } from './extHost.protocol';
import { IExtensionMemento, ExtensionsActivator, ActivatedExtension, IExtensionAPI, IExtensionContext, EmptyExtension, IExtensionModule } from 'vs/workbench/api/node/extHostExtensionActivator';
import { IExtensionMemento, ExtensionsActivator, ActivatedExtension, IExtensionAPI, IExtensionContext, EmptyExtension, IExtensionModule, ExtensionActivationTimesBuilder, ExtensionActivationTimes } from 'vs/workbench/api/node/extHostExtensionActivator';
import { Barrier } from 'vs/workbench/services/extensions/node/barrier';
import { ExtHostThreadService } from 'vs/workbench/services/thread/node/extHostThreadService';
import { realpath } from 'fs';
@@ -270,7 +270,8 @@ export class ExtHostExtensionService implements ExtHostExtensionServiceShape {
private _activateExtension(extensionDescription: IExtensionDescription): TPromise<ActivatedExtension> {
return this._doActivateExtension(extensionDescription).then((activatedExtension) => {
this._proxy.$onExtensionActivated(extensionDescription.id);
const activationTimes = activatedExtension.activationTimes;
this._proxy.$onExtensionActivated(extensionDescription.id, activationTimes.codeLoadingTime, activationTimes.activateCallTime, activationTimes.activateResolvedTime);
return activatedExtension;
}, (err) => {
this._proxy.$onExtensionActivationFailed(extensionDescription.id);
@@ -283,13 +284,15 @@ export class ExtHostExtensionService implements ExtHostExtensionServiceShape {
this._mainThreadTelemetry.$publicLog('activatePlugin', event);
if (!extensionDescription.main) {
// Treat the extension as being empty => NOT AN ERROR CASE
return TPromise.as(new EmptyExtension());
return TPromise.as(new EmptyExtension(ExtensionActivationTimes.NONE));
}
const activationTimesBuilder = new ExtensionActivationTimesBuilder();
return TPromise.join<any>([
loadCommonJSModule(extensionDescription.main),
loadCommonJSModule(extensionDescription.main, activationTimesBuilder),
this._loadExtensionContext(extensionDescription)
]).then(values => {
return ExtHostExtensionService._callActivate(<IExtensionModule>values[0], <IExtensionContext>values[1]);
return ExtHostExtensionService._callActivate(<IExtensionModule>values[0], <IExtensionContext>values[1], activationTimesBuilder);
}, (errors: any[]) => {
// Avoid failing with an array of errors, fail with a single error
if (errors[0]) {
@@ -323,22 +326,30 @@ export class ExtHostExtensionService implements ExtHostExtensionServiceShape {
});
}
private static _callActivate(extensionModule: IExtensionModule, context: IExtensionContext): TPromise<ActivatedExtension> {
private static _callActivate(extensionModule: IExtensionModule, context: IExtensionContext, activationTimesBuilder: ExtensionActivationTimesBuilder): TPromise<ActivatedExtension> {
// Make sure the extension's surface is not undefined
extensionModule = extensionModule || {
activate: undefined,
deactivate: undefined
};
return this._callActivateOptional(extensionModule, context).then((extensionExports) => {
return new ActivatedExtension(false, extensionModule, extensionExports, context.subscriptions);
return this._callActivateOptional(extensionModule, context, activationTimesBuilder).then((extensionExports) => {
return new ActivatedExtension(false, activationTimesBuilder.build(), extensionModule, extensionExports, context.subscriptions);
});
}
private static _callActivateOptional(extensionModule: IExtensionModule, context: IExtensionContext): TPromise<IExtensionAPI> {
private static _callActivateOptional(extensionModule: IExtensionModule, context: IExtensionContext, activationTimesBuilder: ExtensionActivationTimesBuilder): TPromise<IExtensionAPI> {
if (typeof extensionModule.activate === 'function') {
try {
return TPromise.as(extensionModule.activate.apply(global, [context]));
activationTimesBuilder.activateCallStart();
const activateResult = extensionModule.activate.apply(global, [context]);
activationTimesBuilder.activateCallStop();
activationTimesBuilder.activateResolveStart();
return TPromise.as(activateResult).then((value) => {
activationTimesBuilder.activateResolveStop();
return value;
});
} catch (err) {
return TPromise.wrapError(err);
}
@@ -355,12 +366,15 @@ export class ExtHostExtensionService implements ExtHostExtensionServiceShape {
}
}
function loadCommonJSModule<T>(modulePath: string): TPromise<T> {
function loadCommonJSModule<T>(modulePath: string, activationTimesBuilder: ExtensionActivationTimesBuilder): TPromise<T> {
let r: T = null;
activationTimesBuilder.codeLoadingStart();
try {
r = require.__$__nodeRequire<T>(modulePath);
} catch (e) {
return TPromise.wrapError<T>(e);
} finally {
activationTimesBuilder.codeLoadingStop();
}
return TPromise.as(r);
}