Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Capture stopwatch results #12812

Merged

Conversation

tortmayr
Copy link
Contributor

@tortmayr tortmayr commented Aug 8, 2023

What it does

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 (when running with debug log level).

The new metrics can be picked up by the performance measurement step of the e2e framework.

Contributed on behalf of STMicroelectronics

How to test

Start the example Theia application in browser in debug mode (yarn browser start:debug). Go to localhost:3000/metrics. The stopwatch results for the backend and frontend should be part of the dataset.
Reload the theia application, then reload localhost:3000/metrics. It should now contain an additional dataset for the second frontend instance.

Review checklist

Reminder for reviewers

@vince-fugnitto vince-fugnitto added the metrics issues related to metrics and logging label Aug 18, 2023
* Flag to indicate whether the stopwatch should cache 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.
*/
cacheResults?: boolean
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In IT, the word "cache" usually refers to a short-term, incomplete set of items, often size-limited, where some items may be replaced according to some algorithm. I suspect this is not what's happening here. If we want to store a full trace of results, we should call this field storeResults and rename related variables accordingly.

@@ -50,10 +51,20 @@ export abstract class Stopwatch {
@inject(ILogger)
protected readonly logger: ILogger;

protected cachedResults: MeasurementResult[] = [];
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

storedMeasurements

@@ -50,10 +51,20 @@ export abstract class Stopwatch {
@inject(ILogger)
protected readonly logger: ILogger;

protected cachedResults: MeasurementResult[] = [];

protected onMeasurementResultEmitter = new Emitter<MeasurementResult>();
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

According to our guidelines, the name of this event should be onDidAddMeasurementResult.

@@ -91,14 +102,17 @@ export abstract class Stopwatch {
return result;
}

protected createMeasurement(name: string, measurement: () => number, options?: MeasurementOptions): Measurement {
protected createMeasurement(name: string, measurement: () => { startTime: number, duration: number }, options?: MeasurementOptions): Measurement {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I would prefer measure as a name, since it's a function.

@@ -112,6 +126,19 @@ export abstract class Stopwatch {
return result;
}

protected handleCompletedMeasurement(name: string, startTime: number, elapsed: number, options: LogOptions): void {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why not keep this method private or inline it? I don't see the point of overriding it in a subclass. It just adds gratuitous API surface.

@@ -154,4 +181,8 @@ export abstract class Stopwatch {
this.logger.log(level, `${whatWasMeasured}: ${elapsed.toFixed(1)} ms [${timeFromStart}]`, ...(options.arguments ?? []));
}

getCachedResults(): MeasurementResult[] {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why not use a property accessor returning a readonly array? It prevent unnecessary copying.

// SPDX-License-Identifier: EPL-2.0 OR GPL-2.0-only WITH Classpath-exception-2.0
// *****************************************************************************

export * from './metrics-frontend-application-contribution';
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Isn't the point of the contribution to be used in the module? Why does it need to be exported from index.ts?

protected logLevelCli: LogLevelCliContribution;

protected metrics = '';
protected frontendCounter = new Map<string, string>();
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

frontendCounters

@tsmaeder
Copy link
Contributor

Here's the text form localhost:3000/metrics after starting a front end:

# HELP process_cpu_user_seconds_total Total user CPU time spent in seconds. # TYPE process_cpu_user_seconds_total counter process_cpu_user_seconds_total 0.516 1693146828441 # HELP process_cpu_system_seconds_total Total system CPU time spent in seconds. # TYPE process_cpu_system_seconds_total counter process_cpu_system_seconds_total 0.078 1693146828441 # HELP process_cpu_seconds_total Total user and system CPU time spent in seconds. # TYPE process_cpu_seconds_total counter process_cpu_seconds_total 0.594 1693146828441 # HELP process_start_time_seconds Start time of the process since unix epoch in seconds. # TYPE process_start_time_seconds gauge process_start_time_seconds 1693146482 # HELP process_resident_memory_bytes Resident memory size in bytes. # TYPE process_resident_memory_bytes gauge process_resident_memory_bytes 85241856 1693146828441 # HELP nodejs_eventloop_lag_seconds Lag of event loop in seconds. # TYPE nodejs_eventloop_lag_seconds gauge nodejs_eventloop_lag_seconds 0.0001915 1693146828441 # HELP nodejs_active_handles_total Number of active handles. # TYPE nodejs_active_handles_total gauge nodejs_active_handles_total 23 1693146828441 # HELP nodejs_active_requests_total Number of active requests. # TYPE nodejs_active_requests_total gauge nodejs_active_requests_total 0 1693146828441 # HELP nodejs_heap_size_total_bytes Process heap size from node.js in bytes. # TYPE nodejs_heap_size_total_bytes gauge nodejs_heap_size_total_bytes 49008640 1693146828441 # HELP nodejs_heap_size_used_bytes Process heap size used from node.js in bytes. # TYPE nodejs_heap_size_used_bytes gauge nodejs_heap_size_used_bytes 46841368 1693146828441 # HELP nodejs_external_memory_bytes Nodejs external memory size in bytes. # TYPE nodejs_external_memory_bytes gauge nodejs_external_memory_bytes 19389753 1693146828441 # HELP nodejs_heap_space_size_total_bytes Process heap space size total from node.js in bytes. # TYPE nodejs_heap_space_size_total_bytes gauge nodejs_heap_space_size_total_bytes{space="read_only"} 176128 1693146828441 nodejs_heap_space_size_total_bytes{space="old"} 24633344 1693146828441 nodejs_heap_space_size_total_bytes{space="code"} 2203648 1693146828441 nodejs_heap_space_size_total_bytes{space="map"} 2105344 1693146828441 nodejs_heap_space_size_total_bytes{space="large_object"} 18841600 1693146828441 nodejs_heap_space_size_total_bytes{space="code_large_object"} 0 1693146828441 nodejs_heap_space_size_total_bytes{space="new_large_object"} 0 1693146828441 nodejs_heap_space_size_total_bytes{space="new"} 1048576 1693146828441 # HELP nodejs_heap_space_size_used_bytes Process heap space size used from node.js in bytes. # TYPE nodejs_heap_space_size_used_bytes gauge nodejs_heap_space_size_used_bytes{space="read_only"} 170944 1693146828441 nodejs_heap_space_size_used_bytes{space="old"} 23872880 1693146828441 nodejs_heap_space_size_used_bytes{space="code"} 2030624 1693146828441 nodejs_heap_space_size_used_bytes{space="map"} 1304784 1693146828441 nodejs_heap_space_size_used_bytes{space="large_object"} 18754816 1693146828441 nodejs_heap_space_size_used_bytes{space="code_large_object"} 0 1693146828441 nodejs_heap_space_size_used_bytes{space="new_large_object"} 0 1693146828441 nodejs_heap_space_size_used_bytes{space="new"} 710912 1693146828441 # HELP nodejs_heap_space_size_available_bytes Process heap space size available from node.js in bytes. # TYPE nodejs_heap_space_size_available_bytes gauge nodejs_heap_space_size_available_bytes{space="read_only"} 0 1693146828441 nodejs_heap_space_size_available_bytes{space="old"} 293408 1693146828441 nodejs_heap_space_size_available_bytes{space="code"} 25568 1693146828441 nodejs_heap_space_size_available_bytes{space="map"} 761144 1693146828441 nodejs_heap_space_size_available_bytes{space="large_object"} 0 1693146828441 nodejs_heap_space_size_available_bytes{space="code_large_object"} 0 1693146828441 nodejs_heap_space_size_available_bytes{space="new_large_object"} 1031072 1693146828441 nodejs_heap_space_size_available_bytes{space="new"} 320160 1693146828441 # HELP nodejs_version_info Node.js version info. # TYPE nodejs_version_info gauge nodejs_version_info{version="v16.17.0",major="16",minor="17",patch="0"} 1 # HELP theia_extension_version Theia extension version info. # TYPE theia_extension_version gauge theia_extension_version{extension="theia_electron",version="1.40.0"} 1 theia_extension_version{extension="theia_core",version="1.40.0"} 1 theia_extension_version{extension="theia_variable_resolver",version="1.40.0"} 1 theia_extension_version{extension="theia_editor",version="1.40.0"} 1 theia_extension_version{extension="theia_filesystem",version="1.40.0"} 1 theia_extension_version{extension="theia_process",version="1.40.0"} 1 theia_extension_version{extension="theia_workspace",version="1.40.0"} 1 theia_extension_version{extension="theia_file_search",version="1.40.0"} 1 theia_extension_version{extension="theia_markers",version="1.40.0"} 1 theia_extension_version{extension="theia_outline_view",version="1.40.0"} 1 theia_extension_version{extension="theia_monaco",version="1.40.0"} 1 theia_extension_version{extension="theia_output",version="1.40.0"} 1 theia_extension_version{extension="theia_navigator",version="1.40.0"} 1 theia_extension_version{extension="theia_search_in_workspace",version="1.40.0"} 1 theia_extension_version{extension="theia_userstorage",version="1.40.0"} 1 theia_extension_version{extension="theia_toolbar",version="1.40.0"} 1 theia_extension_version{extension="theia_bulk_edit",version="1.40.0"} 1 theia_extension_version{extension="theia_callhierarchy",version="1.40.0"} 1 theia_extension_version{extension="theia_console",version="1.40.0"} 1 theia_extension_version{extension="theia_terminal",version="1.40.0"} 1 theia_extension_version{extension="theia_task",version="1.40.0"} 1 theia_extension_version{extension="theia_debug",version="1.40.0"} 1 theia_extension_version{extension="theia_editor_preview",version="1.40.0"} 1 theia_extension_version{extension="theia_messages",version="1.40.0"} 1 theia_extension_version{extension="theia_preferences",version="1.40.0"} 1 theia_extension_version{extension="theia_scm",version="1.40.0"} 1 theia_extension_version{extension="theia_timeline",version="1.40.0"} 1 theia_extension_version{extension="theia_typehierarchy",version="1.40.0"} 1 theia_extension_version{extension="theia_plugin_ext",version="1.40.0"} 1 theia_extension_version{extension="theia_plugin_ext_vscode",version="1.40.0"} 1 theia_extension_version{extension="theia_vsx_registry",version="1.40.0"} 1 theia_extension_version{extension="theia_api_samples",version="1.40.0"} 1 theia_extension_version{extension="theia_keymaps",version="1.40.0"} 1 theia_extension_version{extension="theia_getting_started",version="1.40.0"} 1 theia_extension_version{extension="theia_scm_extra",version="1.40.0"} 1 theia_extension_version{extension="theia_git",version="1.40.0"} 1 theia_extension_version{extension="theia_memory_inspector",version="1.40.0"} 1 theia_extension_version{extension="theia_metrics",version="1.40.0"} 1 theia_extension_version{extension="theia_mini_browser",version="1.40.0"} 1 theia_extension_version{extension="theia_plugin_dev",version="1.40.0"} 1 theia_extension_version{extension="theia_plugin_metrics",version="1.40.0"} 1 theia_extension_version{extension="theia_preview",version="1.40.0"} 1 theia_extension_version{extension="theia_property_view",version="1.40.0"} 1 

Beyond the confusing format, I'm not seeing any outputs the look stopwatch-related.

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
@tortmayr
Copy link
Contributor Author

Thanks for the review @tsmaeder. I have rebased the PR and addresses your comments.

Beyond the confusing format, I'm not seeing any outputs the look stopwatch-related.

The test instructions were incomplete, my bad. Currently the measurement metrics is only active if the application is started in debug mode (yarn start browser:debug), I have updated the instructions accordingly.

Copy link
Contributor

@tsmaeder tsmaeder left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for addressing the comments, I can see the metrics now.

@tsmaeder
Copy link
Contributor

I'm approving based on the assumption that the /metrics endpoint is not to be consumed by humans. If it is for humans, we need to fix the formatting.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
metrics issues related to metrics and logging
Projects
Archived in project
Development

Successfully merging this pull request may close these issues.

3 participants