Skip to content

Commit

Permalink
Add start-up timing logs in frontend and backend (#10407)
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 authored Feb 10, 2022
1 parent a552c06 commit 8fe4fa2
Show file tree
Hide file tree
Showing 19 changed files with 682 additions and 105 deletions.
4 changes: 4 additions & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -4,10 +4,14 @@

[1.23.0 Milestone](https://github.com/eclipse-theia/theia/milestone/31)

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

<a name="breaking_changes_1.23.0">[Breaking Changes:](#breaking_changes_1.23.0)</a>

- [plugin] Deprecated `PseudoTerminalOptions`. `ExternalTerminalOptions` should be used from now on instead. [#10683](https://github.com/eclipse-theia/theia/pull/10683) - Contributed on behalf of STMicroelectronics
- [core] Removed method `attachGlobalShortcuts` from `ElectronMainApplication`. Attaching shortcuts in that way interfered with internal shortcuts. Use internal keybindings instead of global shortcuts. [#10704](https://github.com/eclipse-theia/theia/pull/10704)
- [plugin-ext] function `logMeasurement` of `PluginDeployerImpl` class and browser class `HostedPluginSupport` is replaced by `measure` using the new `Stopwatch` API [#10407](https://github.com/eclipse-theia/theia/pull/10407)
- [plugin-ext] the constructor of `BackendApplication` class no longer invokes the `initialize` method. Instead, the `@postConstruct configure` method now starts by calling `initialize` [#10407](https://github.com/eclipse-theia/theia/pull/10407)

## v1.22.0 - 1/27/2022

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 @@ -390,4 +391,7 @@ export const frontendApplicationModule = new ContainerModule((bind, unbind, isBo
child.bind(Coordinate).toConstantValue(position);
return child.get(BreadcrumbPopupContainer);
});

bindFrontendStopwatch(bind);
bindBackendStopwatch(bind);
});
39 changes: 17 additions & 22 deletions packages/core/src/browser/frontend-application.ts
Original file line number Diff line number Diff line change
Expand Up @@ -15,7 +15,7 @@
********************************************************************************/

import { inject, injectable, named } from 'inversify';
import { ContributionProvider, CommandRegistry, MenuModelRegistry, isOSX } from '../common';
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 @@ -127,6 +127,12 @@ export class FrontendApplication {
@inject(TooltipService)
protected readonly tooltipService: TooltipService;

@inject(Stopwatch)
protected readonly stopwatch: Stopwatch;

@inject(BackendStopwatch)
protected readonly backendStopwatch: BackendStopwatch;

constructor(
@inject(CommandRegistry) protected readonly commands: CommandRegistry,
@inject(MenuModelRegistry) protected readonly menus: MenuModelRegistry,
Expand All @@ -152,7 +158,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 @@ -161,13 +169,15 @@ 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);
await this.measure('revealShell', () => this.revealShell(host), 'Replace loading indicator with ready workbench UI (animation)', false);
this.registerEventListeners();
this.stateService.state = 'ready';

startup.then(idToken => this.backendStopwatch.stop(idToken, 'Frontend application start', []));
}

/**
Expand Down Expand Up @@ -266,7 +276,6 @@ export class FrontendApplication {
return new Promise(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 Down Expand Up @@ -408,23 +417,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(({ container }) => {
const connection = 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 @@ -40,6 +40,7 @@ export * from './lsp-types';
export * from './contribution-filter';
export * from './nls';
export * from './numbers';
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';
104 changes: 104 additions & 0 deletions packages/core/src/common/performance/measurement-protocol.ts
Original file line number Diff line number Diff line change
@@ -0,0 +1,104 @@
/********************************************************************************
* 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 } from 'inversify';
import { Measurement, MeasurementOptions } from './measurement';
import { Stopwatch } from './stopwatch';

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;

export const BackendStopwatchOptions = Symbol('BackendStopwatchOptions');

/**
* A service that exposes the back-end's {@link Stopwatch} to clients
* via the remote API. If you do not need this service then bind or re-bind
* the {@link NullBackendStopwatch} implementation to this service interface.
*/
export interface BackendStopwatch {

/**
* 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;

@inject(Stopwatch)
protected readonly stopwatch: Stopwatch;

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);
}
}

}

/**
* No-op implementation of the (remote) back-end stopwatch service.
*/
@injectable()
export class NullBackendStopwatch implements BackendStopwatch {

start(): Promise<RemoteMeasurement> {
return Promise.resolve(0);
}

stop(): Promise<void> {
return Promise.resolve();
}

}
Loading

0 comments on commit 8fe4fa2

Please sign in to comment.