microsoft / vscode

Visual Studio Code
https://code.visualstudio.com
MIT License
164.51k stars 29.39k forks source link

Extension commands do not show any status indicator while waiting for activation #168676

Open kycutler opened 1 year ago

kycutler commented 1 year ago

Does this issue occur when all extensions are disabled?: Technically no


When an extension command is triggered, and that command activates the extension, there is no status displayed to indicate that the extension is being activated / waiting for activation to start. If there are many extensions to load, it could take a long time just to get around to activating the relevant extension.

This may leave the user wondering what is happening, and give the impression that the slowdown comes from the extension (rather than VS Code / the presence of many other extensions).

Some past issues have seen improvements in specific cases like tree views (see #59645), but other entry points (in my case, editor title / context menu items) are still impacted.

It would be good to have some sort of indicator (perhaps a notification or status bar item) to communicate to the user that extensions are still loading and the command will be executed when done.

gjsjohnmurray commented 1 year ago

Maybe I am misremembering, but I thought that we already get a status bar message while activating.

alexdima commented 1 year ago

Looking at the code, I believe this status bar message will show for any activation event that take more than 5s to activate.

jrieken commented 1 year ago

It's the other way around - we show an activation message after 150ms but for no longer than 5sec (since some extensions never resolve their activation promise or are truly slow)

@kycutler Do you have more precise steps? I am seeing the activation message being shown. Can you check "F1 > Startup Performance > ## Raw Perf Marks: localExtHost" and look for messages like will/DidLoad and willDidActivateExtension?

Screenshot 2022-12-20 at 09 52 23
kycutler commented 1 year ago

@jrieken It looks like the extension host is taking a while to start:

Raw Perf Marks: localExtHost

Name    Timestamp   Delta   Total
code/timeOrigin 1671556887222   0   0
code/fork/start 1671556896373   9151    9151
code/fork/willLoadCode  1671556896406   33  9184
code/extHost/willConnectToRenderer  1671556896577   171 9355
code/extHost/didConnectToRenderer   1671556896580   3   9358
code/extHost/didWaitForInitData 1671556896609   29  9387
code/extHost/didCreateServices  1671556896611   2   9389
code/extHost/willWaitForConfig  1671556896626   15  9404
code/extHost/didWaitForConfig   1671556896635   9   9413
code/extHost/didInitAPI 1671556896667   32  9445
code/extHost/didInitProxyResolver   1671556896671   4   9449
code/extHost/ready  1671556897763   1092    10541
...

The actual extension loading is pretty fast after that.

I can see the "Activating Extensions..." status item only briefly after that ~10s delay. It would be good if it was visible immediately after dispatching the extension command, even before the extension host is ready.

jrieken commented 1 year ago

Oh, wow. That's horribly slow. Do you have by any chance AV software that could interfere with extension host startup? Forking the process should be fast /cc @deepak1556 for similar cases

kycutler commented 1 year ago

Oh whoops, those measurements are in a debug session. It's quite a bit faster without, but still not ideal:

Raw Perf Marks: localExtHost

Name    Timestamp   Delta   Total
code/timeOrigin 1671559642346   0   0
code/fork/start 1671559642412   66  66
code/fork/willLoadCode  1671559642432   20  86
code/extHost/willConnectToRenderer  1671559642605   173 259
code/extHost/didConnectToRenderer   1671559642606   1   260
code/extHost/didWaitForInitData 1671559643332   726 986
code/extHost/didCreateServices  1671559643333   1   987
code/extHost/willWaitForConfig  1671559643349   16  1003
code/extHost/didWaitForConfig   1671559643430   81  1084
code/extHost/didInitAPI 1671559643430   0   1084
code/extHost/didInitProxyResolver   1671559643435   5   1089
code/extHost/ready  1671559644649   1214    2303
...

So there is still a ~2.5s pause where no status is shown.

jrieken commented 1 year ago

Looks like it is waiting quite some time for its init data (726ms)

alexdima commented 1 year ago

AFAICT, there are two unexpected gaps:

@kycutler Does configuring "extensions.experimental.useUtilityProcess": true make any difference in these timings? Do the timings look better when opening an empty window?

kycutler commented 1 year ago

The workspace I was testing with had a rather large file open, so I suppose the delay could be caused by that. An empty window loads much faster. I am testing using Insiders so it seems extensions.experimental.useUtilityProcess was already enabled. Disabling it didn't make much difference.

Regardless of the cause of the delay, my point is that VS Code should always show some indication to the user that something is happening and that the command they issued is being processed. There will always be a user with a large workspace open, or with AV software that slows things down, or who is running in debug mode. Even if there's nothing that can be done to speed things up, they shouldn't have to wonder if anything is happening or if things are just frozen.

deepak1556 commented 1 year ago

@alexdima currently the chrome tracing tool does not profile the utility process, so if we want to know additional details about delay at the IPC layer it needs some work in the runtime. I will address this in the January milestone, tracked at https://github.com/microsoft/vscode/issues/169704

Oh whoops, those measurements are in a debug session. It's quite a bit faster without, but still not ideal:

@kycutler I am curious about the process launch being slow in debug session, do you have a minimal debugging repro or does it happen with any extension debugging session, for ex: debugging https://github.com/microsoft/vscode-extension-samples/tree/main/helloworld-sample ?

alexdima commented 1 year ago

Regardless of the cause of the delay, my point is that VS Code should always show some indication to the user that something is happening and that the command they issued is being processed.

@jrieken Would it make sense to consider adding some indication from the command service directly? As you point out, adding something central with onWillActivate suffers from the fact that some extensions might never resolve their activation promise, but users of activateByEvent might have their own timeout or race logic with registrations which is very specific to the invocation, like the command service in this case.


The other angle here is that this is something specific to extension host startup. We could add a message in the renderer status bar if the extension host takes a long time to start up.

jrieken commented 1 year ago

Would it make sense to consider adding some indication from the command service directly?

Yeah, I like that. The original issue was actually about command- and view-based activation. We have tackled views and the current solution is the catch all but we could trade it in for a command specific activation message (its capped at 30secs) here

vscodenpa commented 1 year ago

This issue has been closed automatically because it needs more information and has not had recent activity. See also our issue reporting guidelines.

Happy Coding!

kycutler commented 1 year ago

@jrieken Does this still need info? It seems it shouldn't have been closed.