Add start-up timing logs in frontend and backend #10407

cdamus · 2021-11-10T20:16:34Z

What it does

Refactors various functions in a few different places in the frontend into a new abstract Stopwatch class that provides measurement of tasks and logs their completion with messages similar to what we had before. The frontend injects a concrete implementation based on the browser performance API used previously and the backend injects a concrete implementation based on the similar, but different, node.js performance API.

Additionally, as the performance of the frontend and backend applications is largely independent but also coupled at a few synchronization points, a BackendStopwatch RPC service is added that publishes limited access to the backend’s stopwatch, letting the frontend log timing messages in the timeframe of the backend application. This is used to log how long it took the frontend to fully start up from the backend’s perspective, which is especially useful in the Electron deployment but also makes sense in most Browser use cases.

Resolves #10406.

No new package dependencies are added.

Contributed on behalf of STMicroelectronics.

How to test

Start the Electron or Browser example and see the timing log messages from both the frontend and the backend emitted on the console.

Note also that the format of log messages is slightly changed, for example removing the word "took" from the took: xy.z ms part of the pattern, as it caused some new messages to read strangely and was redundant.

Review checklist

As an author, I have thoroughly tested my changes and carefully followed the review guidelines

Reminder for reviewers

As a reviewer, I agree to behave in accordance with the review guidelines

vince-fugnitto

Thank you for your contribution 👍

In order to accept your changes please be sure to sure to sign the eclipse contributor agreement (eca) with the same email as your authorship.

cdamus · 2021-11-11T14:18:33Z

Thank you for your contribution 👍

In order to accept your changes please be sure to sure to sign the eclipse contributor agreement (eca) with the same email as your authorship.

Thanks, @vince-fugnitto ! I had already signed the ECA (being a committer on other projects) but used a different e-mail address as commit author than what is registered at Eclipse. I have fixed that.

cdamus · 2022-01-11T15:01:42Z

Commit 4a34d3f rebases the branch onto a bunch of changes on the master branch and resolves merge conflicts.

msujew

The approach already looks quite good. I have a few suggestions, regarding APIs and optionality.

msujew · 2022-01-13T16:49:03Z

packages/core/src/browser/frontend-application.ts

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


Is there a special reason why this is optional? As far as I can tell, making it optional only makes stuff more complicated. If users don't want to enable this BackendStopwatch stuff, I would much rather have an injectable option object on which I can simply set a disabled flag.

I'll look for an example elsewhere in the codebase to mimic.

msujew · 2022-01-13T16:50:11Z

packages/core/src/common/performance/stopwatch.ts

+        return result;
+    }
+
+    private mergeLogOptions(logOptions?: Partial<LogOptions>): LogOptions {


Minor: We usually leave nothing as private and allow everything to be overwritten by the downstream user. Please use protected instead.

msujew · 2022-01-13T16:52:08Z

packages/core/src/common/performance/measurement-protocol.ts

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


Suggestion: We usually try to shy away from constructor injection due to the API constraints it introduces when trying to override classes. I would make this a class field.

Good point!

Actually, I had originally tried field injection, but the LazyServiceIdentifer [sic] for function-based injection to break dependency cycles doesn't work for property injection¹. It has to be used in a class constructor. And this case is a dependency cycle, so I'm not sure what else I can do. I could try @lazyInject but that requires adding a new package dependency that we haven't used to date in Theia.

Footnotes

https://github.com/inversify/InversifyJS/issues/944 ↩

And this case is a dependency cycle

I'm not sure what you mean here. DefaultBackendStopwatch depends on Stopwatch, and on the back end, Stopwatch is bound to NodeStopwatch, which does not depend on DefaultBackendStopwatch in any way, so I don't see any dependency cycle, and I was able to get this code working with simple property injection @inject(Stopwatch) protected readonly stopwatch: Stopwatch;. What circularity do you see or foresee here?

And this case is a dependency cycle

I'm not sure what you mean here. DefaultBackendStopwatch depends on Stopwatch, and on the back end, Stopwatch is bound to NodeStopwatch, which does not depend on DefaultBackendStopwatch in any way, so I don't see any dependency cycle, and I was able to get this code working with simple property injection @inject(Stopwatch) protected readonly stopwatch: Stopwatch;. What circularity do you see or foresee here?

I got an injection failure exception complaining of unsatisfied dependency when I tried that initially. I tracked it down to a dependency cycle in debugging, which is why I resorted to the lazy service identifier. Perhaps subsequent changes have broken that cycle. I'll have another look.

Confirmed. The dependency cycle that we once had here is evidently no longer. So, that's better all around.

cdamus · 2022-01-22T17:33:55Z

Thanks for the review, @msujew! I've pushed commit 28c7094 that rebases to resolve merge conflicts and addresses your comments:

the back-end stopwatch RPC service is now optional via injectable options. The only option so far is disabled. If disabled, an empty stub is supplied instead of the default implementation (on either frontend or backend or both). I tested this ad hoc with option injection on the frontend and the backend separately to confirm that the setup doesn't break and no logs actually happen
private methods are made protected in the Stopwatch class
I've added an explanatory comment to the constructor injection in the DefaultBackendStopwatch class. As I replied in-line above, constructor injection is required with the packages currently available. Better suggestions are most welcome!

colin-grant-work · 2022-01-25T20:51:38Z

packages/core/src/browser/performance/measurement-frontend-bindings.ts

+export function bindBackendStopwatch(bind: interfaces.Bind): interfaces.BindingWhenOnSyntax<unknown> {
+    return bind(BackendStopwatch).toDynamicValue(({ container }) => {
+        if (container.isBound(BackendStopwatchOptions) && container.get<BackendStopwatchOptions>(BackendStopwatchOptions).disabled) {
+            // If the back-end stopwatch service is disabled, then we don't the RPC proxy at all


Suggested change

// If the back-end stopwatch service is disabled, then we don't the RPC proxy at all

// If the back-end stopwatch service is disabled, then we don't need the RPC proxy at all

Maybe?

colin-grant-work · 2022-01-25T21:14:46Z

packages/core/src/common/performance/measurement-protocol.ts

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


It doesn't look like any of JsonRpcServer machinery is referred to by callers of the BackendStopwatch. Unless you foresee a use for calls to setClient etc., you could omit extends JsonRpcServer.

I see no use cases for exposing those APIs, so yes I would prefer to leave off the inherited interface. Didn't know I could do that!

colin-grant-work · 2022-01-25T22:09:56Z

packages/core/src/common/performance/measurement-protocol.ts

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


And this case is a dependency cycle

I'm not sure what you mean here. DefaultBackendStopwatch depends on Stopwatch, and on the back end, Stopwatch is bound to NodeStopwatch, which does not depend on DefaultBackendStopwatch in any way, so I don't see any dependency cycle, and I was able to get this code working with simple property injection @inject(Stopwatch) protected readonly stopwatch: Stopwatch;. What circularity do you see or foresee here?

colin-grant-work · 2022-01-25T22:22:15Z

packages/core/src/common/performance/measurement-protocol.ts

+@injectable()
+export class NullBackendStopwatch {
+
+    protected idSequence: number = 0;
+
+    start(): RemoteMeasurement {
+        return ++this.idSequence;
+    }
+
+    stop(): void {
+        // Nothing to stop
+    }
+
+    /**
+     * Obtain a proxy for myself that implements the asynchronous RPC API.
+     *
+     * @returns the async proxy for myself
+     */
+    asyncProxy(): BackendStopwatch {
+        return new Proxy<BackendStopwatch>(this as any, {
+            get(target: any, p: string | symbol, receiver: any): any {
+                if (p === 'start') {
+                    return () => Promise.resolve(target.start());
+                }
+                if (p === 'stop') {
+                    return () => Promise.resolve();
+                }
+            }
+        });
+
+    }
+}


Since the only purpose of this class is to satisfy the BackendStopwatch interface without doing anything, it could be as simple as

Suggested change

@injectable()

export class NullBackendStopwatch {

protected idSequence: number = 0;

start(): RemoteMeasurement {

return ++this.idSequence;

}

stop(): void {

// Nothing to stop

}

/**

* Obtain a proxy for myself that implements the asynchronous RPC API.

*

* @returns the async proxy for myself

*/

asyncProxy(): BackendStopwatch {

return new Proxy<BackendStopwatch>(this as any, {

get(target: any, p: string | symbol, receiver: any): any {

if (p === 'start') {

return () => Promise.resolve(target.start());

}

if (p === 'stop') {

return () => Promise.resolve();

}

}

});

}

}

@injectable()

export class NullBackendStopwatch implements BackendStopwatch {

start(): Promise<RemoteMeasurement> {

return Promise.resolve(0);

}

stop(): Promise<void> {

return Promise.resolve();

}

}

Assuming that the BackendStopwatch interface is simplified to exclude the RPCProxy part.

Yes, this complexity was only there to maintain the RPC protocol. Glad to drop it.

colin-grant-work · 2022-01-25T22:29:14Z

packages/core/src/common/performance/measurement.ts

+     */
+    context?: string;
+
+    /** An optional logging level at which to emit the log message. The default-default is {@link LogLevel.INFO}. */


Suggested change

/** An optional logging level at which to emit the log message. The default-default is {@link LogLevel.INFO}. */

/** An optional logging level at which to emit the log message. The default default is {@link LogLevel.INFO}. */

Or 'default value' or just 'default'.

colin-grant-work · 2022-01-25T23:10:45Z

packages/core/src/common/performance/measurement-protocol.ts

+/**
+ * Injectable options for configuration of the (remote) back-end stopwatch service.
+ */
+export interface BackendStopwatchOptions {
+    /**
+     * Wether to disable the back-end stopwatch service. When `disabled`, the service interface
+     * is still fulfilled, but it just doesn't do anything. The default `disabled` state is
+     * `false` (being enabled).
+     */
+    disabled?: boolean;
+}


I'm not sure I see the purpose of this interface. Without it, adopters who don't want a BackendStopwatch can do something like

rebind(BackendStopwatch).to(NullBackendStopwatch).inSingletonScope();

which seems at least as straightforward as

bind(BackendStopwatchOptions).toConstantValue({disabled: true});

colin-grant-work · 2022-01-25T23:19:16Z

packages/core/src/common/performance/stopwatch.ts

+            return options?.levelOverride;
+        }
+
+        return options?.defaultLogLevel || DEFAULT_LOG_LEVEL;


Suggested change

return options?.defaultLogLevel || DEFAULT_LOG_LEVEL;

return options?.defaultLogLevel ?? this.defaultOptions.defaultLogLevel ?? DEFAULT_LOG_LEVEL;

This method is likely expected to be called on options have gone through mergeOptions, but it isn't guaranteed, so it's like worth inserting the local default.

colin-grant-work · 2022-01-25T23:21:14Z

packages/core/src/common/performance/stopwatch.ts

+
+    protected logLevel(elapsed: number, options?: Partial<LogOptions>): LogLevel {
+        if (options?.levelOverride) {
+            return options?.levelOverride;


Suggested change

return options?.levelOverride;

return options.levelOverride;

colin-grant-work · 2022-01-25T23:25:35Z

packages/core/src/node/backend-application.ts

    constructor(
        @inject(ContributionProvider) @named(BackendApplicationContribution)
        protected readonly contributionsProvider: ContributionProvider<BackendApplicationContribution>,
-        @inject(BackendApplicationCliContribution) protected readonly cliParams: BackendApplicationCliContribution
+        @inject(BackendApplicationCliContribution) protected readonly cliParams: BackendApplicationCliContribution,
+        @inject(Stopwatch) protected readonly stopwatch: Stopwatch


This can be added as a property injection.

The constructor calls initialize, which needs to use the stopwatch to measure the initializations of contributions. But this happens before property injection, so constructor injection seemed to be the way to go. This then would also have to be added to the breaking API changes in the changelog.

I would have moved the initialize step to the @postConstruct configure method, but I figured there must have been a reason to call it from the constructor and so I wasn't comfortable making that change.

packages/core/src/node/performance/node-stopwatch.ts

cdamus · 2022-01-31T16:32:30Z

Thanks @colin-grant-work for the review. I think this has helped to clean things up considerably!

I've rebased to resolve merge conflict in the changelog and made changes to address your comments. I've not got a solution to the matter of changing the constructor of the BackendApplication. Suggestions what to do about that are welcome. I'm nervous about moving the this.initialize() call to the configure() method because I expect it was called by the constructor for a good reason. But as it's an async method I don't see that it could be such a problem to make that change.

Personally, I'd rather see that initialization step also happen in the post construction because it doesn't feel like an object constructor responsibility and it would mean that we can avoid the API-breaking changing to the constructor signature. WDYT?

colin-grant-work · 2022-01-31T16:36:48Z

Personally, I'd rather see that initialization step also happen in the post construction because it doesn't feel like an object constructor responsibility and it would mean that we can avoid the API-breaking changing to the constructor signature. WDYT?

I agree here - in general we want initialization to happen in decorated postConstruct methods. It's still likely worth mentioning as a breaking change, though, since extenders may have code in their own constructors that assumes that super has already run the initialize method, but if we have to break API - and we do, either way - I'd rather break it in a direction that moves us closer to our guidelines.

cdamus · 2022-01-31T17:07:29Z

I've pushed an update that moves the initialization as discussed, to maintain the existing constructor signature. Testing the example deployment shows no outward change in behaviour. In particular, initialization and configuration of contributions are still interleaved as before (the initialize method still being async). Presumably contributions that provide both methods are already expected to handle them being invoked in either order, so this should not be a change that impacts on contributions.

Because now the constructor does not trigger initialization, any derivative applications that don't get the BackendApplication from the IoC container may now find that initialize is not called and so could break. Hence the mention in the changelog.

msujew

The changes are looking really good to me now. I have a minor remark, but except for that I don't have anything to add 👍

packages/core/src/browser/frontend-application.ts

colin-grant-work · 2022-02-04T23:14:52Z

@cdamus, apologies for the delay. I'll take a look now.

colin-grant-work

Looks good to me, and it's good to have a more unified style of measurement.

colin-grant-work · 2022-02-04T23:19:57Z

packages/core/src/browser/frontend-application.ts

@@ -263,10 +273,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 => {


Since we're already adding several measurements to the start method, which is where this is called, it seems more consistent (and easier) to add the measurement there? I'm not sure how often we enter the else here - in principle, it shouldn't be often.

Indeed, this was too cute by half. Thanks for the insight about the else case!

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 <cdamus.ext@eclipsesource.com>

cdamus · 2022-02-07T22:53:46Z

@cdamus, apologies for the delay. I'll take a look now.

No apologies needed @colin-grant-work. I'm very glad to have your keen eyes on this, and as you can tell I don't have a great deal of bandwidth for this, either!

I've pushed an update that resolves the merge conflict and simplifies the frontend application start measurement per your suggestion.

vince-fugnitto reviewed Nov 10, 2021

View reviewed changes

vince-fugnitto added logging issues related to logging performance issues related to performance labels Nov 10, 2021

cdamus force-pushed the backend-perf-logs branch 2 times, most recently from 05a1731 to cb28d08 Compare November 11, 2021 14:14

JonasHelming requested a review from vince-fugnitto November 21, 2021 12:55

vince-fugnitto requested review from msujew and tsmaeder December 3, 2021 13:49

cdamus force-pushed the backend-perf-logs branch from cb28d08 to 4a34d3f Compare January 11, 2022 15:00

msujew reviewed Jan 19, 2022

View reviewed changes

cdamus force-pushed the backend-perf-logs branch from 4a34d3f to 28c7094 Compare January 22, 2022 17:26

JonasHelming requested a review from msujew January 24, 2022 11:28

colin-grant-work self-requested a review January 25, 2022 17:28

colin-grant-work reviewed Jan 25, 2022

View reviewed changes

cdamus force-pushed the backend-perf-logs branch from 28c7094 to 2270385 Compare January 31, 2022 16:26

cdamus force-pushed the backend-perf-logs branch from 2270385 to 07b3617 Compare January 31, 2022 17:02

msujew approved these changes Jan 31, 2022

View reviewed changes

packages/core/src/browser/frontend-application.ts Show resolved Hide resolved

JonasHelming requested a review from colin-grant-work February 1, 2022 08:51

JonasHelming assigned colin-grant-work Feb 1, 2022

colin-grant-work approved these changes Feb 4, 2022

View reviewed changes

cdamus force-pushed the backend-perf-logs branch from 07b3617 to 232477a Compare February 7, 2022 22:51

JonasHelming merged commit 8fe4fa2 into eclipse-theia:master Feb 10, 2022

JonasHelming added this to the 1.23.0 milestone Feb 10, 2022

vince-fugnitto mentioned this pull request Mar 2, 2022

Uninstall of extensions does not refresh the view due to logging error #10828

Closed

sdirix mentioned this pull request Nov 16, 2022

Additional back-end start-up performance logging eclipsesource/theia#22

Closed

	// If the back-end stopwatch service is disabled, then we don't the RPC proxy at all
	// If the back-end stopwatch service is disabled, then we don't need the RPC proxy at all

	/** An optional logging level at which to emit the log message. The default-default is {@link LogLevel.INFO}. */
	/** An optional logging level at which to emit the log message. The default default is {@link LogLevel.INFO}. */

	return options?.defaultLogLevel \|\| DEFAULT_LOG_LEVEL;
	return options?.defaultLogLevel ?? this.defaultOptions.defaultLogLevel ?? DEFAULT_LOG_LEVEL;

Add start-up timing logs in frontend and backend #10407

Add start-up timing logs in frontend and backend #10407

Conversation

cdamus commented Nov 10, 2021 • edited

What it does

How to test

Review checklist

Reminder for reviewers

vince-fugnitto left a comment

Choose a reason for hiding this comment

cdamus commented Nov 11, 2021

cdamus commented Jan 11, 2022

msujew left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Footnotes

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

cdamus commented Jan 22, 2022 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

colin-grant-work Jan 25, 2022 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

cdamus commented Jan 31, 2022

colin-grant-work commented Jan 31, 2022

cdamus commented Jan 31, 2022

msujew left a comment

Choose a reason for hiding this comment

colin-grant-work commented Feb 4, 2022 • edited

colin-grant-work left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

cdamus commented Feb 7, 2022

cdamus commented Nov 10, 2021 •

edited

cdamus commented Jan 22, 2022 •

edited

colin-grant-work Jan 25, 2022 •

edited

colin-grant-work commented Feb 4, 2022 •

edited