cpptools takes hours of CPU time per day for a project which compiles in 5 seconds

[MSoegtropIMC]

Type: LanguageService

Describe the bug

• OS and Version: OSX 10.15.4
• VS Code Version: 1.45.1
• C/C++ Extension Version: 0.28.1

For every C++ project, even tiny ones which compile in a few seconds, a cpptools process runs for something between 6 and 40 minutes every time I open the project and also from time to time after editing or git operations. Over the day this accumulates to many hours and estimated about 25% of the time my laptop fan runs cause of cpptools (it hardly every runs cause of compiles). Also the memory consumption of cpptools is fairly high - around 7GB is common. I guess this has to do with scanning system headers, but is still seems wasteful to spend 30 minutes on symbol analysis for a project where a release build takes 5 seconds. This is not really a bug, but to me it looks like unnecessary waste of resources.

One more observation: when I delete the folder in which VSCode keeps the database (on Mac ~/Library/Application Support/VSCodium/User/workspaceStorage/) it runs the first time "only" for 6 minutes - Intellisense is fully operational. The second time it decides to run for the same projects - about 1 hour later - it runs for 29 minutes.

Steps to reproduce

• Open any project with C files
• Look at the CPU time of the cpptools process

Expected behavior

• cpptools needs less than 10x the compile time

In case you cannot reproduce this (for me this happens for every C++ project every time since at least 6 months) I can of cause provide logs, a sample project and gprof statistics.

[sean-mcmanus]

Yeah, that is not normal behavior. What message does it say when you hover over the database icon in the status bar? Can you set C_Cpp.loggingLevel to "Debug" and check the C/C++ logging to see what it says in regards to "tag parsing file" messages? If you don't care about files in those locations you could add those locations to your files.exclude setting.

[MSoegtropIMC]

@sean-mcmanus : when I hover over the database icon it shows "Discovering Files" with a file count. The file count started at 496,783, then quickly went to 0, increased again in steps of about 100,000 to e.g. 553,383, then went to zero again, started to increase again. One cycle takes about 10..20 seconds. It seems to cycle through that until something makes it happy or it gives up. I guess what I want is that it goes through this cycle just once. I will inspect the log as soon as it is finished (it seems to be more on the 30 minutes side).

Btw.: I don't think that the OSX system headers are 500,000 files. A find /usr | wc says there are 19,362 and a find /Library/Developer/CommandLineTools/SDKs/MacOSX.sdk/System/Library/Frameworks | wc says there are 9,322 files, so in total less than 30,000. I have these settings:

{
    "configurations": [
        {
            "name": "Mac",
            "includePath": [
                "${workspaceFolder}/"
            ],
            "defines": ["_DEBUG"],
            "macFrameworkPath": [
                "/Library/Developer/CommandLineTools/SDKs/MacOSX.sdk/System/Library/Frameworks"
            ],
            "compilerPath": "/usr/bin/clang",
            "cStandard": "c99",
            "cppStandard": "c++11",
            "intelliSenseMode": "clang-x86",
            "compilerArgs": [
                
            ]
        }
    ],
    "version": 4
}

My workspace folder has about 60 C files in it, but I have links to a few folders which do have a large number of files in my workspace (no filesystem symlinks, I mean references to other folders out of my workspace folder in my VSCode project). But all in all this is also not more than 100,000 files, and very little C (find + wc says 66 C header files and 55 C source files).

Btw.: I have a i9 CPU and 32 GB RAM and otherwise my PC is fairly unloaded, both memory and CPU wise.

Still waiting for cpptools to finish so that I can inspect the logs ...

[MSoegtropIMC]

P.S.: It looks like the cycles get slower each time. It is now at about 1 minute per cycle. I hope the database ops don't kill my SSD ... Aah it just finished: 30m45s - I will have a look at the logs.

[MSoegtropIMC]

OK, the logs say it went 240 times through these folders:

  Processing folder (recursive): /usr/local/include/
  Processing folder (recursive): /Library/Developer/CommandLineTools/usr/lib/clang/11.0.3/include/
  Processing folder (recursive): /Library/Developer/CommandLineTools/SDKs/MacOSX10.15.sdk/usr/include/
  Processing folder (recursive): /Library/Developer/CommandLineTools/usr/include/
  Processing folder (recursive): /Library/Developer/CommandLineTools/SDKs/MacOSX10.15.sdk/System/Library/Frameworks/<200 subfolders>

Under the last of the above folders it scans about 200 subfolders. There are no error messages in the log while it prcoesses folders. It just starts over with /usr/local/include/ when it finished. The overall log file looks like this:

16 loops over the below block:

File exclude: **/.git
File exclude: **/.svn
File exclude: **/.hg
File exclude: **/CVS
File exclude: **/.DS_Store
File exclude: **/.vscode
Search exclude: **/node_modules
Search exclude: **/bower_components
Search exclude: **/*.code-search
Search exclude: **/.vscode
IntelliSense Engine = Default.
Enhanced Colorization is enabled.
Error squiggles are enabled if all header dependencies are resolved.
Autocomplete is enabled.

(the last 4 lines appear only in the first 15 loops, but not in the 16ths loop)

15 Loops over the below block:

Populate include completion cache.
Discovering files...
  Processing folder (recursive): /usr/local/include/
  :
  16 loops (in total 240=15*16) through the same set of a bit more than 200 folders, in total > 50,000 Processing folder lines
  No other messages than "Processing folders" in this block - when it finished it just starts over
  :
  Discovering files: 569698 file(s) processed
  0 file(s) removed from database
Done discovering files.
Parsing open files...
Parsing remaining files...
  Parsing: 0 files(s) processed
Done parsing remaining files.
Done parsing open files.

I didn't check very carefully, but I think the inner loop is always exactly 16. I searched for Discovering files and the distance in lines is about equal.

One more note: cpptools has 30 threads - as far as I can tell for a period of 3 seconds always only two of these threads are active and the others are sleeping. Maybe instead of distributing the work over 15 pairs of threads, each thread pair does the complete job - one after another (the kind of parallelisation some humans enjoy but computers usually not ;-)

In summary, if it would go through the folders just once rather than 240 times, it would take just 8 seconds - which would be will within my expectations.

[MSoegtropIMC]

P.S.: If this is of interest, I can attach the log (with a few private lines xed out)

[sean-mcmanus]

The logging "File exclude: **/.git" should not appear with 0.28.1 unless the cpptools process is crashing, in which case you would see that once per crash. It sounds like you see that 16 times? There's code that checks for 5 crashes in 3 minutes and if that is hit then it won't keep restarting our cpptools process, but if you're hitting the 16 crashes in 9+ minutes then that would explain it.

Can you attach a debugger to the cpptools process to get a call stack for why it's crashing. Or check the ~/Library/Logs/DiagnosticReports for a crash log?

The discovering files is only supposed to occur 1 time and not process the same folders repeatedly...unless some settings/config change causes it to abort and start over.

You're hitting a problem with our code that recurses through the file system to look for files that it may need to parse later, so it's not actually doing any parsing (it says Parsing: 0 files processed).

I hit an issue on Windows with a symlink causing huge performance problems at #3123 . Do you know if you have any symlinks that could cause a similar failure? I don't think we have gotten other complaints from Mac users like this yet.

I'm using XCode and not the command line tools and I also don't have /usr/local/include in my includePath (not sure if that would matter). Other than that, the 9k files is what it should be processing, not 569k.

[nsoblath]

In case it can be helpful, I believe I'm seeing the same problem. I see the same repeated blocks in the log output, both the part with the File exclude lines and the part that starts Populate include completion cache..

Here's my system information:

• OS and Version: macOS version 10.14.6
• VS Code Version: 1.45.1
• C/C++ Extension Version: 0.28.2

I don't think I have any symlinks as were discussed in #3123.

I don't see anything relevant in ~/Library/Logs/DiagnosticReports.

I don't know if this is relevant, but in the Activity Monitor I see that there are two instances of cpptools (and one cpptools-srv. One has a CPU time of 49.06 seconds, and the other has a time of 26:42.31. Presumably the second is the instance that is doing all of the work when it's doing all of this file discovery.

I have noticed this on my CentOS machine as well. I use this in conjunction with the Remote Development extension. cpptools consistently uses over 80% CPU.

I plan to look into this in detail over the coming weekend. Let me know if you guys have pointers on where I should be looking at.

[MSoegtropIMC]

@MohammadGhazanfar : I didn't have time to look deeper into it, but also planned to do so maybe tomorrow (a bank holiday in Germany) or during the weekend. It would be nice to stay in contact on this. I post here as soon as I have something. I will start with doing some profile statistics (easy on OSX) which helps in setting break points for a first analysis.

Thanks @MSoegtropIMC ! That will be great !

[MSoegtropIMC]

@sean-mcmanus : I tried to debug cpptools. I followed the instructions in (https://github.com/microsoft/vscode-cpptools/blob/master/Documentation/Building%20the%20Extension.md) and I can start VSCode in extension development mode and break and step the typescript code, but what is not clear to me is how to debug or even build the cpptools binary which is causing the actual problem. As far as I can tell the binary is downloaded from microsoft following information from the package.json file

    {
      "description": "C/C++ language components (OS X)",
      "url": "https://go.microsoft.com/fwlink/?linkid=2131173",
      "platforms": [
        "darwin"
      ],
      "binaries": [
        "./bin/cpptools",
        "./bin/cpptools-srv"
      ]
    },

It doesn't look like the build instructions given for the extension actually build this. Can you point me to the source / build instruction of the cpptools binary and maybe some hints for debugging it? This would really be helpful for getting forward.

[sean-mcmanus]

@MSoegtropIMC You don't need to debug the TypeScript part of the extension. Just attach a debugger to the cpptools process to and you should be able to get call stacks (i.e. set the path to cpptools in the tasks.json for gdb attach debugging). The cpptools process is closed source.