Format on save with clang-format takes too long

[xolom]

Describe the bug

• OS and Version: MacOS 11.1 (ubuntu docker)
• VS Code Version: 1.52.1
• C/C++ Extension Version: 1.1.3
• Other extensions you installed (and if the issue persists after disabling them):

eamodio.gitlens
ms-azuretools.vscode-docker
ms-vscode.cpptools
gitlab.gitlab-workflow
renesackers.angelscript
ms-python.python
ms-python.vscode-pylance

Sometimes format on save with clang-format takes really long. I need to cancel the task to save the file. What is the cause for that, how can i debug that further? I see this popup for like forever

[sean-mcmanus]

When this occurs can you check which process is using CPU? If it's cpptools, then the formatting might be blocked on another operation (or possibly processing the formatting result), in which case, if you set C_Cpp.loggingLevel to "Debug" and check the formatting-related logging that can help determine where it's getting stuck (or attaching a debugger and getting a call stack: https://github.com/microsoft/vscode-cpptools/wiki/Attaching-debugger-to-cpptools-or-cpptools%E2%80%90srv). If it's clang-format, then it would be a clang-format bug.

[xolom]

Unfortunately i can't attach to the cpptool process. Running on mac and lldb gives me following error:

❯ sudo lldb -p 72381
(lldb) process attach --pid 72381
error: attach failed: attach failed (Not allowed to attach to process.  Look in the console messages (Console.app), near the debugserver entries when the attached failed.  The subsystem that denied the attach permission will likely have logged an informative message about why it was denied.)

Everything i can say right now is that the extension stucks completely somehow. The log output doesn't print anything anymore and this little message where it says Updating IntelliSense... won't go away.

[Colengms]

Hi @xolom . When this happens, can you check whether or not clang-format is still executing (based on the Activity Monitor) ? Also, I noticed that you repro'ed this with 1.1.3. Could you try upgrading to 1.2.0-insiders2 ? We recently upgraded the bundled version of clang-format to 11.x.

[xolom]

Hi @xolom . When this happens, can you check whether or not clang-format is still executing (based on the Activity Monitor) ? Also, I noticed that you repro'ed this with 1.1.3. Could you try upgrading to 1.2.0-insiders2 ? We recently upgraded the bundled version of clang-format to 11.x.

Hi.

I was already @ 1.2.0-insiders2, when i made the post above. I just checked if clang-format is executed at all and it seems like it's not.

❯ ps -ax | grep clang-format
 4470 ttys000    0:00.00 grep --color clang-format

On the other hand there are many running cpptools processes:

❯ ps -ax | grep cpptools
 3876 ??         0:16.33 /Users/.../.vscode/extensions/ms-vscode.cpptools-1.2.0-insiders2/bin/cpptools-srv 98674 {D1ADD6A9-6917-484C-A2A3-5934EFE2C1FC}
 4068 ??         0:17.72 /Users/.../.vscode/extensions/ms-vscode.cpptools-1.2.0-insiders2/bin/cpptools-srv 98674 {BA1E20A6-7AFC-46D2-9B4A-31A4ADDF0A3B}
34106 ??         2:34.51 /Users/.../.vscode/extensions/ms-vscode.cpptools-1.2.0-insiders2/bin/cpptools
35050 ??         3:53.48 /Users/.../.vscode/extensions/ms-vscode.cpptools-1.2.0-insiders2/bin/cpptools-srv 34106 {05C81682-4426-4663-B3BC-487DAB1E8DAA}
35548 ??         0:36.44 /Users/.../.vscode/extensions/ms-vscode.cpptools-1.2.0-insiders2/bin/cpptools-srv 34106 {CDF5E910-5117-447D-BFBA-C46FD774F803}
42871 ??         3:49.08 /Users/.../.vscode/extensions/ms-vscode.cpptools-1.2.0-insiders2/bin/cpptools
43088 ??         3:44.94 /Users/.../.vscode/extensions/ms-vscode.cpptools-1.2.0-insiders2/bin/cpptools-srv 42871 {F2181B3C-89A9-4BD9-B26F-C12143A0106A}
43093 ??         1:04.20 /Users/.../.vscode/extensions/ms-vscode.cpptools-1.2.0-insiders2/bin/cpptools-srv 42871 {5C1E7AF8-B2C8-4629-9EE8-B682226105BD}
52121 ??         3:01.85 /Users/.../.vscode/extensions/ms-vscode.cpptools-1.2.0-insiders2/bin/cpptools
52445 ??         3:43.38 /Users/.../.vscode/extensions/ms-vscode.cpptools-1.2.0-insiders2/bin/cpptools-srv 52121 {B2D7787E-7396-4262-82DA-DED399FFA01C}
53415 ??         1:13.78 /Users/.../.vscode/extensions/ms-vscode.cpptools-1.2.0-insiders2/bin/cpptools-srv 52121 {5C360CEC-FDD1-487C-ACD0-4737A150942A}
53742 ??         1:30.25 /Users/.../.vscode/extensions/ms-vscode.cpptools-1.2.0-insiders2/bin/cpptools-srv 52121 {95655A9A-1F92-43E6-872D-95AFF42165DA}
53855 ??         1:30.17 /Users/.../.vscode/extensions/ms-vscode.cpptools-1.2.0-insiders2/bin/cpptools-srv 52121 {39D44902-D12E-4A89-823C-DFC0A9606B20}
55101 ??         0:27.71 /Users/.../.vscode/extensions/ms-vscode.cpptools-1.2.0-insiders2/bin/cpptools
55469 ??         1:09.67 /Users/.../.vscode/extensions/ms-vscode.cpptools-1.2.0-insiders2/bin/cpptools-srv 55101 {C98B2C4E-7F4A-4AC3-88BC-B6C269C2BD1D}
72381 ??         4:24.26 /Users/.../.vscode/extensions/ms-vscode.cpptools-1.2.0-insiders2/bin/cpptools
73757 ??         1:11.39 /Users/.../.vscode/extensions/ms-vscode.cpptools-1.2.0-insiders2/bin/cpptools-srv 72381 {36271D50-EB4D-4BB7-B538-96BF1D1038ED}
74113 ??         0:08.92 /Users/.../.vscode/extensions/ms-vscode.cpptools-1.2.0-insiders2/bin/cpptools-srv 72381 {5222506C-49DF-4FCF-B008-34A5F4A91528}
74555 ??         0:30.64 /Users/.../.vscode/extensions/ms-vscode.cpptools-1.2.0-insiders2/bin/cpptools-srv 72381 {E327868E-68F6-4B29-A64F-6E4448A0EC63}
74829 ??         0:15.68 /Users/.../.vscode/extensions/ms-vscode.cpptools-1.2.0-insiders2/bin/cpptools-srv 72381 {4B625ED8-0758-43DF-BF86-1BDEF98A4000}
75083 ??         0:16.99 /Users/.../.vscode/extensions/ms-vscode.cpptools-1.2.0-insiders2/bin/cpptools-srv 72381 {BB461531-82A6-499D-807C-3F327FD0F7BC}
98674 ??        10:30.70 /Users/.../.vscode/extensions/ms-vscode.cpptools-1.2.0-insiders2/bin/cpptools

[xolom]

What i also noticed is following message in the log:
Shutting down IntelliSense server: /some/path/foo.cpp. Memory usage is 4386 MB and has exceeded the 4096 MB limit.

Today i mostly worked mostly only in one .cpp file. The IntelliSense parsing flame icon came up like every few seconds and my MacBook also needs to "breathe". I don't know, but it feels like the parsing is overwhelmed in some way and I'm pretty sure that this blocks the execution of clang-format.

I already tried to speedup the parsing as much as possible by only include the necessary folders, setting limitSymbolsToIncludedHeaders to true and exclude system includes (we're cross compiling for a microcontroller).
Unfortunately the debug log doesn't help me in this case.

[Colengms]

Hi @xolom . Is the code involved rather complex? With debug logging enabled with "C_Cpp.loggingLevel": "Debug", an Update IntelliSense time (sec): x.xx message should occasionally be output to the C/C++ output channel when working with the file, as IntelliSense passes complete. The duration may vary a bit. Does it roughly match the delay in your scenario?

I suspect the cause of the issue is an operation prior to formatting that is trying to synchronize with the results of an IntelliSense pass. We have a known issue in which certain combinations of operations might result in a delay for this reason. We have some ongoing work that should lead to addressing the issue.

Can you identify the combination of operations prior to formatting that lead to the delay? It's likely due to making an edit, hovering, then closing the file before the hover operation is complete). Depending on your specific repro, there may be something we can do to address it sooner.

[xolom]

Hi @Colengms.
To the code complexity: There is one part that is generated and has 480,496 loc across 28 files and the actual code has 52,881 loc across 449 files. The path to the generated code is set without ** in c_cpp_properties.json, because we're using precompiled headers and we need to have them available globally. Means that we always parse all generated files.

From what I have seen in the log these are the values coming up over the day:

Update IntelliSense time (sec): 0.282
Update IntelliSense time (sec): 0.271
Update IntelliSense time (sec): 0.281
Update IntelliSense time (sec): 0.285
Update IntelliSense time (sec): 0.277
Update IntelliSense time (sec): 0.283
Update IntelliSense time (sec): 0.289
Update IntelliSense time (sec): 6.022
Update IntelliSense time (sec): 0.274
Update IntelliSense time (sec): 0.274
Update IntelliSense time (sec): 0.27
Update IntelliSense time (sec): 0.278
Update IntelliSense time (sec): 0.273
Update IntelliSense time (sec): 0.477
Update IntelliSense time (sec): 0.279
Update IntelliSense time (sec): 0.276
Update IntelliSense time (sec): 2.276
Update IntelliSense time (sec): 3.605
Update IntelliSense time (sec): 3.238
Update IntelliSense time (sec): 33.036
Update IntelliSense time (sec): 0.273
Update IntelliSense time (sec): 0.284
Update IntelliSense time (sec): 0.269
Update IntelliSense time (sec): 0.56
Update IntelliSense time (sec): 0.274
Update IntelliSense time (sec): 0.285
Update IntelliSense time (sec): 0.275
Update IntelliSense time (sec): 11.737
Update IntelliSense time (sec): 7.917
Update IntelliSense time (sec): 0.274
Update IntelliSense time (sec): 0.276
Update IntelliSense time (sec): 0.545
Update IntelliSense time (sec): 0.561
Update IntelliSense time (sec): 0.351
Update IntelliSense time (sec): 0.287
Update IntelliSense time (sec): 0.573
Update IntelliSense time (sec): 0.273
Update IntelliSense time (sec): 0.279
Update IntelliSense time (sec): 0.331
Update IntelliSense time (sec): 0.322
Update IntelliSense time (sec): 0.522
Update IntelliSense time (sec): 3.61
Update IntelliSense time (sec): 17.964
Update IntelliSense time (sec): 0.457
Update IntelliSense time (sec): 2.27
Update IntelliSense time (sec): 0.33
Update IntelliSense time (sec): 0.271
Update IntelliSense time (sec): 0.279
Update IntelliSense time (sec): 0.274
Update IntelliSense time (sec): 0.28
Update IntelliSense time (sec): 0.275
Update IntelliSense time (sec): 0.28
Update IntelliSense time (sec): 0.276
Update IntelliSense time (sec): 0.275
Update IntelliSense time (sec): 0.276
Update IntelliSense time (sec): 0.563
Update IntelliSense time (sec): 0.271
Update IntelliSense time (sec): 3.981
Update IntelliSense time (sec): 1.02
Update IntelliSense time (sec): 2.2
Update IntelliSense time (sec): 6.913
Update IntelliSense time (sec): 0.27
Update IntelliSense time (sec): 0.271
Update IntelliSense time (sec): 0.539
Update IntelliSense time (sec): 0.275
Update IntelliSense time (sec): 0.27
Update IntelliSense time (sec): 0.394
Update IntelliSense time (sec): 0.278
Update IntelliSense time (sec): 0.818
Update IntelliSense time (sec): 1.276
Update IntelliSense time (sec): 0.271
Update IntelliSense time (sec): 0.681
Update IntelliSense time (sec): 20.329
Update IntelliSense time (sec): 0.537
Update IntelliSense time (sec): 0.275
Update IntelliSense time (sec): 0.272
Update IntelliSense time (sec): 12.57
Update IntelliSense time (sec): 0.275
Update IntelliSense time (sec): 0.548
Update IntelliSense time (sec): 0.837
Update IntelliSense time (sec): 0.272
Update IntelliSense time (sec): 2.708
Update IntelliSense time (sec): 8.534
Update IntelliSense time (sec): 0.28
Update IntelliSense time (sec): 0.54
Update IntelliSense time (sec): 0.279
Update IntelliSense time (sec): 0.278
Update IntelliSense time (sec): 0.419
Update IntelliSense time (sec): 0.302

I'll try to find out, if there is any specific action happening before i save the file and clang-format (or cpptools) gets stuck

[xolom]

I'm pretty sure that cpptools or cpptools-srv (don't really know which does what) gets stuck. That's why i had so many processes running like shown in #6809 (comment)
I always need to kill the processes and restart vscode. After that everything starts to work again.

Unfortunately i can't attach lldb on my MacOS machine to give you the call stack (see: #6809 (comment))

[Dakror]

I'm experiencing the same issue on Windows and the issue disappears when downgrading the plugin to i think 0.29, but then again much of the functionality gets lost too.