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

Version 0.10.9 (0.10.9) using 90% cpu. #3222

Closed
ransanjeev opened this issue Feb 22, 2016 · 26 comments
Closed

Version 0.10.9 (0.10.9) using 90% cpu. #3222

ransanjeev opened this issue Feb 22, 2016 · 26 comments
Assignees
Labels
freeze-slow-crash-leak VS Code crashing, performance, freeze and memory leak issues

Comments

@ransanjeev
Copy link

On Mac 10.11.3 (15D21), one of the electron helper is constantly running at 90% cpu.

@fhelje
Copy link

fhelje commented Feb 23, 2016

Seeing the same thing.

@bmoeskau
Copy link

Mine runs at 120%+ (not sure about that math, but that's what it says). Fan starts spinning constantly until I kill the VSCode window. Interestingly it seems to happen on one project in particular (a large Node project with lots of files and node_modules stuff) and not on others. Not sure what other detail about that might be relevant.

screenshot 2016-02-23 22 02 53

@fhelje
Copy link

fhelje commented Feb 24, 2016

Every core is 100%

@egamma egamma added the freeze-slow-crash-leak VS Code crashing, performance, freeze and memory leak issues label Feb 24, 2016
@ransanjeev
Copy link
Author

In my tasks.json, "isWatching" was set to true. When I changed this to true, cpu usage has gone down.
Not sure if this is the solution. But I use tsc --watch so I am not sure if i need iswatching.

@bpasero
Copy link
Member

bpasero commented Feb 29, 2016

@dbaeumer any ideas?

@bpasero bpasero added this to the March 2016 milestone Feb 29, 2016
@dbaeumer
Copy link
Member

@bpasero watching tasks (expecially tsc) are not executed in the Electron Helper. They are executed in a separate node environment (e.g. what is specified in the tsc shell script).

What could have an impact is if a tasks produces a lot of output which will cause constant scanning of that output. But the described issues doesn't sound like this.

@bpasero
Copy link
Member

bpasero commented Feb 29, 2016

Can people here open the output window to see if we spam the output when this happens?

@egamma egamma mentioned this issue Feb 29, 2016
82 tasks
@bpasero
Copy link
Member

bpasero commented Mar 7, 2016

Closing as duplicate of #774 which seems to be caused on Mac when having a large folder in the workspace.

@bpasero bpasero closed this as completed Mar 7, 2016
@bpasero
Copy link
Member

bpasero commented Mar 8, 2016

Since i cannot reproduce the high CPU use for a large folder this must be something else.

@bpasero bpasero reopened this Mar 8, 2016
@bpasero
Copy link
Member

bpasero commented Mar 8, 2016

@ransanjeev @fhelje @bmoeskau is one of you able to do a little experiment? I am speculating that maybe our library for file watching is failing. The steps would be:

  • setup to run vscode out of our sources as described at https://github.com/Microsoft/vscode/wiki/How-to-Contribute
  • copy the contents of Applications/Visual Studio Code.app/Contents/Resources/app/node_modules/chokidar into the sources at ./node_modules/chokidar (replace the entire folder)
  • open ./node_modules/chokidar/lib/fsevents-handler.js from the sources and insert console.log('Do we have fsevents?: ', !!fsevents) in line 9
  • open ./src/vs/workbench/services/files/node/watcher/unix/watcherService.ts from the sources and set VERBOSE_LOGGING to true in line 43
  • run code out of sources with ./scripts/code.sh
  • from the window that opens show the developer console (Help | Toggle Developer Tools)
  • check if you see [Service Library: Watcher] Do we have fsevents?: true

For me (since fsevents works ok), I get this:

image

If something goes wrong, I would expect fsevents to print as undefined. In that case, can you put another console.log inside the try/catch block of line 7 to see what the error is loading that native module?

Thanks!

@bmoeskau
Copy link

bmoeskau commented Mar 8, 2016

@bpasero Looks like your guess is correct in my case. Anything else you want me to check?

screenshot 2016-03-08 12 38 38

@bmoeskau
Copy link

bmoeskau commented Mar 8, 2016

This is the error that got swallowed by the require:

Error: Module version mismatch. Expected 47, got 46.
    at Error (native)
    at Object.Module._extensions..node (module.js:440:18)
    at Module.load (module.js:357:32)
    at Function.Module._load (module.js:314:12)
    at Module.require (module.js:367:17)
    at require (internal/module.js:16:19)
    at Object.<anonymous> (/Users/Brian/Projects/vscode/node_modules/chokidar/node_modules/fsevents/fsevents.js:9:14)
    at Module._compile (module.js:413:34)
    at Object.Module._extensions..js (module.js:422:10)
    at Module.load (module.js:357:32)

@bpasero
Copy link
Member

bpasero commented Mar 8, 2016

@bmoeskau wow, this error is weird though, if I understand it correctly it means the native library fsevents (our mac file watcher) was compiled against a node version 46 but running it within VS Code has version 47. This does not make much sense to me because the node version in VS Code is 46 (47 was only added in node.js >= 5.0.0 and we use 4.x).

A couple of further thoughts:

  • verify you are on master with latest changes. I did not see that electron gets downloaded which indicates to me that you have used this workspace before (?) and maybe you are on a branch with a different electron version?
  • can you start code.sh and show me the output of typing process.versions from the developer tools console?
  • can you run git clean -xfd from the vscode source folder and then ./scripts/npm.sh install. this will compile all node modules against your platform. then please try again to run code.sh and see if you get something printed or the same error?

Thanks for taking the time!

@bmoeskau
Copy link

bmoeskau commented Mar 8, 2016

Oh, interesting. I did not consider mentioning that I'm actually running Node 5.6.0 locally. I nvm switched to 4.2.1 and re-ran with no other changes and now fsevents does load properly:

 Moe in ~/Projects/vscode
± |master ✓| → ./scripts/code.sh
fsevents:
{ [Function: watch]
  getInfo: [Function: getInfo],
  FSEvents: [Function: FSEvents],
  Constants:
   { kFSEventStreamEventFlagNone: 0,
   ....

However, that said, there appears to be no difference in CPU usage either way. Even with fsevents loaded properly Activity Monitor still reports Electron Helper at 108% CPU and my laptop is about to fly off my desk...

Again note that for me this only happens for one very large Node project folder that contains a bunch of repos, each with its own node_modules. In all there are hundreds of thousands of files under the root folder. When I load other folders of various sizes (all much smaller) I don't get this issue at all. To me this appears to be either A) a simple file count / memory limit, or B) some specific file(s) or folders(s) within my problem project that VSCode does not agree with.

@bpasero
Copy link
Member

bpasero commented Mar 8, 2016

I was suspicious and tried to open a very large folder (all of chrome sources actually) with Code on Mac and did not notice any CPU spikes like that. Is there any chance I could setup a folder like yours if you share the (open source?) repositories?

@bmoeskau
Copy link

bmoeskau commented Mar 8, 2016

Unfortunately the main codebase is private, but what I can do is try replicating only the dependency tree by creating a new folder structure and copying in the package.json files we use and npm install them one by one, monitoring VS Code as I go. I'll try that out later and let you know if I find out anything.

@bpasero
Copy link
Member

bpasero commented Mar 8, 2016

Great!

@bmoeskau
Copy link

bmoeskau commented Mar 9, 2016

This still seems to me to be a simple issue of file count. The total file count for everything under the root folder is something like 500k files (well over 2Gb). I have one repo in particular that contains 28 sub-projects, each with its own node_modules (it's a collection of small utility programs). I went through and deleted all 28 sub-node_modules folders within that repo (approx 130k files) and suddenly things started running much better. I noticed that on startup it still pegged the CPU, but after a minute or two it dropped to zero. I started removing more files, and it started performing even better. I then started adding files back, 5k at a time, and sure enough, each time it took longer and longer for the app to recover from full CPU usage on startup (I literally timed it -- each time it took 30s to 1 minute longer to recover). Copying files into the project path while VS Code is already running also causes the same thing to happen as soon as it picks up on the file changes.

I didn't have time to identify the threshold between "normal" startup vs when the CPU hit becomes noticeable. I'm also not sure if the performance issue is linear, or if it simply drops off a cliff from which it can't recover at some point. My original project folder with all files never seemed to recover the CPU, even after 30+ minutes.

I admit that this is a lot of files, but it's the new reality with npm if you have a large project. Also I've been loading the exact same project into Sublime, Textmate etc. with no issues. In fact I downloaded Atom today just to see and it also loads just fine with barely a blip in CPU on startup. So this definitely seems specific to VS Code.

@bpasero
Copy link
Member

bpasero commented Mar 9, 2016

@bmoeskau I am still puzzled why the size of a folder could cause this. to verify, can you remove the if-statement in https://github.com/Microsoft/vscode/blob/master/src/vs/workbench/services/files/electron-browser/fileService.ts#L48 and then recompile vs code locally and run it out of the sources on this large folder? it would be interesting to know if this issue can be solved by adding "node_modules" to the list of ignored folders by the watcher.

Meanwhile I have opened paulmillr/chokidar#447 to see if chokidar has an idea.

@bpasero
Copy link
Member

bpasero commented Mar 9, 2016

@bmoeskau very sorry, I realized my instructions were not good and I have updated them. the output we see on the console is coming from a different use of chokidar, not the one from VS Code. the new instructions are slightly different but not much and we can see if chokidar is running by looking at the developer console within Code. Can you retry please?

Meanwhile I have talked to the chokidar developers and got confirmation that chokidar does 1 full scan of the directory on startup. I can reproduce this, however my CPU goes down after a while. Are you saying that CPU stays high forever and never calms down?

@bmoeskau
Copy link

bmoeskau commented Mar 9, 2016

Based on the updated instructions I still see " fsevents: true" in the bash command line output, but in the UI developer console I don't see anything after the "listening on port 5870" message. I've tried console logging from within various instance methods of FsEventsHandler and I never see anything, but not sure what's expected.

As I mentioned previously, depending on the total number of files, I do see the CPU go down after a while too, but the more files there are, the longer this takes. I measured a very clear increase in CPU thrashing time each time I added a batch of 5k files to the project root.

As an additional data point I also added the "real memory" column to the activity monitor output and (maybe as expected) memory use also climbs dramatically along with CPU use while this occurs, and then also drops to normal when it recovers.

screenshot 2016-03-09 11 32 24

@bpasero
Copy link
Member

bpasero commented Mar 10, 2016

@bmoeskau could it be that after your change you did not recompile? we typically first run gulp watch before making changes, which will compile everything first and then watch for more changes.

@bmoeskau
Copy link

I must have missed that step. Yes I do see the "fsevents: true" now. I also verified that this line is running many, many times on startup:

watchContainer.listeners.push(filteredListener);

@bpasero
Copy link
Member

bpasero commented Mar 10, 2016

@bmoeskau thanks for checking, I also got confirmation from another user that the native library indeed is not the issue. He saw an interesting pattern though: the process that runs the watcher (the one with high CPU/MEM use) climbs to ~1 GB and then quits and restarts. This is because the process runs out of memory, crashes and VS Code decides to just start it again because Code without watcher is pretty bad.

Can you check if this also happens for you here? This would explain why the process never recovers.

Btw two things pushed to master so far, maybe you want to give it a try running "out of the sources":

  • you can now explicitly configure exclude rules for the watcher with the new files.watcherExclude setting, so I would expect things to improve if you add a folder in here that is large
  • Code stops restarting the watcher process after 5 attempts that fail

@bmoeskau
Copy link

Ah! I had reduced my project file count such that the CPU would recover after a couple of minutes while testing things out, but after your last comment I added a huge folder back into the project. Now that I'm logging from the code I am seeing the same pattern you mentioned -- memory climbs to around 1.5Gb, hovers there for a minute, then drops down to a few hundred Mb. Each time that happens I get the "fsevents: true" logged again, so obviously that process is restarting as you mentioned. That definitely explains why the CPU never recovers beyond a certain file count.

I downloaded the latest from master, and first ran it as-is just to make sure it didn't get fixed somehow. The CPU problem continued unchanged. Then I added this to my user settings file:

// Place your settings in this file to overwrite the default settings
{
    "files.watcherExclude": {
        "**/.git/objects/**": true,
        "**/node_modules/**": true
    }
}

Voila, now the CPU spikes just for a second or two on load and then immediately drops to 0. Seems like probably a good default setting... :)

@bpasero
Copy link
Member

bpasero commented Mar 11, 2016

We found out about the issue and here is what happens:

  • user opens a large folder in VS Code
  • VS Code installs a watcher on the root of the folder from another process
  • watcher starts to walk the folder in a way that memory increases a lot
  • eventually the process dies with out of memory
  • VS Code detects this and starts the watcher again because we typically never want to loose the watching information
  • this goes on and on forever and simply results in constant and high CPU use

We also verified that chokidar was not falling back to polling.

The fixes for March are:

  • allow the user to configure excludes from the new files.watcherExclude setting
  • add node_modules to the excluded folders by default
  • do not restart chokidar after 5 failing attempts

For the future, we are looking into #3998

@bpasero bpasero closed this as completed Mar 11, 2016
@bpasero bpasero modified the milestone: March 2016 Mar 23, 2016
@vscodebot vscodebot bot locked and limited conversation to collaborators Nov 18, 2017
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
freeze-slow-crash-leak VS Code crashing, performance, freeze and memory leak issues
Projects
None yet
Development

No branches or pull requests

6 participants