Skip to content

Commit

Permalink
Add start-up timing logs in frontend and backend
Browse files Browse the repository at this point in the history
Added some finer-grained logging of timing measurements
in backend start-up tasks. Includes a refactoring of
similar patterns used throughout frontend and backend
code, using different performance tracing APIs, into
a common injected Stopwatch service providing
Measurements. Also publishes the backend Stopwatch
to frontends via a new BackendStopwatch RPC service,
letting frontends log messages in the timeframe of the
backend application.

Contributed on behalf of STMicroelectronics.

Signed-off-by: Christian W. Damus <[email protected]>
  • Loading branch information
cdamus committed Nov 10, 2021
1 parent f09fc1a commit 05a1731
Show file tree
Hide file tree
Showing 19 changed files with 643 additions and 103 deletions.
2 changes: 2 additions & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
@@ -1,5 +1,7 @@
# Change Log

- [plugin-ext] add more detail to logging of back-end and front-end start-up, especially in plug-in management [#](https://github.com/eclipse-theia/theia/pull/#) - Contributed on behalf of STMicroelectronics

## v1.19.0 - 10/28/2021

[1.19.0 Milestone](https://github.com/eclipse-theia/theia/milestone/25)
Expand Down
4 changes: 4 additions & 0 deletions packages/core/src/browser/frontend-application-module.ts
Original file line number Diff line number Diff line change
Expand Up @@ -119,6 +119,7 @@ import {
} from './breadcrumbs';
import { RendererHost } from './widgets';
import { TooltipService, TooltipServiceImpl } from './tooltip-service';
import { bindFrontendStopwatch, bindBackendStopwatch } from './performance';

export { bindResourceProvider, bindMessageService, bindPreferenceService };

Expand Down Expand Up @@ -389,4 +390,7 @@ export const frontendApplicationModule = new ContainerModule((bind, unbind, isBo
child.bind(Coordinate).toConstantValue(position);
return child.get(BreadcrumbPopupContainer);
});

bindFrontendStopwatch(bind);
bindBackendStopwatch(bind);
});
45 changes: 22 additions & 23 deletions packages/core/src/browser/frontend-application.ts
Original file line number Diff line number Diff line change
Expand Up @@ -14,8 +14,8 @@
* SPDX-License-Identifier: EPL-2.0 OR GPL-2.0 WITH Classpath-exception-2.0
********************************************************************************/

import { inject, injectable, named } from 'inversify';
import { ContributionProvider, CommandRegistry, MenuModelRegistry, isOSX } from '../common';
import { inject, injectable, named, optional } from 'inversify';
import { ContributionProvider, CommandRegistry, MenuModelRegistry, isOSX, BackendStopwatch, LogLevel, Stopwatch } from '../common';
import { MaybePromise } from '../common/types';
import { KeybindingRegistry } from './keybinding';
import { Widget } from './widgets';
Expand Down Expand Up @@ -104,6 +104,13 @@ export class FrontendApplication {
@inject(TooltipService)
protected readonly tooltipService: TooltipService;

@inject(Stopwatch)
protected readonly stopwatch: Stopwatch;

@optional()
@inject(BackendStopwatch)
protected readonly backendStopwatch?: BackendStopwatch;

constructor(
@inject(CommandRegistry) protected readonly commands: CommandRegistry,
@inject(MenuModelRegistry) protected readonly menus: MenuModelRegistry,
Expand All @@ -129,7 +136,9 @@ export class FrontendApplication {
* - reveal the application shell if it was hidden by a startup indicator
*/
async start(): Promise<void> {
await this.startContributions();
const startup = this.backendStopwatch?.start('frontend');

await this.measure('startContributions', () => this.startContributions(), 'Start frontend contributions', false);
this.stateService.state = 'started_contributions';

const host = await this.getHost();
Expand All @@ -138,13 +147,16 @@ export class FrontendApplication {
await animationFrame();
this.stateService.state = 'attached_shell';

await this.initializeLayout();
await this.measure('initializeLayout', () => this.initializeLayout(), 'Initialize the workbench layout', false);
this.stateService.state = 'initialized_layout';
await this.fireOnDidInitializeLayout();

await this.revealShell(host);
this.registerEventListeners();
this.stateService.state = 'ready';

// If the startup exists, then it was created by the backendStopwatch, so that is known also to exist
startup?.then(idToken => this.backendStopwatch!.stop(idToken, 'Frontend application start', []));
}

/**
Expand Down Expand Up @@ -240,10 +252,9 @@ export class FrontendApplication {
protected revealShell(host: HTMLElement): Promise<void> {
const startupElem = this.getStartupIndicator(host);
if (startupElem) {
return new Promise(resolve => {
const doRevealShell = () => new Promise<void>(resolve => {
window.requestAnimationFrame(() => {
startupElem.classList.add('theia-hidden');
console.log(`Finished loading frontend application after ${(performance.now() / 1000).toFixed(3)} seconds`);
const preloadStyle = window.getComputedStyle(startupElem);
const transitionDuration = parseCssTime(preloadStyle.transitionDuration, 0);
window.setTimeout(() => {
Expand All @@ -255,6 +266,8 @@ export class FrontendApplication {
}, transitionDuration);
});
});
return this.stopwatch.startAsync('revealShell', 'Replace loading indicator with ready workbench UI (animation)', doRevealShell,
{ defaultLogLevel: LogLevel.INFO });
} else {
return Promise.resolve();
}
Expand Down Expand Up @@ -385,23 +398,9 @@ export class FrontendApplication {
console.info('<<< All frontend contributions have been stopped.');
}

protected async measure<T>(name: string, fn: () => MaybePromise<T>): Promise<T> {
const startMark = name + '-start';
const endMark = name + '-end';
performance.mark(startMark);
const result = await fn();
performance.mark(endMark);
performance.measure(name, startMark, endMark);
for (const item of performance.getEntriesByName(name)) {
const contribution = `Frontend ${item.name}`;
if (item.duration > TIMER_WARNING_THRESHOLD) {
console.warn(`${contribution} is slow, took: ${item.duration.toFixed(1)} ms`);
} else {
console.debug(`${contribution} took: ${item.duration.toFixed(1)} ms`);
}
}
performance.clearMeasures(name);
return result;
protected async measure<T>(name: string, fn: () => MaybePromise<T>, message = `Frontend ${name}`, threshold = true): Promise<T> {
return this.stopwatch.startAsync(name, message, fn,
threshold ? { thresholdMillis: TIMER_WARNING_THRESHOLD, defaultLogLevel: LogLevel.DEBUG } : {});
}

}
62 changes: 62 additions & 0 deletions packages/core/src/browser/performance/frontend-stopwatch.ts
Original file line number Diff line number Diff line change
@@ -0,0 +1,62 @@
/********************************************************************************
* Copyright (c) 2019, 2021 TypeFox, STMicroelectronics and others.
*
* This program and the accompanying materials are made available under the
* terms of the Eclipse Public License 2.0 which is available at
* http://www.eclipse.org/legal/epl-2.0.
*
* This Source Code may also be made available under the following Secondary
* Licenses when the conditions for such availability set forth in the Eclipse
* Public License v. 2.0 are satisfied: GNU General Public License, version 2
* with the GNU Classpath Exception which is available at
* https://www.gnu.org/software/classpath/license.html.
*
* SPDX-License-Identifier: EPL-2.0 OR GPL-2.0 WITH Classpath-exception-2.0
*******************************************************************************/

import { injectable } from 'inversify';
import { Measurement, MeasurementOptions, Stopwatch } from '../../common';

@injectable()
export class FrontendStopwatch extends Stopwatch {

constructor() {
super({
owner: 'frontend',
now: () => performance.now(),
});
}

start(name: string, options?: MeasurementOptions): Measurement {
const startMarker = `${name}-start`;
const endMarker = `${name}-end`;
performance.clearMeasures(name);
performance.clearMarks(startMarker);
performance.clearMarks(endMarker);

performance.mark(startMarker);

return this.createMeasurement(name, () => {
performance.mark(endMarker);

let duration: number;

try {
performance.measure(name, startMarker, endMarker);

const entries = performance.getEntriesByName(name);
// If no entries, then performance measurement was disabled or failed, so
// signal that with a `NaN` result
duration = entries.length > 0 ? entries[0].duration : Number.NaN;
} catch (e) {
console.warn(e);
duration = Number.NaN;
}

performance.clearMeasures(name);
performance.clearMarks(startMarker);
performance.clearMarks(endMarker);
return duration;
}, options);
}
};
18 changes: 18 additions & 0 deletions packages/core/src/browser/performance/index.ts
Original file line number Diff line number Diff line change
@@ -0,0 +1,18 @@
/********************************************************************************
* Copyright (C) 2021 STMicroelectronics and others.
*
* This program and the accompanying materials are made available under the
* terms of the Eclipse Public License v. 2.0 which is available at
* http://www.eclipse.org/legal/epl-2.0.
*
* This Source Code may also be made available under the following Secondary
* Licenses when the conditions for such availability set forth in the Eclipse
* Public License v. 2.0 are satisfied: GNU General Public License, version 2
* with the GNU Classpath Exception which is available at
* https://www.gnu.org/software/classpath/license.html.
*
* SPDX-License-Identifier: EPL-2.0 OR GPL-2.0 WITH Classpath-exception-2.0
********************************************************************************/

export * from './frontend-stopwatch';
export * from './measurement-frontend-bindings';
Original file line number Diff line number Diff line change
@@ -0,0 +1,31 @@
/********************************************************************************
* Copyright (c) 2021 STMicroelectronics and others.
*
* This program and the accompanying materials are made available under the
* terms of the Eclipse Public License 2.0 which is available at
* http://www.eclipse.org/legal/epl-2.0.
*
* This Source Code may also be made available under the following Secondary
* Licenses when the conditions for such availability set forth in the Eclipse
* Public License v. 2.0 are satisfied: GNU General Public License, version 2
* with the GNU Classpath Exception which is available at
* https://www.gnu.org/software/classpath/license.html.
*
* SPDX-License-Identifier: EPL-2.0 OR GPL-2.0 WITH Classpath-exception-2.0
*******************************************************************************/

import { interfaces } from 'inversify';
import { BackendStopwatch, Stopwatch, stopwatchPath } from '../../common';
import { WebSocketConnectionProvider } from '../messaging';
import { FrontendStopwatch } from './frontend-stopwatch';

export function bindFrontendStopwatch(bind: interfaces.Bind): interfaces.BindingWhenOnSyntax<Stopwatch> {
return bind(Stopwatch).to(FrontendStopwatch).inSingletonScope();
}

export function bindBackendStopwatch(bind: interfaces.Bind): interfaces.BindingWhenOnSyntax<unknown> {
return bind(BackendStopwatch).toDynamicValue(ctx => {
const connection = ctx.container.get(WebSocketConnectionProvider);
return connection.createProxy<BackendStopwatch>(stopwatchPath);
}).inSingletonScope();
}
1 change: 1 addition & 0 deletions packages/core/src/common/index.ts
Original file line number Diff line number Diff line change
Expand Up @@ -39,6 +39,7 @@ export * from './application-error';
export * from './lsp-types';
export * from './contribution-filter';
export * from './nls';
export * from './performance';

import { environment } from '@theia/application-package/lib/environment';
export { environment };
19 changes: 19 additions & 0 deletions packages/core/src/common/performance/index.ts
Original file line number Diff line number Diff line change
@@ -0,0 +1,19 @@
/********************************************************************************
* Copyright (C) 2021 STMicroelectronics and others.
*
* This program and the accompanying materials are made available under the
* terms of the Eclipse Public License v. 2.0 which is available at
* http://www.eclipse.org/legal/epl-2.0.
*
* This Source Code may also be made available under the following Secondary
* Licenses when the conditions for such availability set forth in the Eclipse
* Public License v. 2.0 are satisfied: GNU General Public License, version 2
* with the GNU Classpath Exception which is available at
* https://www.gnu.org/software/classpath/license.html.
*
* SPDX-License-Identifier: EPL-2.0 OR GPL-2.0 WITH Classpath-exception-2.0
********************************************************************************/

export * from './measurement';
export * from './stopwatch';
export * from './measurement-protocol';
87 changes: 87 additions & 0 deletions packages/core/src/common/performance/measurement-protocol.ts
Original file line number Diff line number Diff line change
@@ -0,0 +1,87 @@
/********************************************************************************
* Copyright (c) 2021 STMicroelectronics and others.
*
* This program and the accompanying materials are made available under the
* terms of the Eclipse Public License 2.0 which is available at
* http://www.eclipse.org/legal/epl-2.0.
*
* This Source Code may also be made available under the following Secondary
* Licenses when the conditions for such availability set forth in the Eclipse
* Public License v. 2.0 are satisfied: GNU General Public License, version 2
* with the GNU Classpath Exception which is available at
* https://www.gnu.org/software/classpath/license.html.
*
* SPDX-License-Identifier: EPL-2.0 OR GPL-2.0 WITH Classpath-exception-2.0
*******************************************************************************/

/* eslint-disable @typescript-eslint/no-explicit-any */

import { inject, injectable, LazyServiceIdentifer } from 'inversify';
import { Measurement, MeasurementOptions } from './measurement';
import { Stopwatch } from './stopwatch';
import { JsonRpcServer } from '../messaging';

export const BackendStopwatch = Symbol('BackendStopwatch');

/** API path of the stopwatch service that exposes the back-end stopwatch to clients. */
export const stopwatchPath = '/services/stopwatch';

/** Token representing a remote measurement in the {@link BackendStopwatch} protocol. */
export type RemoteMeasurement = number;

/**
* A service that exposes the back-end's {@link Stopwatch} to clients
* via the remote API.
*/
export interface BackendStopwatch extends JsonRpcServer<unknown> {

/**
* Create a {@link Measurement} that will compute the time that elapsed on the back-end when logged.
*
* @param name the {@link Measurement.name measurement name}
* @param options optional configuration of the new measurement
* @returns a token identifying an unique self-timing measurement relative to the back-end's timeline
*/
start(name: string, options?: MeasurementOptions): Promise<RemoteMeasurement>;

/**
* Stop a measurement previously {@link start started} and log in the back-end a measurement of
* its duration relative to the back-end's timeline.
*
* @param measurement token identifying a measurement previously {@link start started}
* @param message a message to log
* @param messageArgs optional arguments to the `message`
*/
stop(measurement: RemoteMeasurement, message: string, messageArgs: any[]): Promise<void>;

}

/**
* Default implementation of the (remote) back-end stopwatch service.
*/
@injectable()
export class DefaultBackendStopwatch {

readonly measurements = new Map<number, Measurement>();

protected idSequence: number = 0;

constructor(@inject(new LazyServiceIdentifer(() => Stopwatch)) protected readonly stopwatch: Stopwatch) {
// Nothing else to initialize
}

start(name: string, options?: MeasurementOptions): RemoteMeasurement {
const result = ++this.idSequence;
this.measurements.set(result, this.stopwatch.start(name, options));
return result;
}

stop(measurementToken: RemoteMeasurement, message: string, messageArgs: any[]): void {
const measurement = this.measurements.get(measurementToken);
if (measurement) {
this.measurements.delete(measurementToken);
measurement.log(message, ...messageArgs);
}
}

};
Loading

0 comments on commit 05a1731

Please sign in to comment.