Skip to content

Commit

Permalink
Capture stopwatch results (#12812)
Browse files Browse the repository at this point in the history
Introduce `MeasurementResults` that capture a stopwatch execution in a serializable format.
Add `onMeasurementResult` event emitter to stopwatch class and introduce optional 
caching of results.
Add a metrics contribution to `@theia/metrics` that collects all measurement results of frontend and backend processes

Contributed on behalf of STMicroelectronics
  • Loading branch information
tortmayr authored Aug 28, 2023
1 parent 2d31490 commit 72bd9c9
Show file tree
Hide file tree
Showing 11 changed files with 280 additions and 16 deletions.
7 changes: 5 additions & 2 deletions packages/core/src/browser/performance/frontend-stopwatch.ts
Original file line number Diff line number Diff line change
Expand Up @@ -40,23 +40,26 @@ export class FrontendStopwatch extends Stopwatch {
performance.mark(endMarker);

let duration: number;
let startTime: 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;
duration = entries[0].duration ?? Number.NaN;
startTime = entries[0].startTime ?? Number.NaN;
} catch (e) {
console.warn(e);
duration = Number.NaN;
startTime = Number.NaN;
}

performance.clearMeasures(name);
performance.clearMarks(startMarker);
performance.clearMarks(endMarker);
return duration;
return { startTime, duration };
}, options);
}
};
26 changes: 26 additions & 0 deletions packages/core/src/common/performance/measurement.ts
Original file line number Diff line number Diff line change
Expand Up @@ -101,4 +101,30 @@ export interface MeasurementOptions {
* @see {@link thresholdLogLevel}
*/
thresholdMillis?: number;

/**
* Flag to indicate whether the stopwatch should store measurement results for later retrieval.
* For example the cache can be used to retrieve measurements which were taken during startup before a listener had a chance to register.
*/
storeResults?: boolean
}

/**
* Captures the result of a {@link Measurement} in a serializable format.
*/
export interface MeasurementResult {
/** The measurement name. This may show up in the performance measurement framework appropriate to the application context. */
name: string;

/** The time when the measurement recording has been started */
startTime: number;

/**
* The elapsed time measured, if it has been {@link stop stopped} and measured, or `NaN` if the platform disabled
* performance measurement.
*/
elapsed: number;

/** An optional label for the application the start of which (in real time) is the basis of all measurements. */
owner?: string;
}
50 changes: 38 additions & 12 deletions packages/core/src/common/performance/stopwatch.ts
Original file line number Diff line number Diff line change
Expand Up @@ -19,7 +19,8 @@
import { inject, injectable } from 'inversify';
import { ILogger, LogLevel } from '../logger';
import { MaybePromise } from '../types';
import { Measurement, MeasurementOptions } from './measurement';
import { Measurement, MeasurementOptions, MeasurementResult } from './measurement';
import { Emitter, Event } from '../event';

/** The default log level for measurements that are not otherwise configured with a default. */
const DEFAULT_LOG_LEVEL = LogLevel.INFO;
Expand Down Expand Up @@ -50,10 +51,20 @@ export abstract class Stopwatch {
@inject(ILogger)
protected readonly logger: ILogger;

protected _storedMeasurements: MeasurementResult[] = [];

protected onDidAddMeasurementResultEmitter = new Emitter<MeasurementResult>();
get onDidAddMeasurementResult(): Event<MeasurementResult> {
return this.onDidAddMeasurementResultEmitter.event;
}

constructor(protected readonly defaultLogOptions: LogOptions) {
if (!defaultLogOptions.defaultLogLevel) {
defaultLogOptions.defaultLogLevel = DEFAULT_LOG_LEVEL;
}
if (defaultLogOptions.storeResults === undefined) {
defaultLogOptions.storeResults = true;
}
}

/**
Expand Down Expand Up @@ -91,25 +102,36 @@ export abstract class Stopwatch {
return result;
}

protected createMeasurement(name: string, measurement: () => number, options?: MeasurementOptions): Measurement {
protected createMeasurement(name: string, measure: () => { startTime: number, duration: number }, options?: MeasurementOptions): Measurement {
const logOptions = this.mergeLogOptions(options);

const result: Measurement = {
const measurement: Measurement = {
name,
stop: () => {
if (result.elapsed === undefined) {
result.elapsed = measurement();
if (measurement.elapsed === undefined) {
const { startTime, duration } = measure();
measurement.elapsed = duration;
const result: MeasurementResult = {
name,
elapsed: duration,
startTime,
owner: logOptions.owner
};
if (logOptions.storeResults) {
this._storedMeasurements.push(result);
}
this.onDidAddMeasurementResultEmitter.fire(result);
}
return result.elapsed;
return measurement.elapsed;
},
log: (activity: string, ...optionalArgs: any[]) => this.log(result, activity, this.atLevel(logOptions, undefined, optionalArgs)),
debug: (activity: string, ...optionalArgs: any[]) => this.log(result, activity, this.atLevel(logOptions, LogLevel.DEBUG, optionalArgs)),
info: (activity: string, ...optionalArgs: any[]) => this.log(result, activity, this.atLevel(logOptions, LogLevel.INFO, optionalArgs)),
warn: (activity: string, ...optionalArgs: any[]) => this.log(result, activity, this.atLevel(logOptions, LogLevel.WARN, optionalArgs)),
error: (activity: string, ...optionalArgs: any[]) => this.log(result, activity, this.atLevel(logOptions, LogLevel.ERROR, optionalArgs)),
log: (activity: string, ...optionalArgs: any[]) => this.log(measurement, activity, this.atLevel(logOptions, undefined, optionalArgs)),
debug: (activity: string, ...optionalArgs: any[]) => this.log(measurement, activity, this.atLevel(logOptions, LogLevel.DEBUG, optionalArgs)),
info: (activity: string, ...optionalArgs: any[]) => this.log(measurement, activity, this.atLevel(logOptions, LogLevel.INFO, optionalArgs)),
warn: (activity: string, ...optionalArgs: any[]) => this.log(measurement, activity, this.atLevel(logOptions, LogLevel.WARN, optionalArgs)),
error: (activity: string, ...optionalArgs: any[]) => this.log(measurement, activity, this.atLevel(logOptions, LogLevel.ERROR, optionalArgs)),
};

return result;
return measurement;
}

protected mergeLogOptions(logOptions?: Partial<LogOptions>): LogOptions {
Expand Down Expand Up @@ -154,4 +176,8 @@ export abstract class Stopwatch {
this.logger.log(level, `${whatWasMeasured}: ${elapsed.toFixed(1)} ms [${timeFromStart}]`, ...(options.arguments ?? []));
}

get storedMeasurements(): ReadonlyArray<MeasurementResult> {
return this._storedMeasurements;
}

}
2 changes: 1 addition & 1 deletion packages/core/src/node/performance/node-stopwatch.ts
Original file line number Diff line number Diff line change
Expand Up @@ -33,7 +33,7 @@ export class NodeStopwatch extends Stopwatch {

return this.createMeasurement(name, () => {
const duration = performance.now() - startTime;
return duration;
return { duration, startTime };
}, options);
}

Expand Down
1 change: 1 addition & 0 deletions packages/metrics/package.json
Original file line number Diff line number Diff line change
Expand Up @@ -11,6 +11,7 @@
},
"theiaExtensions": [
{
"frontend": "lib/browser/metrics-frontend-module",
"backend": "lib/node/metrics-backend-module"
}
],
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,51 @@
// *****************************************************************************
// Copyright (C) 2023 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-only WITH Classpath-exception-2.0
// *****************************************************************************
import { inject, injectable } from '@theia/core/shared/inversify';
import { FrontendApplicationContribution } from '@theia/core/lib/browser';
import { ILogger, LogLevel, MeasurementResult, Stopwatch } from '@theia/core';
import { UUID } from '@theia/core/shared/@phosphor/coreutils';
import { MeasurementNotificationService } from '../common';

@injectable()
export class MetricsFrontendApplicationContribution implements FrontendApplicationContribution {
@inject(Stopwatch)
protected stopwatch: Stopwatch;

@inject(MeasurementNotificationService)
protected notificationService: MeasurementNotificationService;

@inject(ILogger)
protected logger: ILogger;

readonly id = UUID.uuid4();

initialize(): void {
this.doInitialize();
}

protected async doInitialize(): Promise<void> {
const logLevel = await this.logger.getLogLevel();
if (logLevel !== LogLevel.DEBUG) {
return;
}
this.stopwatch.storedMeasurements.forEach(result => this.notify(result));
this.stopwatch.onDidAddMeasurementResult(result => this.notify(result));
}

protected notify(result: MeasurementResult): void {
this.notificationService.onFrontendMeasurement(this.id, result);
}
}
28 changes: 28 additions & 0 deletions packages/metrics/src/browser/metrics-frontend-module.ts
Original file line number Diff line number Diff line change
@@ -0,0 +1,28 @@
// *****************************************************************************
// Copyright (C) 2023 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-only WITH Classpath-exception-2.0
// *****************************************************************************

import { ContainerModule } from '@theia/core/shared/inversify';
import { MetricsFrontendApplicationContribution } from './metrics-frontend-application-contribution';
import { MeasurementNotificationService, measurementNotificationServicePath } from '../common';
import { FrontendApplicationContribution, WebSocketConnectionProvider } from '@theia/core/lib/browser';

export default new ContainerModule(bind => {
bind(FrontendApplicationContribution).to(MetricsFrontendApplicationContribution).inSingletonScope();
bind(MeasurementNotificationService).toDynamicValue(ctx => {
const connection = ctx.container.get(WebSocketConnectionProvider);
return connection.createProxy<MeasurementNotificationService>(measurementNotificationServicePath);
});
});
17 changes: 17 additions & 0 deletions packages/metrics/src/common/index.ts
Original file line number Diff line number Diff line change
@@ -0,0 +1,17 @@
// *****************************************************************************
// Copyright (C) 2023 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-only WITH Classpath-exception-2.0
// *****************************************************************************

export * from './measurement-notification-service';
29 changes: 29 additions & 0 deletions packages/metrics/src/common/measurement-notification-service.ts
Original file line number Diff line number Diff line change
@@ -0,0 +1,29 @@
// *****************************************************************************
// Copyright (C) 2023 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-only WITH Classpath-exception-2.0
// *****************************************************************************

import { MeasurementResult } from '@theia/core';

export const measurementNotificationServicePath = '/services/measurement-notification';

export const MeasurementNotificationService = Symbol('MeasurementNotificationService');
export interface MeasurementNotificationService {
/**
* Notify the backend when a fronted stopwatch provides a new measurement.
* @param frontendId The unique id associated with the frontend that sends the notification
* @param result The new measurement result
*/
onFrontendMeasurement(frontendId: string, result: MeasurementResult): void;
}
75 changes: 75 additions & 0 deletions packages/metrics/src/node/measurement-metrics-contribution.ts
Original file line number Diff line number Diff line change
@@ -0,0 +1,75 @@
// *****************************************************************************
// Copyright (C) 2023 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-only WITH Classpath-exception-2.0
// *****************************************************************************
import { inject, injectable, } from '@theia/core/shared/inversify';
import { MetricsContribution } from './metrics-contribution';
import { LogLevel, MeasurementResult, Stopwatch } from '@theia/core';
import { MeasurementNotificationService } from '../common';
import { LogLevelCliContribution } from '@theia/core/lib/node/logger-cli-contribution';

const backendId = 'backend';
const metricsName = 'theia_measurements';

@injectable()
export class MeasurementMetricsBackendContribution implements MetricsContribution, MeasurementNotificationService {
@inject(Stopwatch)
protected backendStopwatch: Stopwatch;

@inject(LogLevelCliContribution)
protected logLevelCli: LogLevelCliContribution;

protected metrics = '';
protected frontendCounters = new Map<string, string>();

startCollecting(): void {
if (this.logLevelCli.defaultLogLevel !== LogLevel.DEBUG) {
return;
}
this.metrics += `# HELP ${metricsName} Theia stopwatch measurement results.\n`;
this.metrics += `# TYPE ${metricsName} gauge\n`;
this.backendStopwatch.storedMeasurements.forEach(result => this.onBackendMeasurement(result));
this.backendStopwatch.onDidAddMeasurementResult(result => this.onBackendMeasurement(result));
}

getMetrics(): string {
return this.metrics;
}

protected appendMetricsValue(id: string, result: MeasurementResult): void {
const { name, elapsed, startTime, owner } = result;
const labels: string = `id="${id}", name="${name}", startTime="${startTime}", owner="${owner}"`;
const metricsValue = `${metricsName}{${labels}} ${elapsed}`;
this.metrics += (metricsValue + '\n');
}

protected onBackendMeasurement(result: MeasurementResult): void {
this.appendMetricsValue(backendId, result);
}

protected createFrontendCounterId(frontendId: string): string {
const counterId = `frontend-${this.frontendCounters.size + 1}`;
this.frontendCounters.set(frontendId, counterId);
return counterId;
}

protected toCounterId(frontendId: string): string {
return this.frontendCounters.get(frontendId) ?? this.createFrontendCounterId(frontendId);
}

onFrontendMeasurement(frontendId: string, result: MeasurementResult): void {
this.appendMetricsValue(this.toCounterId(frontendId), result);
}

}
10 changes: 9 additions & 1 deletion packages/metrics/src/node/metrics-backend-module.ts
Original file line number Diff line number Diff line change
Expand Up @@ -16,17 +16,25 @@

import { ContainerModule } from '@theia/core/shared/inversify';
import { BackendApplicationContribution } from '@theia/core/lib/node';
import { bindContributionProvider } from '@theia/core/lib/common';
import { ConnectionHandler, RpcConnectionHandler, bindContributionProvider } from '@theia/core/lib/common';
import { MetricsContribution } from './metrics-contribution';
import { NodeMetricsContribution } from './node-metrics-contribution';
import { ExtensionMetricsContribution } from './extensions-metrics-contribution';
import { MetricsBackendApplicationContribution } from './metrics-backend-application-contribution';
import { measurementNotificationServicePath } from '../common';
import { MeasurementMetricsBackendContribution } from './measurement-metrics-contribution';

export default new ContainerModule(bind => {
bindContributionProvider(bind, MetricsContribution);
bind(MetricsContribution).to(NodeMetricsContribution).inSingletonScope();
bind(MetricsContribution).to(ExtensionMetricsContribution).inSingletonScope();

bind(MeasurementMetricsBackendContribution).toSelf().inSingletonScope();
bind(MetricsContribution).toService(MeasurementMetricsBackendContribution);
bind(ConnectionHandler).toDynamicValue(ctx =>
new RpcConnectionHandler(measurementNotificationServicePath,
() => ctx.container.get(MeasurementMetricsBackendContribution)));

bind(BackendApplicationContribution).to(MetricsBackendApplicationContribution).inSingletonScope();

});

0 comments on commit 72bd9c9

Please sign in to comment.