Very long startup activation time

[divslinger]

Prettier takes 3+ minutes to start, prettier is the only activated extension:

System Info:

Version:          Code 1.41.0 (9579eda04fdb3a9bba2750f15193e5fafe16b959, 2019-12-11T18:37:42.077Z)
OS Version:       Windows_NT x64 10.0.17134
CPUs:             Intel(R) Core(TM) i7-6820HQ CPU @ 2.70GHz (8 x 2712)
Memory (System):  31.85GB (18.75GB free)
VM:               0%
Screen Reader:    no
Process Argv:
GPU Status:       2d_canvas:                     enabled
                  flash_3d:                      enabled
                  flash_stage3d:                 enabled
                  flash_stage3d_baseline:        enabled
                  gpu_compositing:               enabled
                  metal:                         disabled_off
                  multiple_raster_threads:       enabled_on
                  oop_rasterization:             disabled_off
                  protected_video_decode:        unavailable_off
                  rasterization:                 enabled
                  skia_renderer:                 disabled_off
                  surface_control:               disabled_off
                  surface_synchronization:       enabled_on
                  video_decode:                  enabled
                  viz_display_compositor:        enabled_on
                  viz_hit_test_surface_layer:    disabled_off
                  webgl:                         enabled
                  webgl2:                        enabled

CPU %   Mem MB     PID  Process
    0       99   20940  code main
    0      114    5716     shared-process
    0       15   17052     electron-crash-reporter
    0      232   17616     gpu-process
    0       24   20620     utility
    0      168   22460     window (Running Extensions - coremedia-i-net - Visual Studio Code)
    0        8     108       winpty-process
    0        7   15528         C:\Users\[REDACTED]\AppData\Local\Programs\Git\bin\bash.exe
    0       13    4752           "C:\Users\[REDACTED]\AppData\Local\Programs\Git\bin\..\usr\bin\bash.exe"
    0       10   21564         console-window-host (Windows internal process)
    0       69   20760       extensionHost
    0       32   17804         "C:\Users\[REDACTED]\AppData\Local\Programs\Microsoft VS Code\Code.exe" "c:\Users\[REDACTED]\AppData\Local\Programs\Microsoft VS Code\resources\app\extensions\css-language-features\server\dist\cssServerMain" --node-ipc --clientProcessId=20760
    0       13   22468       watcherService
    0        7    5744         console-window-host (Windows internal process)

Workspace Stats:
|  Window (Running Extensions - [REDACTED] - Visual Studio Code)
|    Folder ([REDACTED]): more than 34899 files
|      File types: js(3510) jar(1567) xml(1538) png(1456) scss(1065) rb(588)
|                  json(506) gif(483) md(403) css(233)
|      Conf files: package.json(190) webpack.config.js(3) project.json(3)
|                  tasks.json(1)

[divslinger]

This causes all sorts of problems. Most prominently, git will only be available after prettier has finished. I think this bugreport is related: https://github.com/microsoft/vscode/issues/87102

[ntotten]

Interesting, I haven't seen that before and our telemetry does not seem to indicate that this is common.

Can you tell me, are you opening a workspace with lots of different projects. One thing the extension does have to do is activate for every workspace. It's possible that could be the issue.

I have been considering moving the activation to be out of band as we don't technically need to activate anything until you open a file in a workspace, but that will be a fairly large refactor.

If possible, could you provide a sample github repo that reproduces the issue? I will hop on my windows computer and try to verify.

[divslinger]

If I start VS Code without a folder (new window) it activates normally. If I start it with any folder opened it takes forever (always close to 192s). The folder can be empty, git initialized or contain 40 workspaces, it's always around 192s.

I have tested it with a brand new vs code (insiders) installation, still the same.

I am in a corporate environment with multiple slow network drives attached (the working directory and vscode are on my internal drives, though). I'll try to gather some more data, so I can narrow it down.

[divslinger]

My Startup Performance output looks like this:

Extension Activation Stats

| Extension                         | Eager | Load Code | Call Activate | Finish Activate | Event               | By                                |
| --------------------------------- | ----- | --------- | ------------- | --------------- | ------------------- | --------------------------------- |
| vscode.debug-auto-launch          | true  | 9         | 1             | 192248          | *                   | vscode.debug-auto-launch          |
| vscode.emmet                      | true  | 46        | 2             | 192246          | *                   | vscode.emmet                      |
| vscode.git                        | true  | 116       | 26            | 193821          | *                   | vscode.git                        |
| vscode.merge-conflict             | true  | 20        | 1             | 192228          | *                   | vscode.merge-conflict             |
| vscode.search-result              | true  | 4         | 1             | 192227          | *                   | vscode.search-result              |
| esbenp.prettier-vscode            | true  | 223       | 192218        | 9               | *                   | esbenp.prettier-vscode            |
| vscode.extension-editing          | false | 176       | 1             | 7               | onLanguage:markdown | vscode.extension-editing          |
| vscode.markdown-language-features | false | 322       | 7             | 0               | onLanguage:markdown | vscode.markdown-language-features |

[AriPerkkio]

@divslinger I'm having the exact same issues. It all started this week. My environment sounds about the same as yours. I've tried multiple git repos.

When I disconnect from the network, prettier extension seems to start up extremely fast.

E: That 192s seems weirdly accurate. I just timed the start up and got 195s. Is this used as timeout value somewhere?

[divslinger]

When I disconnect from the network, prettier extension seems to start up extremely fast.

Can confirm. Disconnecting from the network fixes it.

[divslinger]

Downgrading VS Code to 1.40.2 doesn't solve the issue.

[ntotten]

Interesting. It seems there are some VS Code issues that may be related (see: https://github.com/microsoft/vscode/issues/86772). I can't think of anything that would have changed on the extension side that would have caused this.

I'll do some digging though and see what i can find.

[KenanHArik]

I'm also getting a similar issue. I initially thought it was associated with the latest push of VScode version, but through disabling extensions found this tread and Prettier taking a long time to load. Commenting here to get latched to this thread.

[ntotten]

Has anyone tried to install an older version of the prettier extension? I'd be curious to understand if this was actually something introduced recently. I don't see any changes that seem related, but you never know. If possible try installing older versions to see if any of them make the problem go away and let me know which fixes it. I wasn't able to repro on my windows laptop so any additional info would be helpful.

[AriPerkkio]

I tested older versions of prettier extension. No changes there. I don't think this is an issue on prettier extension itself.

I spotted a new error message from VS Codes ESLint plugin. I think it also appeared on prettier's logs at one point. Immediately after this error shows up, prettier and eslint start working.

[Info  - 8.31.40] ESLint server stopped.
[Info  - 8.31.41] ESLint server running in node v12.4.0
[Info  - 8.31.41] ESLint server is running.
Uncaught exception received.
Error: spawn C:\Users\xx\AppData\Local\Programs\Microsoft VS Code\Code.exe ENOENT
    at Process.ChildProcess._handle.onexit (internal/child_process.js:264:19)
    at onErrorNT (internal/child_process.js:456:16)
    at processTicksAndRejections (internal/process/task_queues.js:84:9)
[Info  - 8.34.52] ESLint library loaded from: C:\Users\xx\<path-to-project-root>\node_modules\eslint\lib\api.js

That path to Code.exe is correct. Time between those last two timestamps seems the be the same ~190s.

[AriPerkkio]

Found a solution/work-around. Set environment variable on windows: NO_UPDATE_NOTIFIER with value true

Prettier extension loads up in 5-10s now.

Related issues where fix was found: https://npm.community/t/npm-version-takes-3-minutes-to-complete-when-run-in-child-process-and-behind-corporate-proxy/1658 https://github.com/nodejs/node/issues/21632#issuecomment-416140065

[divslinger]

Set environment variable on windows: NO_UPDATE_NOTIFIER with value true

Can confirm, this works! Great find!

[CiGit]

From @AriPerkkio related issues, seems we could disable it when running the commands. Can you try to run these two commands and compare their timing ? npm --no-update-notifier config get prefix vs npm config get prefix

This is the command run by this extension.

[AriPerkkio]

Removed the environment variable and ran script below. Note that this issue only exists when running npm using child_process. Npm on terminal is fine.

I copied this script from those node issues I linked earlier.

const { execFile } = require('child_process');
const precise = require('precise');

const timer = precise();
timer.start();

execFile('npm.cmd', ['--no-update-notifier', 'config', 'get', 'prefix'], { env: process.env }, (e, out) => {
    timer.stop();
    console.log('Timer1 ', timer.diff() / 1000000, 'ms');
    if (e) {
        console.error(e);
    } else {
        console.log(out);
    }
});

const timer2 = precise();
timer2.start();

execFile('npm.cmd', ['config', 'get', 'prefix'], { env: process.env }, (e, out) => {
    timer2.stop();
    console.log('Timer2 ', timer2.diff() / 1000000, 'ms');
    if (e) {
        console.error(e);
    } else {
        console.log(out);
    }
});

const timer3 = precise();
timer3.start();

execFile('npm.cmd', ['config', 'get', 'prefix'], { env: { ...process.env, NO_UPDATE_NOTIFIER: true } }, (e, out) => {
    timer3.stop();
    console.log('Timer3 ', timer3.diff() / 1000000, 'ms');
    if (e) {
        console.error(e);
    } else {
        console.log(out);
    }
});

Output:

Timer3  1638.719999 ms
C:\Users\xx\AppData\Roaming\npm

Timer1  189839.1295 ms
C:\Users\xx\AppData\Roaming\npm

Timer2  189997.866699 ms
C:\Users\xx\AppData\Roaming\npm

It seems that the --no-update-notifier doesn't work as expected.

[divslinger]

Same result:

Timer3  2696.552599 ms
D:\Programs\node-v12

Timer1  190700.5517 ms
D:\Programs\node-v12

Timer2  190719.711801 ms
D:\Programs\node-v12

[CiGit]

Thanks. So Timer3 is the only worth in your case.

2 seconds instead of 3 minutes seems a good improvement to me :-)

https://github.com/prettier/prettier-vscode/blob/bec291c5031df31f1dc6a21be94c80a3bf285797/src/Files.ts#L134

Ideally we should also remove the Sync call to unblock the event loop

I tried that script on my system and get every numbers around 200 ms (Timer3 being slightly better). Seems there is still room for another improvement.

[ntotten]

I think even if we make it async, the startup time will still take a long time. I am going to change the global module resolution to be off by default. This is something that I don't think many people actually need and after looking again at the telemetry today it does seem that it has had a noticeable impact on startup time. I'll be pushing an update soon that has global resolution off by default and a new config option to enable it.

[ntotten]

Version 3.17.0 is live. This version disables global module resolution by default. Please let me know if this solves the issue.

[KenanHArik]

I have updated, and I can confirm that behavior seems normal for me. Thanks for getting this resolved quickly 👍

[AriPerkkio]

I removed the environment variable and upgraded extension from 3.16.0 to 3.17.0. Prettier starts up fast as expected. Thanks @ntotten & @CiGit !

However I still have the same issue with vscode-eslint extension. Without the environment variable it will take 3mins for it to start up. I'll just leave the env variable in place.

[divslinger]

Thanks for the quick fix. I'll close the issue for now, although I won't be able to test it myself before Monday.

[github-actions[bot]]

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.